Add --profile flag with performance breakdown

dav-og · dav-og · commit 98dfcf214236 · 2025-10-10T16:17:28.000-06:00
Display profiling summary showing Setup, Dynamics Loop (with Chrono solver and hydrodynamics breakdown), and Export times.
diff --git a/app/run_hydrochrono.cpp b/app/run_hydrochrono.cpp
@@ -83,6 +83,7 @@ struct CLIArgs {
     bool h5_verbose = false;            // NEW: HDF5 verbose diagnostics
     std::string h5_tag;                 // NEW: Optional tag appended to filename
     bool fail_fast = false;             // NEW: Stop on first failure during sweep
+    bool profile = false;               // NEW: Enable runtime profiling summary
 };
 
 static CLIArgs ParseArguments(int argc, char* argv[]) {
@@ -136,6 +137,8 @@ static CLIArgs ParseArguments(int argc, char* argv[]) {
             }
         } else if (arg == "--fail-fast") {
             args.fail_fast = true;
+        } else if (arg == "--profile") {
+            args.profile = true;
         } else if (arg.substr(0, 1) != "-") {
             // This is a positional argument (input directory)
             if (args.input_directory.empty()) {
@@ -286,6 +289,10 @@ int main(int argc, char* argv[]) {
         runner_args.push_back("--trace");
     }
     
+    if (args.profile) {
+        runner_args.push_back("--profile");
+    }
+    
     if (!args.model_file.empty()) {
         runner_args.push_back("--model_file");
         runner_args.push_back(args.model_file);
diff --git a/include/hydroc/hydro_forces.h b/include/hydroc/hydro_forces.h
@@ -149,6 +149,16 @@ class ForceFunc6d {
 
 class ChLoadAddedMass;
 
+// Lightweight hydrodynamics profiling stats
+struct HydroProfileStats {
+    double hydrostatics_seconds = 0.0;
+    double radiation_seconds    = 0.0;
+    double waves_seconds        = 0.0;
+    int hydrostatics_calls      = 0;
+    int radiation_calls         = 0;
+    int waves_calls             = 0;
+};
+
 // TODO: Rename TestHydro for clarity, perhaps to HydroForces?
 // TODO: Split TestHydro class from its helper classes for clearer code structure.
 class TestHydro {
@@ -233,6 +243,9 @@ class TestHydro {
      */
     double CoordinateFuncForBody(int b, int i);
 
+    // Hydrodynamics profiling accessors
+    HydroProfileStats GetProfileStats() const { return profile_stats_; }
+
   private:
     // Class properties related to the body and hydrodynamics
     std::vector<std::shared_ptr<ChBody>> bodies_;
@@ -281,6 +294,9 @@ class TestHydro {
      * @param index The DOF index, ranging from [0,1,...,5].
      */
     double SetVelHistory(double val, int step, int b_num, int index);
+
+    // Hydrodynamics profiling data (accumulated over run)
+    HydroProfileStats profile_stats_;
 };
 
 #endif
diff --git a/include/hydroc/utils/profiler.h b/include/hydroc/utils/profiler.h
diff --git a/src/hydro_forces.cpp b/src/hydro_forces.cpp
@@ -24,6 +24,7 @@
 #include <random>
 #include <stdexcept>
 #include <vector>
+#include <chrono>
 
 const int kDofPerBody  = 6;
 const int kDofLinOrRot = 3;
@@ -251,6 +252,7 @@ void TestHydro::AddWaves(std::shared_ptr<WaveBase> waves) {
 }
 
 std::vector<double> TestHydro::ComputeForceHydrostatics() {
+    auto __t0 = std::chrono::steady_clock::now();
     assert(num_bodies_ > 0);
 
     const double rho = file_info_.GetRhoVal();
@@ -305,10 +307,13 @@ std::vector<double> TestHydro::ComputeForceHydrostatics() {
         body_force_hydrostatic[5] += buoyancy_torque.z();
     }
 
+    profile_stats_.hydrostatics_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();
+    profile_stats_.hydrostatics_calls++;
     return force_hydrostatic_;
 }
 
 std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {
+    auto __t0 = std::chrono::steady_clock::now();
     const int rirf_steps = file_info_.GetRIRFDims(2);
     const int total_dofs = kDofPerBody * num_bodies_;
 
@@ -348,14 +353,16 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {
             for (int b = 0; b < num_bodies_; ++b) {
                 auto& velocity_history_body = velocity_history_[b];
                 if (!velocity_history_body.empty()) {
-                    velocity_history_body.pop_back();
-                }
+                velocity_history_body.pop_back();
             }
         }
+        }
     }
 
     // Nothing to convolve with if we don't yet have at least 2 time points
     if (time_history_.size() <= 1) {
+        profile_stats_.radiation_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();
+        profile_stats_.radiation_calls++;
         return force_radiation_damping_;
     }
 
@@ -414,7 +421,7 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {
                 interpolated_velocity_dof[3] = weight_older * older_velocity[3] + weight_newer * newer_velocity[3];
                 interpolated_velocity_dof[4] = weight_older * older_velocity[4] + weight_newer * newer_velocity[4];
                 interpolated_velocity_dof[5] = weight_older * older_velocity[5] + weight_newer * newer_velocity[5];
-            } else {
+                } else {
                 throw std::runtime_error(
                     "Radiation convolution: interpolation error; rirf_query_time not bracketed by adjacent history.");
             }
@@ -435,6 +442,8 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {
         }
     }
 
+    profile_stats_.radiation_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();
+    profile_stats_.radiation_calls++;
     return force_radiation_damping_;
 }
 
@@ -452,19 +461,16 @@ double TestHydro::GetRIRFval(int row, int col, int st) {
 }
 
 Eigen::VectorXd TestHydro::ComputeForceWaves() {
+    auto __t0 = std::chrono::steady_clock::now();
     // Ensure bodies_ is not empty
     if (bodies_.empty()) {
         throw std::runtime_error("bodies_ array is empty in ComputeForceWaves");
     }
 
     force_waves_ = user_waves_->GetForceAtTime(bodies_[0]->GetChTime());
 
-    // TODO: Add size check for force_waves_ if needed
-    // Example:
-    // if (force_waves_.size() != expected_size) {
-    //     throw std::runtime_error("Mismatched size in ComputeForceWaves");
-    // }
-
+    profile_stats_.waves_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();
+    profile_stats_.waves_calls++;
     return force_waves_;
 }
 
diff --git a/src/hydrochrono_runner/run_hydrochrono_from_yaml.cpp b/src/hydrochrono_runner/run_hydrochrono_from_yaml.cpp
@@ -292,6 +292,7 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
         bool enable_logging = false; // default: only log when --log is supplied
         bool debug_mode = false;
         bool trace_mode = false;
+        bool profile_mode = false;
 
         // Parse command line arguments
         for (int i = 1; i < argc; ++i) {
@@ -311,6 +312,8 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
             } else if (arg == "--trace") {
                 trace_mode = true;
                 debug_mode = true; // trace implies debug
+            } else if (arg == "--profile") {
+                profile_mode = true;
             } else if (arg == "--nobanner") {
                 // Optional: could disable banner; currently handled by enable_cli_output
             } else if (arg == "--quiet") {
@@ -655,7 +658,14 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
         // ---------------------------------------------------------------------
         // 7. Run simulation
         // ---------------------------------------------------------------------
-        auto start_time = std::chrono::steady_clock::now();
+        auto wall_start = std::chrono::steady_clock::now();
+        // Profiling accumulators
+        std::chrono::steady_clock::time_point t;
+        double prof_setup_seconds = 0.0;
+        double prof_loop_seconds = 0.0;
+        double prof_export_seconds = 0.0;
+        double prof_other_seconds = 0.0;
+        auto prof_section_start = std::chrono::steady_clock::now(); // setup section start
         
         
         // Log simulation loop entry
@@ -680,10 +690,14 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
             while (system->GetChTime() < end_time_bound) {
                 double current_time = system->GetChTime();
                 try {
+                    if (profile_mode) { t = std::chrono::steady_clock::now(); }
                     system->DoStepDynamics(loop_dt);
+                    if (profile_mode) { prof_loop_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - t).count(); }
                     step_count++;
                     if (exporter) {
+                        if (profile_mode) { t = std::chrono::steady_clock::now(); }
                         exporter->RecordStep(system.get());
+                        if (profile_mode) { prof_export_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - t).count(); }
                     }
                     previous_time = current_time;
                 } catch (const std::exception& e) {
@@ -734,10 +748,14 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
                 
                 try {
                     // 🧯 Scoped try/catch around DoStepDynamics
+                    if (profile_mode) { t = std::chrono::steady_clock::now(); }
                     system->DoStepDynamics(loop_dt);
+                    if (profile_mode) { prof_loop_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - t).count(); }
                     step_count++;
                     if (exporter) {
+                        if (profile_mode) { t = std::chrono::steady_clock::now(); }
                         exporter->RecordStep(system.get());
+                        if (profile_mode) { prof_export_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - t).count(); }
                     }
                     
                     // 🧯 After first step - check if simulation time advanced
@@ -875,21 +893,54 @@ int RunHydroChronoFromYAML(int argc, char* argv[]) {
                     break;  // Exit simulation loop on exception
                 }
             }
-        }
+            }
         }
         
