Output better timing information with each step (#1714)

Author: marchdf

amr-wind/core/SimTime.H

@@ -177,6 +177,11 @@ public:
         m_stop_time = -1.;
     }
 
+    /** Return true if TinyProfiler output should be sent to the log file at
+     * this timestep
+     */
+    bool output_profiling_info() const;
+
 private:
     //! Timestep sizes
     amrex::Vector<amrex::Real> m_dt =
@@ -287,6 +292,9 @@ private:
     //! Time interval for regridding
     int m_regrid_interval{-1};
 
+    //! Time step interval for profiling output
+    int m_profiling_interval{-1};
+
     //! Verbosity
     int m_verbose{0};
 

amr-wind/core/SimTime.cpp

@@ -39,6 +39,7 @@ void SimTime::parse_parameters()
     pp.query("plot_start", m_plt_start_index);
     pp.query("checkpoint_start", m_chkpt_start_index);
     pp.query("use_force_cfl", m_use_force_cfl);
+    pp.query("profiling_interval", m_profiling_interval);
 
     // Tolerances
     pp.query("plot_time_interval_reltol", m_plt_t_tol);
@@ -418,4 +419,11 @@ void SimTime::calculate_minimum_enforce_dt_abs_tol()
     }
 }
 
+bool SimTime::output_profiling_info() const
+{
+    return (
+        (m_profiling_interval > 0) &&
+        (m_time_index % m_profiling_interval == 0));
+}
+
 } // namespace amr_wind

amr-wind/incflo.cpp

@@ -23,10 +23,6 @@ incflo::incflo()
     // constructor. No valid BoxArray and DistributionMapping have been defined.
     // But the arrays for them have been resized.
 
-    amrex::Print() << std::endl
-                   << "Initializing AMR-Wind." << std::endl
-                   << std::endl;
-
     // Check if dry run is requested and set up if so
     CheckAndSetUpDryRun();
 
@@ -287,8 +283,10 @@ void incflo::Evolve()
 {
     BL_PROFILE("amr-wind::incflo::Evolve()");
 
+    const amrex::Real init_time = amrex::ParallelDescriptor::second();
+
     while (m_time.new_timestep()) {
-        amrex::Real time0 = amrex::ParallelDescriptor::second();
+        const amrex::Real time0 = amrex::ParallelDescriptor::second();
 
         regrid_and_update();
 
@@ -302,7 +300,7 @@ void incflo::Evolve()
             pre_advance_stage2();
         }
 
-        amrex::Real time1 = amrex::ParallelDescriptor::second();
+        const amrex::Real time1 = amrex::ParallelDescriptor::second();
         // Advance to time t + dt
         for (int fixed_point_iteration = 0;
              fixed_point_iteration < m_fixed_point_iterations;
@@ -311,22 +309,27 @@ void incflo::Evolve()
         }
 
         amrex::Print() << std::endl;
-        amrex::Real time2 = amrex::ParallelDescriptor::second();
+        const amrex::Real time2 = amrex::ParallelDescriptor::second();
         post_advance_work();
-        amrex::Real time3 = amrex::ParallelDescriptor::second();
+        const amrex::Real time3 = amrex::ParallelDescriptor::second();
 
-        amrex::Print() << "WallClockTime: " << m_time.time_index()
-                       << " Pre: " << std::setprecision(3) << (time1 - time0)
+        amrex::Print() << "WallClockTime in Evolve() for step "
+                       << m_time.time_index()
+                       << ": Pre: " << std::setprecision(3) << (time1 - time0)
                        << " Solve: " << std::setprecision(4) << (time2 - time1)
                        << " Post: " << std::setprecision(3) << (time3 - time2)
                        << " Total: " << std::setprecision(4) << (time3 - time0)
                        << std::endl;
-
-        amrex::Print() << "Solve time per cell: " << std::setprecision(4)
-                       << amrex::ParallelDescriptor::NProcs() *
-                              (time2 - time1) /
-                              static_cast<amrex::Real>(m_cell_count)
+        amrex::Print() << "Cumulative WallClockTime in Evolve(): "
+                       << std::setprecision(4) << (time3 - init_time)
                        << std::endl;
+
+#ifdef AMREX_TINY_PROFILING
+        if (m_time.output_profiling_info()) {
+            amrex::Print() << "\nCumulative times reported by TinyProfiler:";
+            amrex::TinyProfiler::Finalize(true);
+        }
+#endif
     }
     amrex::Print() << "\n======================================================"
                       "========================\n"

docs/sphinx/user/inputs_time.rst

@@ -263,3 +263,12 @@ This section also addresses the time-dependent nature of checkpoint files, plot
    When :input_param:`time.enforce_checkpoint_time_dt` is true, a tolerance is needed to determine when
    it is necessary to shrink the time step size. This tolerance is relative to the checkpoint time interval.
    In most cases, this parameter need not be modified, but it can be changed by the user.
+
+.. input_param:: time.profiling_interval
+
+   **type:** Integer, optional, default = -1
+
+   If this value is greater than zero, it indicates the frequency (in
+   timesteps) at which profiling information is written to the log
+   file. This will only work if the code was compiled with
+   ``AMR_WIND_ENABLE_TINY_PROFILE`` set to ``ON``.