ITS: improve logging

Signed-off-by: Felix Schlepper <felix.schlepper@cern.ch>

Author: f3sch

Detectors/ITSMFT/ITS/tracking/include/ITStracking/Definitions.h

@@ -50,6 +50,19 @@ struct LogLogThrottler {
     return false;
   }
 };
+
+struct TimingStats {
+  std::uint64_t calls = 0;
+  double totalTimeMs = 0.;
+
+  void add(double timeMs)
+  {
+    ++calls;
+    totalTimeMs += timeMs;
+  }
+  double averageTimeMs() const { return calls ? totalTimeMs / static_cast<double>(calls) : 0.; }
+};
+
 } // namespace o2::its
 
-#endif
+#endif

Detectors/ITSMFT/ITS/tracking/include/ITStracking/Tracker.h

@@ -25,10 +25,12 @@
 #include <string_view>
 #include <utility>
 #include <sstream>
+#include <vector>
 
 #include <oneapi/tbb/task_arena.h>
 
 #include "ITStracking/Configuration.h"
+#include "ITStracking/Definitions.h"
 #include "ITStracking/TimeFrame.h"
 #include "ITStracking/TrackerTraits.h"
 #include "ITStracking/BoundedAllocator.h"
@@ -91,16 +93,18 @@ class Tracker
   double mTotalTime{0};
   std::shared_ptr<BoundedMemoryResource> mMemoryPool;
 
-  enum State {
+  enum Steps {
     TFInit = 0,
     Trackleting,
     Celling,
     Neighbouring,
     Roading,
-    NStates,
+    NSteps,
   };
-  State mCurState{TFInit};
-  static constexpr std::array<const char*, NStates> StateNames{"TimeFrame initialisation", "Tracklet finding", "Cell finding", "Neighbour finding", "Road finding"};
+  Steps mCurStep{TFInit};
+  static constexpr std::array<const char*, NSteps> StateNames{"TimeFrame initialisation", "Tracklet finding", "Cell finding", "Neighbour finding", "Road finding"};
+  std::vector<std::array<TimingStats, NSteps>> mTimingStats;
+  void addTimingStatCurStep(int iteration, double timeMs);
 };
 
 template <int NLayers>
@@ -125,22 +129,23 @@ float Tracker<NLayers>::evaluateTask(void (Tracker<NLayers>::*task)(T...), std::
     }
     logger(sstream.str());
 
-    if (mTrkParams[0].SaveTimeBenchmarks) {
+    if (mTrkParams[iteration].SaveTimeBenchmarks) {
       std::string taskNameStr(taskName);
       std::transform(taskNameStr.begin(), taskNameStr.end(), taskNameStr.begin(),
                      [](unsigned char c) { return std::tolower(c); });
       std::replace(taskNameStr.begin(), taskNameStr.end(), ' ', '_');
       if (std::ofstream file{"its_time_benchmarks.txt", std::ios::app}) {
         file << "trk:" << iteration << '\t' << taskNameStr << '\t' << diff << '\n';
       }
+      addTimingStatCurStep(iteration, diff);
     }
 
   } else {
     (this->*task)(std::forward<F>(args)...);
   }
 
   if (mTrkParams[iteration].PrintMemory) {
-    LOGP(info, "iter:{}:{}: {}", iteration, StateNames[mCurState], mMemoryPool->asString());
+    LOGP(info, "iter:{}:{}: {}", iteration, StateNames[mCurStep], mMemoryPool->asString());
   }
 
   return diff;

Detectors/ITSMFT/ITS/tracking/include/ITStracking/Vertexer.h

@@ -22,11 +22,11 @@
 #include <array>
 #include <iosfwd>
 #include <memory>
+#include <vector>
 
 #include <oneapi/tbb/task_arena.h>
 
 #include "ITStracking/Constants.h"
-#include "ITStracking/Definitions.h"
 #include "ITStracking/Configuration.h"
 #include "ITStracking/TimeFrame.h"
 #include "ITStracking/VertexerTraits.h"
@@ -56,6 +56,7 @@ class Vertexer
 
   float clustersToVertices(LogFunc = [](const std::string& s) { std::cout << s << '\n'; });
   void filterMCTracklets();
+  void printSummary() const;
 
   template <typename... T>
   void findTracklets(T&&... args)
