From 08844351307638586aeff2b4a11443e2dfe93ac9 Mon Sep 17 00:00:00 2001
From: Giovanni La Mura <giovanni.lamura@inaf.it>
Date: Wed, 1 May 2024 19:32:50 +0200
Subject: [PATCH] Add timing messages for matrix calculation and inversion,
 together with angle grid

---
 src/cluster/cluster.cpp | 39 +++++++++++++++++++++++++++++++++------
 1 file changed, 33 insertions(+), 6 deletions(-)

diff --git a/src/cluster/cluster.cpp b/src/cluster/cluster.cpp
index e9f666b8..742cc6fd 100644
--- a/src/cluster/cluster.cpp
+++ b/src/cluster/cluster.cpp
@@ -178,6 +178,10 @@ void cluster(const string& config_file, const string& data_file, const string& o
       chrono::time_point<chrono::high_resolution_clock> start_iter_1 = chrono::high_resolution_clock::now();
       int jer = cluster_jxi488_cycle(jxi488, sconf, gconf, p_scattering_angles, cid, output, output_path, tppoan, logger);
       chrono::time_point<chrono::high_resolution_clock> end_iter_1 = chrono::high_resolution_clock::now();
+      elapsed = start_iter_1 - t_start;
+      message = "INFO: Calculation setup took " + to_string(elapsed.count()) + "s.\n";
+      logger->log(message);
+      time_logger->log(message);
       elapsed = end_iter_1 - start_iter_1;
       message = "INFO: First iteration took " + to_string(elapsed.count()) + "s.\n";
       logger->log(message);
@@ -231,7 +235,7 @@ void cluster(const string& config_file, const string& data_file, const string& o
 	}
 #pragma omp barrier
 	{
-	  message = "Closing thread-local output files of thread " + to_string(myompthread) + " and syncing threads.\n";
+	  message = "INFO: Closing thread-local output files of thread " + to_string(myompthread) + " and syncing threads.\n";
 	  logger->log(message);
 	}
       } // closes pragma omp parallel
@@ -243,7 +247,7 @@ void cluster(const string& config_file, const string& data_file, const string& o
 	  // Giovanni, please add here in this loop code to reopen the temporary files, reread them and append them respectively to the global output and tppoan, before closing them
 	  string partial_file_name = output_path + "/c_OCLU_" + to_string(ri);
 	  message = "Copying ASCII output of thread " + to_string(ri) + " of " + to_string(ompnumthreads - 1) + "... ";
-	  logger->log(message);
+	  logger->log(message, LOG_DEBG);
 	  FILE *partial_output = fopen(partial_file_name.c_str(), "r");
 	  char c = fgetc(partial_output);
 	  while (c != EOF) {
@@ -252,10 +256,10 @@ void cluster(const string& config_file, const string& data_file, const string& o
 	  }
 	  fclose(partial_output);
 	  remove(partial_file_name.c_str());
-	  logger->log("done.\n");
+	  logger->log("done.\n", LOG_DEBG);
 	  partial_file_name = output_path + "/c_TPPOAN_" + to_string(ri);
 	  message = "Copying binary output of thread " + to_string(ri) + " of " + to_string(ompnumthreads - 1) + "... ";
-	  logger->log(message);
+	  logger->log(message, LOG_DEBG);
 	  fstream partial_tppoan;
 	  partial_tppoan.open(partial_file_name.c_str(), ios::in | ios::binary);
 	  partial_tppoan.seekg(0, ios::end);
@@ -267,7 +271,7 @@ void cluster(const string& config_file, const string& data_file, const string& o
 	  partial_tppoan.close();
 	  delete[] binary_buffer;
 	  remove(partial_file_name.c_str());
-	  logger->log("done.\n");
+	  logger->log("done.\n", LOG_DEBG);
 	}
       }
 #endif
@@ -301,7 +305,10 @@ void cluster(const string& config_file, const string& data_file, const string& o
 int cluster_jxi488_cycle(int jxi488, ScattererConfiguration *sconf, GeometryConfiguration *gconf, ScatteringAngles *sa, ClusterIterationData *cid, FILE *output, const string& output_path, fstream& tppoan, Logger *logger)
 {
   int nxi = sconf->number_of_scales;
-  logger->log("INFO: running scale iteration " + to_string(jxi488) + " of " + to_string(nxi) + ".\n");
+  string message = "INFO: running scale iteration " + to_string(jxi488) + " of " + to_string(nxi) + ".\n";
+  logger->log(message);
+  chrono::duration<double> elapsed;
+  chrono::time_point<chrono::high_resolution_clock> interval_start, interval_end;
   int jer = 0;
   int lcalc = 0;
   int jaw = 1;
@@ -377,12 +384,23 @@ int cluster_jxi488_cycle(int jxi488, ScattererConfiguration *sconf, GeometryConf
       //break;
     }
   } // i132 loop
+  interval_start = chrono::high_resolution_clock::now();
   cms(cid->am, cid->c1, cid->c1ao, cid->c4, cid->c6);
+  interval_end = chrono::high_resolution_clock::now();
+  elapsed = interval_end - interval_start;
+  message = "INFO: matrix calculation for scale " + to_string(jxi488) + " took " + to_string(elapsed.count()) + "s.\n";
+  logger->log(message);
+  interval_start = chrono::high_resolution_clock::now();
   invert_matrix(cid->am, ndit, jer, mxndm);
+  interval_end = chrono::high_resolution_clock::now();
+  elapsed = interval_end - interval_start;
+  message = "INFO: matrix inversion for scale " + to_string(jxi488) + " took " + to_string(elapsed.count()) + "s.\n";
+  logger->log(message);
   if (jer != 0) {
     return jer;
     // break; // jxi488 loop: goes to memory clean
   }
+  interval_start = chrono::high_resolution_clock::now();
   ztm(cid->am, cid->c1, cid->c1ao, cid->c4, cid->c6, cid->c9);
   if (idfc >= 0) {
     if (jxi488 == jwtm) {
@@ -450,6 +468,11 @@ int cluster_jxi488_cycle(int jxi488, ScattererConfiguration *sconf, GeometryConf
   tppoan.write(reinterpret_cast<char *>(&(cid->vk)), sizeof(double));
   pcrsm0(cid->vk, exri, inpol, cid->c1, cid->c1ao, cid->c4);
   apcra(cid->zpv, cid->c4->le, cid->c1ao->am0m, inpol, sqk, cid->gapm, cid->gappm);
+  interval_end = chrono::high_resolution_clock::now();
+  elapsed = interval_end - interval_start;
+  message = "INFO: average calculation for scale " + to_string(jxi488) + " took " + to_string(elapsed.count()) + "s.\n";
+  logger->log(message);
+  interval_start = chrono::high_resolution_clock::now();
   double th = sa->th;
   for (int jth486 = 1; jth486 <= sa->nth; jth486++) { // OpenMP portable?
     double ph = sa->ph;
@@ -934,6 +957,10 @@ int cluster_jxi488_cycle(int jxi488, ScattererConfiguration *sconf, GeometryConf
     } // jph484 loop
     th += sa->thstp;
   } // jth486 loop
+  interval_end = chrono::high_resolution_clock::now();
+  elapsed = interval_end - interval_start;
+  message = "INFO: angle loop for scale " + to_string(jxi488) + " took " + to_string(elapsed.count()) + "s.\n";
+  logger->log(message);
   
   logger->log("INFO: finished scale iteration " + to_string(jxi488) + " of " + to_string(nxi) + ".\n");
 
-- 
GitLab