Add more timers

Author: T3C42

mt-kahypar/dynamic/dynamic_io.h

@@ -276,13 +276,16 @@ inline std::vector<HypernodeID> parseIDs(const std::string& line) {
       throw std::runtime_error("Could not open file: " + filename);
     }
     std::cout << "Saving other timings to file: " << filename << std::endl;
-    file << "total_time, strategy_time, setup_time, initial_partitioning_time, io_time_change_parsing, io_time_graph_parsing" << std::endl;
+    file << "total_time,  io_time_graph_parsing, setup_time, initialization_time, initial_partitioning_time, io_time_change_parsing, strategy_time, logging_time, finalization_time" << std::endl;
     file << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.total_time).count() << ", "
-         << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.strategy_time).count() << ", "
-         << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.setup_time).count() << ", "
-         << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.initial_partitioning_time).count() << ", "
-         << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.io_time_change_parsing).count() << ", "
-         << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.io_time_graph_parsing).count()
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.io_time_graph_parsing).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.setup_time).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.initialization_time).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.initial_partitioning_time).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.io_time_change_parsing).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.strategy_time).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.logging_time).count() << ", "
+    << std::chrono::duration_cast<std::chrono::milliseconds>(context.dynamic.other_timings.finalization_time).count()
          << std::endl;
     file.close();
 

mt-kahypar/dynamic/dynamic_partitioner.h

@@ -84,9 +84,12 @@ namespace mt_kahypar::dyn {
       context.dynamic.local_fm_round = &localFM_round;
 
       context.dynamic.other_timings.setup_time = std::chrono::high_resolution_clock::now() - setup_time_start;
+      auto finalization_time_start = std::chrono::high_resolution_clock::now();
 
       try {
 
+        auto init_time_start = std::chrono::high_resolution_clock::now();
+
         std::cout << "Processing " << num_changes << " changes" << std::endl;
 
         auto& hypergraph_p =  strategy->init();
@@ -97,6 +100,9 @@ namespace mt_kahypar::dyn {
 
         auto duration_sum = std::chrono::high_resolution_clock::duration::zero();
         auto change_io_duration_sum = std::chrono::high_resolution_clock::duration::zero();
+        auto log_duration_sum = std::chrono::high_resolution_clock::duration::zero();
+
+        context.dynamic.other_timings.initialization_time = std::chrono::high_resolution_clock::now() - init_time_start - context.dynamic.other_timings.initial_partitioning_time;
 
         for (size_t i = 0; i < num_changes; ++i) {
           HighResClockTimepoint start_io = std::chrono::high_resolution_clock::now();
@@ -114,11 +120,16 @@ namespace mt_kahypar::dyn {
           if (log_step_size != 0 && i % log_step_size != 0 && i != num_changes - 1) {
             continue;
           }
+          HighResClockTimepoint start_log = std::chrono::high_resolution_clock::now();
           log_km1_live(i+1, num_changes, context, DynamicStrategy::getPartitionedHypergraphCopy(*strategy), duration_sum);
+          log_duration_sum += std::chrono::high_resolution_clock::now() - start_log;
         }
 
         context.dynamic.other_timings.strategy_time = duration_sum;
         context.dynamic.other_timings.io_time_change_parsing = change_io_duration_sum;
+        context.dynamic.other_timings.logging_time = log_duration_sum;
+
+        finalization_time_start = std::chrono::high_resolution_clock::now();
 
         strategy->printAdditionalFinalStats();
 
@@ -135,10 +146,12 @@ namespace mt_kahypar::dyn {
           exit(1);
         }
 
-      context.dynamic.other_timings.total_time = std::chrono::high_resolution_clock::now() - total_time_start;
-      if (context.dynamic.save_other_timings) {
+    context.dynamic.other_timings.finalization_time = std::chrono::high_resolution_clock::now() - finalization_time_start;
+    context.dynamic.other_timings.total_time = std::chrono::high_resolution_clock::now() - total_time_start;
+    if (context.dynamic.save_other_timings) {
         generateOtherTimingsFile(context);
       }
+
       return 0;
     }
 }

mt-kahypar/partition/context.h

@@ -302,11 +302,14 @@ struct LocalFMRound {
 struct OtherTimings
 {
   std::chrono::high_resolution_clock::duration total_time;
-  std::chrono::high_resolution_clock::duration strategy_time;
+  std::chrono::high_resolution_clock::duration io_time_graph_parsing;
   std::chrono::high_resolution_clock::duration setup_time;
+  std::chrono::high_resolution_clock::duration initialization_time;
   std::chrono::high_resolution_clock::duration initial_partitioning_time;
   std::chrono::high_resolution_clock::duration io_time_change_parsing;
-  std::chrono::high_resolution_clock::duration io_time_graph_parsing;
+  std::chrono::high_resolution_clock::duration strategy_time;
+  std::chrono::high_resolution_clock::duration logging_time;
+  std::chrono::high_resolution_clock::duration finalization_time;
 };
 
 struct DynamicParameters {