@@ -90,9 +91,9 @@ class Vertexer
   float evaluateTask(void (Vertexer::*task)(T...), std::string_view taskName, int iteration, LogFunc& logger, T&&... args);
 
   void printEpilog(LogFunc& logger,
-                   const unsigned int trackletN01, const unsigned int trackletN12,
-                   const unsigned selectedN, const unsigned int vertexN, const unsigned int totalVertexN,
-                   const float trackletT, const float selecT, const float vertexT);
+                   unsigned int trackletN01, unsigned int trackletN12,
+                   unsigned selectedN, unsigned int vertexN, unsigned int totalVertexN,
+                   float initT, float trackletT, float selecT, float vertexT);
 
   void setNThreads(int n, std::shared_ptr<tbb::task_arena>& arena) { mTraits->setNThreads(n, arena); }
 
@@ -105,16 +106,18 @@ class Vertexer
   std::vector<VertexingParameters> mVertParams;
   std::shared_ptr<BoundedMemoryResource> mMemoryPool;
 
-  enum State {
+  enum Steps {
     Init = 0,
     Trackleting,
-    Validating,
+    Selection,
     Finding,
     TruthSeeding,
-    NStates,
+    NSteps,
   };
-  State mCurState{Init};
-  static constexpr std::array<const char*, NStates> StateNames{"Initialisation", "Tracklet finding", "Tracklet validation", "Vertex finding", "Truth seeding"};
+  Steps mCurStep{Init};
+  static constexpr std::array<const char*, NSteps> StateNames{"Initialisation", "Tracklet finding", "Tracklet selection", "Vertex finding", "Truth seeding"};
+  std::vector<std::array<TimingStats, NSteps>> mTimingStats;
+  void addTimingStatCurStep(int iteration, double timeMs);
 };
 
 template <int NLayers>
@@ -139,21 +142,22 @@ float Vertexer<NLayers>::evaluateTask(void (Vertexer<NLayers>::*task)(T...), std
     }
     logger(sstream.str());
 
-    if (mVertParams[0].SaveTimeBenchmarks) {
+    if (mVertParams[iteration].SaveTimeBenchmarks) {
       std::string taskNameStr(taskName);
       std::transform(taskNameStr.begin(), taskNameStr.end(), taskNameStr.begin(),
                      [](unsigned char c) { return std::tolower(c); });
       std::replace(taskNameStr.begin(), taskNameStr.end(), ' ', '_');
       if (std::ofstream file{"its_time_benchmarks.txt", std::ios::app}) {
         file << "vtx:" << iteration << '\t' << taskNameStr << '\t' << diff << '\n';
       }
+      addTimingStatCurStep(iteration, diff);
     }
   } else {
     (this->*task)(std::forward<T>(args)...);
   }
 
   if (mVertParams[iteration].PrintMemory) {
-    LOGP(info, "iter:{}:{}: {}", iteration, StateNames[mCurState], mMemoryPool->asString());
+    LOGP(info, "iter:{}:{}: {}", iteration, StateNames[mCurStep], mMemoryPool->asString());
   }
 
   return diff;

Detectors/ITSMFT/ITS/tracking/src/Tracker.cxx

