Add timing measurements for general procedures like io

Author: T3C42

mt-kahypar/dynamic/dynamic_io.h

@@ -262,4 +262,26 @@ inline std::vector<HypernodeID> parseIDs(const std::string& line) {
 
       file.close();
     }
+
+  inline void generateOtherTimingsFile(Context& context)
+  {
+    context.dynamic.result_folder += "_other_timings/";
+    generateFileName(context);
+    std::string filename = context.dynamic.output_path;
+    std::ofstream file(filename);
+    if (!file.is_open()) {
+      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 << 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::endl;
+    file.close();
+
+  }
 }

mt-kahypar/dynamic/dynamic_partitioner.h

@@ -13,17 +13,25 @@
 namespace mt_kahypar::dyn {
   inline int partition(Context& context) {
 
+      context.dynamic.other_timings = OtherTimings();
+      auto total_time_start = std::chrono::high_resolution_clock::now();
+
 
       context.partition.instance_type = InstanceType::hypergraph;
       context.partition.objective = Objective::km1;
       context.partition.gain_policy = GainPolicy::km1;
 
       // Read Hypergraph
+      auto graph_time_parsing_start = std::chrono::high_resolution_clock::now();
       mt_kahypar_hypergraph_t hypergraph_t = io::readInputFile(
               context.partition.graph_filename, context.partition.preset_type,
               context.partition.instance_type, context.partition.file_format,
               context.preprocessing.stable_construction_of_incident_edges);
       auto& hypergraph_m = utils::cast<ds::MutableHypergraph>(hypergraph_t);
+      context.dynamic.other_timings.io_time_graph_parsing = std::chrono::high_resolution_clock::now() -
+        graph_time_parsing_start;
+
+      auto setup_time_start = std::chrono::high_resolution_clock::now();
 
       // Initialize Memory Pool and Algorithm/Policy Registries
       register_memory_pool(hypergraph_t, context);
@@ -75,6 +83,8 @@ namespace mt_kahypar::dyn {
       LocalFMRound localFM_round = LocalFMRound();
       context.dynamic.local_fm_round = &localFM_round;
 
+      context.dynamic.other_timings.setup_time = std::chrono::high_resolution_clock::now() - setup_time_start;
+
       try {
 
         std::cout << "Processing " << num_changes << " changes" << std::endl;
@@ -86,14 +96,17 @@ namespace mt_kahypar::dyn {
         size_t log_step_size = num_changes * context.dynamic.logging_step_size_pct;
 
         auto duration_sum = std::chrono::high_resolution_clock::duration::zero();
+        auto change_io_duration_sum = std::chrono::high_resolution_clock::duration::zero();
 
         for (size_t i = 0; i < num_changes; ++i) {
+          HighResClockTimepoint start_io = std::chrono::high_resolution_clock::now();
           Change change;
           if (!context.dynamic.stream_changes) {
             change = changes[i];
           } else {
             change = parseChange(changes_file);
           }
+          change_io_duration_sum += std::chrono::high_resolution_clock::now() - start_io;
           HighResClockTimepoint start = std::chrono::high_resolution_clock::now();
             strategy->partition(change, num_changes);
           auto duration = std::chrono::high_resolution_clock::now() - start;
@@ -104,6 +117,9 @@ namespace mt_kahypar::dyn {
           log_km1_live(i+1, num_changes, context, DynamicStrategy::getPartitionedHypergraphCopy(*strategy), duration_sum);
         }
 
+        context.dynamic.other_timings.strategy_time = duration_sum;
+        context.dynamic.other_timings.io_time_change_parsing = change_io_duration_sum;
+
         strategy->printAdditionalFinalStats();
 
         if (context.partition.write_partition_file) {
@@ -119,6 +135,10 @@ 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) {
+        generateOtherTimingsFile(context);
+      }
       return 0;
     }
 }

mt-kahypar/dynamic/dynamic_strategy.h

@@ -108,6 +108,8 @@ namespace mt_kahypar::dyn {
         static ds::PartitionedHypergraph<ds::MutableHypergraph>
         partition_hypergraph_km1(ds::MutableHypergraph &hypergraph, Context &context) {
 
+          auto init_hgr_partitioning_start = std::chrono::high_resolution_clock::now();
+
           // copy the hypergraph to make sure we don't modify the original
           // ds::MutableHypergraph hypergraph_copy = hypergraph.copy();
 
@@ -131,6 +133,8 @@ namespace mt_kahypar::dyn {
 
           partitioned_hypergraph_s.setHypergraph(hypergraph);
 
+          context.dynamic.other_timings.initial_partitioning_time = std::chrono::high_resolution_clock::now() - init_hgr_partitioning_start;
+
           return partitioned_hypergraph_s;
         }
 

mt-kahypar/io/command_line_options.cpp

@@ -903,6 +903,10 @@ namespace mt_kahypar {
       ("d-changing-total-weight",
         po::value<bool>(&context.dynamic.changing_total_weight)->value_name("<bool>"),
         "Whether the total weight of the graph is expected to change, used for vcycle spacing");
+      dynamic_options.add_options()
+      ("d-save-other-timings",
+          po::value<bool>(&context.dynamic.save_other_timings)->default_value(false),
+          "If true, then the partitioner saves the timings of other parts of the algorithm, such as io and initial partitioning");
     return dynamic_options;
   }
 

mt-kahypar/partition/context.h

@@ -299,6 +299,16 @@ struct LocalFMRound {
     std::vector<Move> moves;
 };
 
+struct OtherTimings
+{
+  std::chrono::high_resolution_clock::duration total_time;
+  std::chrono::high_resolution_clock::duration strategy_time;
+  std::chrono::high_resolution_clock::duration setup_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;
+};
+
 struct DynamicParameters {
   std::string vcycle_algorithm = "kway_fm";
   size_t vcycle_num = 1;
@@ -333,6 +343,10 @@ struct DynamicParameters {
   HyperedgeWeight incremental_km1 = 0;
   LocalFMRound* local_fm_round = nullptr;
 
+  // other timings independent of strategy used
+  OtherTimings other_timings;
+  bool save_other_timings = false;
+
   // statistics
   std::int64_t km1_gain_vcycle = 0;
   std::chrono::high_resolution_clock::duration vcycle_duration_sum = std::chrono::high_resolution_clock::duration::zero();