Merge pull request #5174 from atgeirr/time-reporting-improvements

Time reporting improvements

opm/simulators/flow/Banners.cpp

@@ -112,7 +112,10 @@ void printFlowBanner(int nprocs, int nthreads, std::string_view moduleVersionNam
     std::cout << "Using "<< nprocs << " MPI processes with "<< nthreads <<" OMP threads on each \n\n";
 }
 
-void printFlowTrailer(int nprocs, int nthreads,
+void printFlowTrailer(int nprocs,
+                      int nthreads,
+                      const double total_setup_time,
+                      const double deck_read_time,
                       const SimulatorReport& report,
                       const SimulatorReportSingle& localsolves_report)
 {
@@ -120,6 +123,8 @@ void printFlowTrailer(int nprocs, int nthreads,
     ss << "\n\n================    End of simulation     ===============\n\n";
     ss << fmt::format("Number of MPI processes: {:9}\n", nprocs);
     ss << fmt::format("Threads per MPI process: {:9}\n", nthreads);
+    ss << fmt::format("Setup time:                 {:9.2f} s\n", total_setup_time);
+    ss << fmt::format("  Deck input:               {:9.2f} s\n", deck_read_time);
     report.reportFullyImplicit(ss);
 
     if (localsolves_report.total_linearizations > 0) {

opm/simulators/flow/Banners.hpp

@@ -40,7 +40,10 @@ void printPRTHeader(const int nprocs, const int nthreads,
 void printFlowBanner(int nprocs, int threads, std::string_view moduleVersionName);
 
 // Print flow application trailer.
-void printFlowTrailer(int nprocs, int nthreads,
+void printFlowTrailer(int nprocs,
+                      int nthreads,
+                      const double total_setup_time,
+                      const double deck_read_time,
                       const SimulatorReport& report,
                       const SimulatorReportSingle& localsolves_report);
 

opm/simulators/flow/FlowMain.hpp

@@ -354,6 +354,9 @@ void handleExtraConvergenceOutput(SimulatorReport& report,
             try {
                 // deal with some administrative boilerplate
 
+                Dune::Timer setupTimerAfterReadingDeck;
+                setupTimerAfterReadingDeck.start();
+
                 int status = setupParameters_(this->argc_, this->argv_, EclGenericVanguard::comm());
                 if (status)
                     return status;
@@ -362,6 +365,9 @@ void handleExtraConvergenceOutput(SimulatorReport& report,
                 setupModelSimulator();
                 createSimulator();
 
+                this->deck_read_time_ = modelSimulator_->vanguard().setupTime();
+                this->total_setup_time_ = setupTimerAfterReadingDeck.elapsed() + this->deck_read_time_;
+
                 // if run, do the actual work, else just initialize
                 int exitCode = (this->*runOrInitFunc)();
                 if (cleanup) {
@@ -514,7 +520,7 @@ void handleExtraConvergenceOutput(SimulatorReport& report,
                 = omp_get_max_threads();
 #endif
 
-            printFlowTrailer(mpi_size_, threads, report, simulator_->model().localAccumulatedReports());
+            printFlowTrailer(mpi_size_, threads, total_setup_time_, deck_read_time_, report, simulator_->model().localAccumulatedReports());
 
             detail::handleExtraConvergenceOutput(report,
                                                  EWOMS_GET_PARAM(TypeTag, std::string, OutputExtraConvergenceInfo),
@@ -590,6 +596,8 @@ void handleExtraConvergenceOutput(SimulatorReport& report,
         char **argv_;
         bool output_cout_;
         bool output_files_;
+        double total_setup_time_ = 0.0;
+        double deck_read_time_ = 0.0;
     };
 
 } // namespace Opm

opm/simulators/timestepping/SimulatorReport.cpp

@@ -114,68 +114,70 @@ namespace Opm
                 return decltype(val){1};
             return val;
         };
-        os << fmt::format("Total time (seconds):       {:9.2f} \n", total_time);
+        // Disabling this output as it is redundant with the solver_time, now
+        // output as "Simulation time". Usually very small difference between them.
+        // os << fmt::format("Total time:                 {:9.2f} s\n", total_time);
 
-         os << fmt::format("Solver time (seconds):      {:9.2f} \n",
+        os << fmt::format("Simulation time:            {:9.2f} s\n",
                           solver_time + (failureReport ? failureReport->solver_time : 0.0));
 
         if (assemble_time > 0.0 || linear_solve_time > 0.0) {
 
             double t = assemble_time + (failureReport ? failureReport->assemble_time : 0.0);
-            os << fmt::format(" Assembly time (seconds):   {:9.2f}", t);
+            os << fmt::format("  Assembly time:            {:9.2f} s", t);
 
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->assemble_time,
                                 100*failureReport->assemble_time/noZero(t));
              }
             os << std::endl;
 
             t = assemble_time_well + (failureReport ? failureReport->assemble_time_well : 0.0);
-            os << fmt::format("   Well assembly (seconds):   {:7.2f}", t);
+            os << fmt::format("    Well assembly:            {:7.2f} s", t);
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->assemble_time_well,
                                 100*failureReport->assemble_time_well/noZero(t));
             }
             os << std::endl;
 
             t = linear_solve_time + (failureReport ? failureReport->linear_solve_time : 0.0);
-            os << fmt::format(" Linear solve time (seconds):{:8.2f}", t);
+            os << fmt::format("  Linear solve time:        {:9.2f} s", t);
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->linear_solve_time,
                                 100*failureReport->linear_solve_time/noZero(t));
             }
             os << std::endl;
 
             t = linear_solve_setup_time + (failureReport ? failureReport->linear_solve_setup_time : 0.0);
-            os << fmt::format("   Linear setup (seconds):    {:7.2f}", t);
+            os << fmt::format("    Linear setup:             {:7.2f} s", t);
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->linear_solve_setup_time,
                                 100*failureReport->linear_solve_setup_time/noZero(t));
             }
             os << std::endl;
 
             t = update_time + (failureReport ? failureReport->update_time : 0.0);
-            os << fmt::format(" Update time (seconds):       {:7.2f}", t);
+            os << fmt::format("  Props/update time:          {:7.2f} s", t);
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->update_time,
                                 100*failureReport->update_time/noZero(t));
             }
             os << std::endl;
             t = pre_post_time + (failureReport ? failureReport->pre_post_time : 0.0);
-            os << fmt::format(" Pre/post step (seconds):     {:7.2f}", t);
+            os << fmt::format("  Pre/post step:              {:7.2f} s", t);
             if (failureReport) {
-              os << fmt::format(" (Failed: {:2.1f}; {:2.1f}%)",
+              os << fmt::format(" (Wasted: {:2.1f} s; {:2.1f}%)",
                                 failureReport->pre_post_time,
                                 100*failureReport->pre_post_time/noZero(t));
             }
             os << std::endl;
 
-            os << fmt::format(" Output write time (seconds): {:7.2f}", 
+            os << fmt::format("  Output write time:          {:7.2f} s",
                               output_write_time + (failureReport ? failureReport->output_write_time : 0.0));
             os << std::endl;
         }
@@ -183,7 +185,7 @@ namespace Opm
         int n = total_linearizations + (failureReport ? failureReport->total_linearizations : 0);
         os << fmt::format("Overall Linearizations:    {:7}", n);
         if (failureReport) {
-          os << fmt::format("    (Failed: {:3}; {:2.1f}%)",
+          os << fmt::format("      (Wasted: {:5}; {:2.1f}%)",
                             failureReport->total_linearizations,
                             100.0*failureReport->total_linearizations/noZero(n));
         }
@@ -192,7 +194,7 @@ namespace Opm
         n = total_newton_iterations + (failureReport ? failureReport->total_newton_iterations : 0);
         os << fmt::format("Overall Newton Iterations: {:7}", n);
         if (failureReport) {
-          os << fmt::format("    (Failed: {:3}; {:2.1f}%)",
+          os << fmt::format("      (Wasted: {:5}; {:2.1f}%)",
                             failureReport->total_newton_iterations,
                             100.0*failureReport->total_newton_iterations/noZero(n));
         }
@@ -201,7 +203,7 @@ namespace Opm
         n = total_linear_iterations + (failureReport ? failureReport->total_linear_iterations : 0);
         os << fmt::format("Overall Linear Iterations: {:7}", n);
         if (failureReport) {
-          os << fmt::format("    (Failed: {:3}; {:2.1f}%)",
+          os << fmt::format("      (Wasted: {:5}; {:2.1f}%)",
                             failureReport->total_linear_iterations,
                             100.0*failureReport->total_linear_iterations/noZero(n));
         }