@@ -49,7 +49,7 @@ float Tracker<NLayers>::clustersToTracks(const LogFunc& logger, const LogFunc& e
   int iteration{0}, iVertex{0};
   auto handleException = [&](const auto& err) {
     LOGP(error, "Too much memory in {} in iteration {} iVtx={}: {:.2f} GB. Current limit is {:.2f} GB, check the detector status and/or the selections.",
-         StateNames[mCurState], iteration, iVertex,
+         StateNames[mCurStep], iteration, iVertex,
          (double)mTimeFrame->getArtefactsMemory() / GB,
          (double)mTrkParams[iteration].MaxMemory / GB);
     if (typeid(err) != typeid(std::bad_alloc)) { // only print if the exceptions is different from what is expected
@@ -76,16 +76,16 @@ float Tracker<NLayers>::clustersToTracks(const LogFunc& logger, const LogFunc& e
       int nTracks{-static_cast<int>(mTimeFrame->getNumberOfTracks())};
       iVertex = std::min(maxNvertices, 0);
       logger(std::format("==== ITS {} Tracking iteration {} summary ====", mTraits->getName(), iteration));
-      total += timeFrame = evaluateTask(&Tracker::initialiseTimeFrame, StateNames[mCurState = TFInit], iteration, evalLog, iteration);
+      total += timeFrame = evaluateTask(&Tracker::initialiseTimeFrame, StateNames[mCurStep = TFInit], iteration, evalLog, iteration);
       logger(std::format(" - TimeFrame initialisation completed in {:.2f} ms", timeFrame));
       do {
-        timeTracklets += evaluateTask(&Tracker::computeTracklets, StateNames[mCurState = Trackleting], iteration, evalLog, iteration, iVertex);
+        timeTracklets += evaluateTask(&Tracker::computeTracklets, StateNames[mCurStep = Trackleting], iteration, evalLog, iteration, iVertex);
         nTracklets += mTraits->getTFNumberOfTracklets();
-        timeCells += evaluateTask(&Tracker::computeCells, StateNames[mCurState = Celling], iteration, evalLog, iteration);
+        timeCells += evaluateTask(&Tracker::computeCells, StateNames[mCurStep = Celling], iteration, evalLog, iteration);
         nCells += mTraits->getTFNumberOfCells();
-        timeNeighbours += evaluateTask(&Tracker::findCellsNeighbours, StateNames[mCurState = Neighbouring], iteration, evalLog, iteration);
+        timeNeighbours += evaluateTask(&Tracker::findCellsNeighbours, StateNames[mCurStep = Neighbouring], iteration, evalLog, iteration);
         nNeighbours += mTimeFrame->getNumberOfNeighbours();
-        timeRoads += evaluateTask(&Tracker::findRoads, StateNames[mCurState = Roading], iteration, evalLog, iteration);
+        timeRoads += evaluateTask(&Tracker::findRoads, StateNames[mCurStep = Roading], iteration, evalLog, iteration);
       } while (++iVertex < maxNvertices);
       logger(std::format(" - Tracklet finding: {} tracklets found in {:.2f} ms", nTracklets, timeTracklets));
       logger(std::format(" - Cell finding: {} cells found in {:.2f} ms", nCells, timeCells));
@@ -229,12 +229,33 @@ void Tracker<NLayers>::adoptTimeFrame(TimeFrame<NLayers>& tf)
   mTraits->adoptTimeFrame(&tf);
 }
 
+template <int NLayers>
+void Tracker<NLayers>::addTimingStatCurStep(int iteration, double timeMs)
+{
+  if (iteration < 0) {
+    return;
+  }
+  if (mTimingStats.size() < (iteration + 1)) {
+    mTimingStats.resize(iteration + 1);
+  }
+  mTimingStats[iteration][mCurStep].add(timeMs);
+}
+
 template <int NLayers>
 void Tracker<NLayers>::printSummary() const
 {
   auto avgTF = mTotalTime * 1.e-3 / ((mTimeFrameCounter > 0) ? (double)mTimeFrameCounter : -1.0);
   auto avgTFwithDropped = mTotalTime * 1.e-3 / (((mTimeFrameCounter + mNumberOfDroppedTFs) > 0) ? (double)(mTimeFrameCounter + mNumberOfDroppedTFs) : -1.0);
   LOGP(info, "Tracker summary: Processed {} TFs (dropped {}) in TOT={:.2f} s, AVG/TF={:.2f} ({:.2f}) s", mTimeFrameCounter, mNumberOfDroppedTFs, mTotalTime * 1.e-3, avgTF, avgTFwithDropped);
+  for (size_t iteration = 0; iteration < mTimingStats.size(); ++iteration) {
+    for (size_t state = 0; state < NSteps; ++state) {
+      const auto& stats = mTimingStats[iteration][state];
+      if (!stats.calls) {
+        continue;
+      }
+      LOGP(info, " - iter {} {}: calls={} total={:.2f} ms avg={:.2f} ms", iteration, StateNames[state], stats.calls, stats.totalTimeMs, stats.averageTimeMs());
+    }
+  }
 }
 
 template class Tracker<7>;

Detectors/ITSMFT/ITS/tracking/src/TrackingInterface.cxx

@@ -457,6 +457,7 @@ void ITSTrackingInterface::finaliseCCDB(ConcreteDataMatcher& matcher, void* obj)
 
 void ITSTrackingInterface::printSummary() const
 {
+  mVertexer->printSummary();
   mTracker->printSummary();
 }
 

Detectors/ITSMFT/ITS/tracking/src/Vertexer.cxx

@@ -15,11 +15,6 @@
 
 #include "ITStracking/Vertexer.h"
 #include "ITStracking/BoundedAllocator.h"
-#include "ITStracking/Cluster.h"
-
-#include "ITStracking/ClusterLines.h"
-#include "ITStracking/Tracklet.h"
-#include "ITStracking/IndexTableUtils.h"
 #include "ITStracking/VertexerTraits.h"
 #include "ITStracking/TrackingConfigParam.h"
 
@@ -41,16 +36,17 @@ float Vertexer<NLayers>::clustersToVertices(LogFunc logger)
   LogFunc evalLog = [](const std::string&) {};
 
   if (mTimeFrame->hasMCinformation() && mVertParams[0].useTruthSeeding) {
-    float t = evaluateTask(&Vertexer::addTruthSeeds, StateNames[mCurState = TruthSeeding], 0, evalLog);
+    float t = evaluateTask(&Vertexer::addTruthSeeds, StateNames[mCurStep = TruthSeeding], 0, evalLog);
     sortVertices();
+    ++mTimeFrameCounter;
     return t;
   }
 
   TrackingParameters trkPars;
   mTraits->updateVertexingParameters(mVertParams);
 
   auto handleException = [&](const auto& err) {
-    LOGP(error, "Encountered critical error in step {}, stopping further processing of this TF: {}", StateNames[mCurState], err.what());
+    LOGP(error, "Encountered critical error in step {}, stopping further processing of this TF: {}", StateNames[mCurStep], err.what());
     if (!mVertParams[0].DropTFUponFailure) {
       throw err;
     } else {
@@ -59,22 +55,23 @@ float Vertexer<NLayers>::clustersToVertices(LogFunc logger)
   };
 
   float timeTracklet{0.f}, timeSelection{0.f}, timeVertexing{0.f}, timeInit{0.f};
+  bool completed = false;
   try {
     for (int iteration = 0; iteration < (int)mVertParams.size(); ++iteration) {
       mMemoryPool->setMaxMemory(mVertParams[iteration].MaxMemory);
       unsigned int nTracklets01{0}, nTracklets12{0};
       logger(fmt::format("=== ITS {} Seeding vertexer iteration {} summary:", mTraits->getName(), iteration));
       trkPars.PhiBins = mTraits->getVertexingParameters()[0].PhiBins;
       trkPars.ZBins = mTraits->getVertexingParameters()[0].ZBins;
-      auto timeInitIteration = evaluateTask(&Vertexer::initialiseVertexer, StateNames[mCurState = Init], iteration, evalLog, trkPars, iteration);
-      auto timeTrackletIteration = evaluateTask(&Vertexer::findTracklets, StateNames[mCurState = Trackleting], iteration, evalLog, iteration);
+      auto timeInitIteration = evaluateTask(&Vertexer::initialiseVertexer, StateNames[mCurStep = Init], iteration, evalLog, trkPars, iteration);
+      auto timeTrackletIteration = evaluateTask(&Vertexer::findTracklets, StateNames[mCurStep = Trackleting], iteration, evalLog, iteration);
       nTracklets01 = mTimeFrame->getTotalTrackletsTF(0);
       nTracklets12 = mTimeFrame->getTotalTrackletsTF(1);
-      auto timeSelectionIteration = evaluateTask(&Vertexer::validateTracklets, StateNames[mCurState = Validating], iteration, evalLog, iteration);
+      auto timeSelectionIteration = evaluateTask(&Vertexer::validateTracklets, StateNames[mCurStep = Selection], iteration, evalLog, iteration);
       const auto nVerticesBefore = mTimeFrame->getPrimaryVertices().size();
-      auto timeVertexingIteration = evaluateTask(&Vertexer::findVertices, StateNames[mCurState = Finding], iteration, evalLog, iteration);
+      auto timeVertexingIteration = evaluateTask(&Vertexer::findVertices, StateNames[mCurStep = Finding], iteration, evalLog, iteration);
       const auto nVerticesAfter = mTimeFrame->getPrimaryVertices().size();
-      printEpilog(logger, nTracklets01, nTracklets12, mTimeFrame->getNLinesTotal(), nVerticesAfter - nVerticesBefore, nVerticesAfter, timeTrackletIteration, timeSelectionIteration, timeVertexingIteration);
+      printEpilog(logger, nTracklets01, nTracklets12, mTimeFrame->getNLinesTotal(), nVerticesAfter - nVerticesBefore, nVerticesAfter, timeInitIteration, timeTrackletIteration, timeSelectionIteration, timeVertexingIteration);
       timeInit += timeInitIteration;
       timeTracklet += timeTrackletIteration;
       timeSelection += timeSelectionIteration;
@@ -84,6 +81,7 @@ float Vertexer<NLayers>::clustersToVertices(LogFunc logger)
       sortVertices();
       mTimeFrame->updateROFVertexLookupTable();
     }
+    completed = true;
   } catch (const BoundedMemoryResource::MemoryLimitExceeded& err) {
     handleException(err);
   } catch (const std::bad_alloc& err) {
@@ -92,6 +90,10 @@ float Vertexer<NLayers>::clustersToVertices(LogFunc logger)
     LOGP(fatal, "Uncaught exception!");
   }
 
+  if (completed) {
+    ++mTimeFrameCounter;
+  }
+
   return timeInit + timeTracklet + timeSelection + timeVertexing;
 }
 
@@ -135,15 +137,43 @@ void Vertexer<NLayers>::adoptTimeFrame(TimeFrameN& tf)
   mTraits->adoptTimeFrame(&tf);
 }
 
+template <int NLayers>
+void Vertexer<NLayers>::addTimingStatCurStep(int iteration, double timeMs)
+{
+  if (iteration < 0) {
+    return;
+  }
+  if (mTimingStats.size() < (iteration + 1)) {
+    mTimingStats.resize(iteration + 1);
+  }
+  mTimingStats[iteration][mCurStep].add(timeMs);
+}
+
+template <int NLayers>
+void Vertexer<NLayers>::printSummary() const
+{
+  LOGP(info, "Vertexer summary: Processed {} TFs", mTimeFrameCounter);
+  for (size_t iteration = 0; iteration < mTimingStats.size(); ++iteration) {
+    for (size_t state = 0; state < NSteps; ++state) {
+      const auto& stats = mTimingStats[iteration][state];
+      if (!stats.calls) {
+        continue;
+      }
+      LOGP(info, " - iter {} {}: calls={} total={:.2f} ms avg={:.2f} ms", iteration, StateNames[state], stats.calls, stats.totalTimeMs, stats.averageTimeMs());
+    }
+  }
+}
+
 template <int NLayers>
 void Vertexer<NLayers>::printEpilog(LogFunc& logger,
-                                    const unsigned int trackletN01, const unsigned int trackletN12,
-                                    const unsigned selectedN, const unsigned int vertexN, const unsigned int totalVertexN,
-                                    const float trackletT, const float selecT, const float vertexT)
+                                    unsigned int trackletN01, unsigned int trackletN12,
+                                    unsigned selectedN, unsigned int vertexN, unsigned int totalVertexN,
+                                    float initT, float trackletT, float selecT, float vertexT)
 {
-  logger(fmt::format(" - {} Vertexer: found {} | {} tracklets in: {:.2f} ms", mTraits->getName(), trackletN01, trackletN12, trackletT));
-  logger(fmt::format(" - {} Vertexer: selected {} tracklets in: {:.2f} ms", mTraits->getName(), selectedN, selecT));
-  logger(fmt::format(" - {} Vertexer: found {} vertices (total: {}) in: {:.2f} ms", mTraits->getName(), vertexN, totalVertexN, vertexT));
+  logger(fmt::format(" - {}: completed in {:.2f} ms", StateNames[Init], initT));
+  logger(fmt::format(" - {}: found {} | {} tracklets in {:.2f} ms", StateNames[Trackleting], trackletN01, trackletN12, trackletT));
+  logger(fmt::format(" - {}: selected {} tracklets in {:.2f} ms", StateNames[Selection], selectedN, selecT));
+  logger(fmt::format(" - {}: found {} vertices (total {}) in {:.2f} ms", StateNames[Finding], vertexN, totalVertexN, vertexT));
 }
 
 template class Vertexer<7>;

Detectors/ITSMFT/ITS/workflow/src/TrackerSpec.cxx

@@ -85,8 +85,11 @@ void TrackerDPL::endOfStream(EndOfStreamContext& ec)
 
 void TrackerDPL::end()
 {
-  mITSTrackingInterface.printSummary();
-  LOGF(info, "ITS CA-Tracker total timing: Cpu: %.3e Real: %.3e s in %d slots", mTimer.CpuTime(), mTimer.RealTime(), mTimer.Counter() - 1);
+  if (static bool printOnce{false}; !printOnce) {
+    printOnce = true;
+    mITSTrackingInterface.printSummary();
+    LOGF(info, "ITS CA-Tracker total timing: Cpu: %.3e Real: %.3e s in %d slots", mTimer.CpuTime(), mTimer.RealTime(), mTimer.Counter() - 1);
+  }
 }
 
 DataProcessorSpec getTrackerSpec(bool useMC, bool doStag, bool useGeom, int trgType, TrackingMode::Type trMode, const bool overrBeamEst, o2::gpu::gpudatatypes::DeviceType dType)