diff --git a/Applications/ApplicationsLib/UncoupledProcessesTimeLoop.cpp b/Applications/ApplicationsLib/UncoupledProcessesTimeLoop.cpp index d1c8c89b335022db14d7fae1a6ea0ca694f253cc..d47efa1e688a6f7da10c7ca2fed4951f5cf8d085 100644 --- a/Applications/ApplicationsLib/UncoupledProcessesTimeLoop.cpp +++ b/Applications/ApplicationsLib/UncoupledProcessesTimeLoop.cpp @@ -8,6 +8,7 @@ */ #include "UncoupledProcessesTimeLoop.h" +#include "BaseLib/RunTime.h" namespace ApplicationsLib { @@ -177,6 +178,9 @@ bool UncoupledProcessesTimeLoop::loop(ProjectData& project) while (_timestepper->next()) { + BaseLib::RunTime time_timestep; + time_timestep.start(); + auto const ts = _timestepper->getTimeStep(); auto const delta_t = ts.dt(); t = ts.current(); @@ -190,12 +194,18 @@ bool UncoupledProcessesTimeLoop::loop(ProjectData& project) for (auto p = project.processesBegin(); p != project.processesEnd(); ++p, ++pcs_idx) { + BaseLib::RunTime time_timestep_process; + time_timestep_process.start(); + auto& x = *_process_solutions[pcs_idx]; nonlinear_solver_succeeded = solveOneTimeStepOneProcess( x, timestep, t, delta_t, per_process_data[pcs_idx], **p, out_ctrl); + INFO("[time] Solving process #%u took %g s in timestep #%u.", + timestep, time_timestep.elapsed(), pcs_idx); + if (!nonlinear_solver_succeeded) { ERR("The nonlinear solver failed in timestep #%u at t = %g s" @@ -213,6 +223,9 @@ bool UncoupledProcessesTimeLoop::loop(ProjectData& project) } } + INFO("[time] Timestep #%u took %g s.", timestep, + time_timestep.elapsed()); + if (!nonlinear_solver_succeeded) break; } diff --git a/Applications/CLI/ogs.cpp b/Applications/CLI/ogs.cpp index a600db57334934c8345dd2b1b83502a45332c577..8f5203f1fb79128f052a8279d791e6de118568e2 100644 --- a/Applications/CLI/ogs.cpp +++ b/Applications/CLI/ogs.cpp @@ -10,6 +10,9 @@ * */ +#include <chrono> +#include <ctime> +#include <sstream> // ThirdParty/tclap #include "tclap/CmdLine.h" @@ -18,6 +21,7 @@ #include "BaseLib/BuildInfo.h" #include "BaseLib/ConfigTreeUtil.h" #include "BaseLib/FileTools.h" +#include "BaseLib/RunTime.h" #include "Applications/ApplicationsLib/LinearSolverLibrarySetup.h" #include "Applications/ApplicationsLib/LogogSetup.h" @@ -74,6 +78,21 @@ int main(int argc, char *argv[]) ApplicationsLib::LogogSetup logog_setup; logog_setup.setLevel(log_level_arg.getValue()); + BaseLib::RunTime run_time; + run_time.start(); + + { + auto const start_time_sys = std::chrono::system_clock::to_time_t( + std::chrono::system_clock::now()); + std::ostringstream sstr; + sstr << std::put_time(std::localtime(&start_time_sys), "%F %T %z"); + INFO("OGS started on %s.", sstr.str().c_str()); + } + + std::chrono::steady_clock::now(); + + auto ogs_status = EXIT_SUCCESS; + try { bool solver_succeeded = false; @@ -117,9 +136,20 @@ int main(int argc, char *argv[]) BaseLib::ConfigTree::assertNoSwallowedErrors(); - return solver_succeeded ? EXIT_SUCCESS : EXIT_FAILURE; + ogs_status = solver_succeeded ? EXIT_SUCCESS : EXIT_FAILURE; } catch (std::exception& e) { ERR(e.what()); - return EXIT_FAILURE; + ogs_status = EXIT_FAILURE; } + + { + auto const end_time_sys = std::chrono::system_clock::to_time_t( + std::chrono::system_clock::now()); + std::ostringstream sstr; + sstr << std::put_time(std::localtime(&end_time_sys), "%F %T %z"); + INFO("OGS terminated on %s.", sstr.str().c_str()); + INFO("[time] Execution took %g s.", run_time.elapsed()); + } + + return ogs_status; } diff --git a/NumLib/ODESolver/NonlinearSolver.cpp b/NumLib/ODESolver/NonlinearSolver.cpp index fed2e6487185b1f527d036f7e77f0d4255855700..47047d302bfefe0afcdca05d566a0ca8e88eb915 100644 --- a/NumLib/ODESolver/NonlinearSolver.cpp +++ b/NumLib/ODESolver/NonlinearSolver.cpp @@ -16,6 +16,7 @@ #include "BaseLib/ConfigTree.h" #include "BaseLib/Error.h" +#include "BaseLib/RunTime.h" #include "MathLib/LinAlg/LinAlg.h" #include "MathLib/LinAlg/VectorNorms.h" #include "NumLib/DOF/GlobalMatrixProviders.h" @@ -47,22 +48,32 @@ bool NonlinearSolver<NonlinearSolverTag::Picard>::solve( LinAlg::copy(x, x_new); // set initial guess, TODO save the copy + unsigned iteration = 1; for (; iteration <= _maxiter; ++iteration) { + BaseLib::RunTime time_iteration; + time_iteration.start(); + sys.preIteration(iteration, x); + BaseLib::RunTime time_assembly; + time_assembly.start(); sys.assembleMatricesPicard(x); sys.getA(A); sys.getRhs(rhs); + INFO("[time] Assembly took %g s.", time_assembly.elapsed()); + BaseLib::RunTime time_dirichlet; + time_dirichlet.start(); // Here _x_new has to be used and it has to be equal to x! sys.applyKnownSolutionsPicard(A, rhs, x_new); + INFO("[time] Applying Dirichlet BCs took %g s.", time_dirichlet.elapsed()); - // std::cout << "A:\n" << Eigen::MatrixXd(A) << "\n"; - // std::cout << "rhs:\n" << rhs << "\n\n"; - + BaseLib::RunTime time_linear_solver; + time_linear_solver.start(); bool iteration_succeeded = _linear_solver.solve(A, rhs, x_new); + INFO("[time] Linear solver took %g s.", time_linear_solver.elapsed()); if (!iteration_succeeded) { @@ -116,6 +127,9 @@ bool NonlinearSolver<NonlinearSolverTag::Picard>::solve( // Update x s.t. in the next iteration we will compute the right delta x LinAlg::copy(x_new, x); + INFO("[time] Iteration #%u took %g s.", iteration, + time_iteration.elapsed()); + if (error_dx < _tol) { error_norms_met = true; @@ -177,20 +191,30 @@ bool NonlinearSolver<NonlinearSolverTag::Newton>::solve( unsigned iteration = 1; for (; iteration < _maxiter; ++iteration) { + BaseLib::RunTime time_iteration; + time_iteration.start(); + sys.preIteration(iteration, x); + BaseLib::RunTime time_assembly; + time_assembly.start(); sys.assembleResidualNewton(x); sys.getResidual(x, res); - sys.assembleJacobian(x); sys.getJacobian(J); + INFO("[time] Assembly took %g s.", time_assembly.elapsed()); + + BaseLib::RunTime time_dirichlet; + time_dirichlet.start(); sys.applyKnownSolutionsNewton(J, res, minus_delta_x); + INFO("[time] Applying Dirichlet BCs took %g s.", time_dirichlet.elapsed()); auto const error_res = LinAlg::norm2(res); - // std::cout << " J:\n" << Eigen::MatrixXd(J) << std::endl; - + BaseLib::RunTime time_linear_solver; + time_linear_solver.start(); bool iteration_succeeded = _linear_solver.solve(J, res, minus_delta_x); + INFO("[time] Linear solver took %g s.", time_linear_solver.elapsed()); if (!iteration_succeeded) { @@ -251,6 +275,9 @@ bool NonlinearSolver<NonlinearSolverTag::Newton>::solve( " tolerance(dx)=%.4e", iteration, error_dx, error_res, norm_x, error_dx / norm_x, _tol); + INFO("[time] Iteration #%u took %g s.", iteration, + time_iteration.elapsed()); + if (error_dx < _tol) { error_norms_met = true; diff --git a/ProcessLib/Output.cpp b/ProcessLib/Output.cpp index af0c2cc77cd7a5d7f86a2c0392f2384f60c07a5a..fa94ca94ce7898da61b0a7a0456fb6584c8e3ad2 100644 --- a/ProcessLib/Output.cpp +++ b/ProcessLib/Output.cpp @@ -16,6 +16,7 @@ #include <logog/include/logog.hpp> #include "BaseLib/FileTools.h" +#include "BaseLib/RunTime.h" namespace { @@ -105,6 +106,9 @@ doOutputAlways(Process const& process, const double t, GlobalVector const& x) { + BaseLib::RunTime time_output; + time_output.start(); + auto spd_it = _single_process_data.find(&process); if (spd_it == _single_process_data.end()) { OGS_FATAL("The given process is not contained in the output configuration." @@ -120,6 +124,8 @@ doOutputAlways(Process const& process, DBUG("output to %s", output_file_name.c_str()); process.output(output_file_name, timestep, x); spd.pvd_file.addVTUFile(output_file_name, t); + + INFO("[time] Output took %g s.", time_output.elapsed()); } void Output:: @@ -149,6 +155,9 @@ void Output::doOutputNonlinearIteration(Process const& process, { if (!_output_nonlinear_iteration_results) return; + BaseLib::RunTime time_output; + time_output.start(); + auto spd_it = _single_process_data.find(&process); if (spd_it == _single_process_data.end()) { OGS_FATAL("The given process is not contained in the output configuration." @@ -164,6 +173,8 @@ void Output::doOutputNonlinearIteration(Process const& process, + ".vtu"; DBUG("output iteration results to %s", output_file_name.c_str()); process.output(output_file_name, timestep, x); + + INFO("[time] Output took %g s.", time_output.elapsed()); } }