Detailed timing per event

[CouthuresJeremy]

Hello, would it be possible to get the detailed timing per event for each algorithm instead of the total? @stephenswat @LuisFelipeCoelho

[paulgessinger]

Did you check timing.tsv that gets written when you run Sequencer?

[CouthuresJeremy]

Yes, below is an example of a timing.tsv file that I have for 100 events. What we can see is that time_perevent_s seems to correspond to time_total_s / 100.

identifier  time_total_s    time_perevent_s
Reader:EventGenerator   13.37   0.1337
Algorithm:ParticleSelector  0.0765  0.000765
Algorithm:FatrasSimulation  10.89   0.1089
Algorithm:DigitizationAlgorithm 2.348   0.02348
Algorithm:TruthSeedSelector 0.2225  0.002225
Algorithm:SpacePointMaker   0.2502  0.002502
Algorithm:SeedingAlgorithm  4.107   0.04107
Algorithm:TrackParamsEstimationAlgorithm    2.422   0.02422
Algorithm:TrackFindingAlgorithm 1033    10.33

What I would like to have is something like:

identifier  event   time_perevent_s
Algorithm:ParticleSelector  1   0.000768
Algorithm:ParticleSelector  2   0.000767
Algorithm:ParticleSelector  3   0.000762
...
Algorithm:ParticleSelector  99  0.000759
Algorithm:ParticleSelector  100 0.000764
Algorithm:FatrasSimulation  1   0.1083
Algorithm:FatrasSimulation  2   0.1094
Algorithm:FatrasSimulation  3   0.1085
...
Algorithm:FatrasSimulation  100 0.1102

This would allow to plot timing performance as a function of event-specific quantities.

[paulgessinger]

Ok got it. We could make the Sequencer produce such a format, but I think it should be off by default, as it might produce very large files.

Would you be willing to add this functionality @CouthuresJeremy?

[CouthuresJeremy]

Ok got it. We could make the Sequencer produce such a format, but I think it should be off by default, as it might produce very large files.

Yes, it would be better off by default.

Would you be willing to add this functionality @CouthuresJeremy?

After a look at the Sequencer.cpp, I honestly don't know how to implement that. https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/src/Framework/Sequencer.cpp#L1

[stale[bot]]

This issue/PR has been automatically marked as stale because it has not had recent activity. The stale label will be removed if any interaction occurs.

[CouthuresJeremy]

Using ChatGPT, I managed to get something working: in the Sequencer.cpp a new struct is defined:

// struct to store timing data
struct EventTimingInfo {
  std::string identifier;
  double time_s = 0;
  int eventId;
  DFE_NAMEDTUPLE(EventTimingInfo, identifier, time_s, eventId);
};

https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/src/Framework/Sequencer.cpp#L235

at the beginning of the Sequencer::run(), the following variable is declared: std::vector<EventTimingInfo> eventTimingData; https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/src/Framework/Sequencer.cpp#L258

inside the loop for each event, just before the nProcessedEvents++; line, the following code is added:

            if(m_cfg.enableEventTiming) {
              // Collect the event timing data
              for (size_t i = 0; i < names.size(); i++) {
                EventTimingInfo eventInfo;
                eventInfo.identifier = names[i];
                eventInfo.time_s = std::chrono::duration_cast<Seconds>(localClocksAlgorithms[i]).count();
                eventInfo.eventId = event;
                eventTimingData.push_back(eventInfo);
              }
            }

https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/src/Framework/Sequencer.cpp#L355

at the end of the Sequencer::run(), the following lines are added:

if(m_cfg.enableEventTiming) {
    // Write the data to a file
    std::string eventTimingPath = joinPaths(m_cfg.outputDir, "event_timing.tsv");
    dfe::NamedTupleTsvWriter<EventTimingInfo> eventTimingWriter(eventTimingPath, 4);
    for (EventTimingInfo info : eventTimingData) {
      eventTimingWriter.append(info);
    }
  }

https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/src/Framework/Sequencer.cpp#L411

in the config of the Sequencer.hpp:

// Enable or disable detailed per event timing writing
bool enableEventTiming = false;

https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Framework/include/ActsExamples/Framework/Sequencer.hpp#L51

and in the Examples/Python/src/ModuleEntry.cpp, the following line is added at the end of the sequencer config: .def_readwrite("enableEventTiming", &Config::enableEventTiming) https://github.com/acts-project/acts/blob/d6f93fa9c2100ef5315e20684ce24c7d2798cedd/Examples/Python/src/ModuleEntry.cpp#L221

[stale[bot]]

This issue/PR has been automatically marked as stale because it has not had recent activity. The stale label will be removed if any interaction occurs.

[paulgessinger]

Coming back to this, do we want to complete this @CouthuresJeremy?

[CouthuresJeremy]

It seems good to help monitoring algorithm performance.

Here is a plot that I made using this detailed timing per event: It corresponds to 100 events at < mu > = 50. What do you think of it @paulgessinger?

[stale[bot]]

This issue/PR has been automatically marked as stale because it has not had recent activity. The stale label will be removed if any interaction occurs.

[LuisFelipeCoelho]

@CouthuresJeremy can you open a PR with your implementation?

[github-actions[bot]]

This issue/PR has been automatically marked as stale because it has not had recent activity. The stale label will be removed if any interaction occurs.