-        auto end_time = std::chrono::steady_clock::now();
-        auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(end_time - start_time);
+        auto wall_end = std::chrono::steady_clock::now();
+        auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(wall_end - wall_start);
         
         // Final results display (CLI visible)
         hydroc::cli::ShowSimulationResults(system->GetChTime(), static_cast<int>(system->GetChTime() / loop_dt), duration.count() / 1000.0);
 
         // Finalize HDF5 output with runtime metadata
         if (exporter) {
-            double wall_s = std::chrono::duration_cast<std::chrono::duration<double>>(end_time - start_time).count();
+            double wall_s = std::chrono::duration_cast<std::chrono::duration<double>>(wall_end - wall_start).count();
             exporter->SetRunMetadata(std::string(""), std::string(""), wall_s, step_count, loop_dt, system->GetChTime());
             exporter->Finalize();
         }
+
+        // Optional profiling summary
+        if (profile_mode) {
+            double wall_seconds = std::chrono::duration_cast<std::chrono::duration<double>>(wall_end - wall_start).count();
+            prof_other_seconds = std::max(0.0, wall_seconds - (prof_setup_seconds + prof_loop_seconds + prof_export_seconds));
+            
+            std::vector<std::string> prof_lines;
+            auto pct = [&](double s){ return hydroc::FormatNumber(100.0 * (s / std::max(1e-12, wall_seconds)), 1) + "%"; };
+            
+            // Top-level sections
+            prof_lines.push_back(hydroc::cli::CreateAlignedLine("📦", "Setup", hydroc::FormatNumber(prof_setup_seconds, 3) + " s (" + pct(prof_setup_seconds) + ")"));
+            prof_lines.push_back(hydroc::cli::CreateAlignedLine("⚙️", "Dynamics Loop", hydroc::FormatNumber(prof_loop_seconds, 3) + " s (" + pct(prof_loop_seconds) + ")"));
+            
+            // Nested breakdown under Dynamics Loop
+            if (test_hydro) {
+                auto hp = test_hydro->GetProfileStats();
+                double hydro_total = hp.hydrostatics_seconds + hp.radiation_seconds + hp.waves_seconds;
+                double chrono_solver = std::max(0.0, prof_loop_seconds - hydro_total);
+                
+                auto loop_pct = [&](double s){ return hydroc::FormatNumber(100.0 * (s / std::max(1e-12, prof_loop_seconds)), 1) + "%"; };
+                prof_lines.push_back(hydroc::cli::CreateAlignedLine("   🔧", "Chrono Solver", hydroc::FormatNumber(chrono_solver, 4) + " s  (" + loop_pct(chrono_solver) + ")"));
+                prof_lines.push_back(hydroc::cli::CreateAlignedLine("   ⚓", "Hydrostatics", hydroc::FormatNumber(hp.hydrostatics_seconds, 4) + " s  (" + loop_pct(hp.hydrostatics_seconds) + ")  [" + std::to_string(hp.hydrostatics_calls) + " calls]"));
+                prof_lines.push_back(hydroc::cli::CreateAlignedLine("   💧", "Radiation Damping", hydroc::FormatNumber(hp.radiation_seconds, 4) + " s  (" + loop_pct(hp.radiation_seconds) + ")  [" + std::to_string(hp.radiation_calls) + " calls]"));
+                prof_lines.push_back(hydroc::cli::CreateAlignedLine("   🌊", "Wave Forces", hydroc::FormatNumber(hp.waves_seconds, 4) + " s  (" + loop_pct(hp.waves_seconds) + ")  [" + std::to_string(hp.waves_calls) + " calls]"));
+            }
+            
+            if (exporter) {
+                prof_lines.push_back(hydroc::cli::CreateAlignedLine("💾", "Export", hydroc::FormatNumber(prof_export_seconds, 3) + " s (" + pct(prof_export_seconds) + ")"));
+            }
+            prof_lines.push_back(hydroc::cli::CreateAlignedLine("━━━", "━━━━━━━━━━━━━━━━━━━━━━", "━━━━━━━━━━━━━━━━━━━━"));
+            prof_lines.push_back(hydroc::cli::CreateAlignedLine("📈", "Total Runtime", hydroc::FormatNumber(wall_seconds, 3) + " s (100%)"));
+            hydroc::cli::ShowSectionBox("🔬 Performance Profiling", prof_lines);
+        }
         
         // Display warnings section if any warnings were collected
         hydroc::cli::DisplayWarnings();

Original file line number	Diff line number	Diff line change
`@@ -24,6 +24,7 @@`
`24`	`24`	`#include <random>`
`25`	`25`	`#include <stdexcept>`
`26`	`26`	`#include <vector>`
	`27`	`+#include <chrono>`
`27`	`28`
`28`	`29`	`const int kDofPerBody = 6;`
`29`	`30`	`const int kDofLinOrRot = 3;`
`@@ -251,6 +252,7 @@ void TestHydro::AddWaves(std::shared_ptr<WaveBase> waves) {`
`251`	`252`	`}`
`252`	`253`
`253`	`254`	`std::vector<double> TestHydro::ComputeForceHydrostatics() {`
	`255`	`+ auto __t0 = std::chrono::steady_clock::now();`
`254`	`256`	`assert(num_bodies_ > 0);`
`255`	`257`
`256`	`258`	`const double rho = file_info_.GetRhoVal();`
`@@ -305,10 +307,13 @@ std::vector<double> TestHydro::ComputeForceHydrostatics() {`
`305`	`307`	`body_force_hydrostatic[5] += buoyancy_torque.z();`
`306`	`308`	`}`
`307`	`309`
	`310`	`+ profile_stats_.hydrostatics_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();`
	`311`	`+ profile_stats_.hydrostatics_calls++;`
`308`	`312`	`return force_hydrostatic_;`
`309`	`313`	`}`
`310`	`314`
`311`	`315`	`std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {`
	`316`	`+ auto __t0 = std::chrono::steady_clock::now();`
`312`	`317`	`const int rirf_steps = file_info_.GetRIRFDims(2);`
`313`	`318`	`const int total_dofs = kDofPerBody * num_bodies_;`
`314`	`319`
`@@ -348,14 +353,16 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {`
`348`	`353`	`for (int b = 0; b < num_bodies_; ++b) {`
`349`	`354`	`auto& velocity_history_body = velocity_history_[b];`
`350`	`355`	`if (!velocity_history_body.empty()) {`
`351`		`- velocity_history_body.pop_back();`
`352`		`- }`
	`356`	`+ velocity_history_body.pop_back();`
`353`	`357`	`}`
`354`	`358`	`}`
	`359`	`+ }`
`355`	`360`	`}`
`356`	`361`
`357`	`362`	`// Nothing to convolve with if we don't yet have at least 2 time points`
`358`	`363`	`if (time_history_.size() <= 1) {`
	`364`	`+ profile_stats_.radiation_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();`
	`365`	`+ profile_stats_.radiation_calls++;`
`359`	`366`	`return force_radiation_damping_;`
`360`	`367`	`}`
`361`	`368`
`@@ -414,7 +421,7 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {`
`414`	`421`	`interpolated_velocity_dof[3] = weight_older * older_velocity[3] + weight_newer * newer_velocity[3];`
`415`	`422`	`interpolated_velocity_dof[4] = weight_older * older_velocity[4] + weight_newer * newer_velocity[4];`
`416`	`423`	`interpolated_velocity_dof[5] = weight_older * older_velocity[5] + weight_newer * newer_velocity[5];`
`417`		`- } else {`
	`424`	`+ } else {`
`418`	`425`	`throw std::runtime_error(`
`419`	`426`	`"Radiation convolution: interpolation error; rirf_query_time not bracketed by adjacent history.");`
`420`	`427`	`}`
`@@ -435,6 +442,8 @@ std::vector<double> TestHydro::ComputeForceRadiationDampingConv() {`
`435`	`442`	`}`
`436`	`443`	`}`
`437`	`444`
	`445`	`+ profile_stats_.radiation_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();`
	`446`	`+ profile_stats_.radiation_calls++;`
`438`	`447`	`return force_radiation_damping_;`
`439`	`448`	`}`
`440`	`449`
`@@ -452,19 +461,16 @@ double TestHydro::GetRIRFval(int row, int col, int st) {`
`452`	`461`	`}`
`453`	`462`
`454`	`463`	`Eigen::VectorXd TestHydro::ComputeForceWaves() {`
	`464`	`+ auto __t0 = std::chrono::steady_clock::now();`
`455`	`465`	`// Ensure bodies_ is not empty`
`456`	`466`	`if (bodies_.empty()) {`
`457`	`467`	`throw std::runtime_error("bodies_ array is empty in ComputeForceWaves");`
`458`	`468`	`}`
`459`	`469`
`460`	`470`	`force_waves_ = user_waves_->GetForceAtTime(bodies_[0]->GetChTime());`
`461`	`471`
`462`		`- // TODO: Add size check for force_waves_ if needed`
`463`		`- // Example:`
`464`		`- // if (force_waves_.size() != expected_size) {`
`465`		`- // throw std::runtime_error("Mismatched size in ComputeForceWaves");`
`466`		`- // }`
`467`		`-`
	`472`	`+ profile_stats_.waves_seconds += std::chrono::duration_cast<std::chrono::duration<double>>(std::chrono::steady_clock::now() - __t0).count();`
	`473`	`+ profile_stats_.waves_calls++;`
`468`	`474`	`return force_waves_;`
`469`	`475`	`}`
`470`	`476`