Getting algorithm run time information

It might be interesting to know in which algorithms the most time is spent in a workflow. This can be achieved with builtin Gaudi services, and auditors, specifically using either the TimelineSvc and/or the AlgTimingAuditor depending on the desired level of detail.

AlgTimingAuditor

The AlgTimingAuditor in combination with the AuditorSvc allow to easily get an overview over the execution time of a workflow and in which algorithms, services or tools time is spent. In order to configure it, you need to simply do the following

from Configurables import AuditorSvc, AlgTimingAuditor, EventDataSvc
from k4FWCore import ApplicationMgr

# List of your algorithms that you want to run
algList = []

# setup the AuditorSvc and add the AlgTimingAuditor to it
auditorSvc = AuditorSvc
auditorSvc.Auditors = [AlgTimingAuditor()]

appMgr = ApplicationMgr(
    TopAlg=algList,
    EvtSel="NONE",
    ExtSvc=[EventDataSvc("EventDataSvc", auditorSvc)]
)

This will result in an output similar to this one

AlgTimingAuditor     INFO -------------------------------------------------------------------
AlgTimingAuditor     INFO Algorithm                      | exec (ms) |   count   | total (s)
AlgTimingAuditor     INFO -------------------------------------------------------------------
AlgTimingAuditor     INFO EVENT LOOP                     |      7210 |         3 |     21.63
AlgTimingAuditor     INFO -------------------------------------------------------------------

Per Algorithm timing

In order to enable a more detailed output and auditing, it is necessary to enable them via

appMgr.AuditAlgorithms = True
appMgr.AuditTools = True
appMgr.AuditServices = True

This will result in output like

AlgTimingAuditor     INFO -------------------------------------------------------------------
AlgTimingAuditor     INFO Algorithm                      | exec (ms) |   count   | total (s)
AlgTimingAuditor     INFO -------------------------------------------------------------------
AlgTimingAuditor     INFO                                |         0 |         0 |         0
AlgTimingAuditor     INFO IncidentSvc                    |         0 |         0 |         0
AlgTimingAuditor     INFO EventPersistencySvc            |         0 |         0 |         0
AlgTimingAuditor     INFO                                |         0 |         0 |         0
AlgTimingAuditor     INFO                                |         0 |         0 |         0
AlgTimingAuditor     INFO                                |         0 |         0 |         0
AlgTimingAuditor     INFO Gaudi::Utils::SignalMonitorSvc |         0 |         0 |         0
AlgTimingAuditor     INFO                                |         0 |         0 |         0
AlgTimingAuditor     INFO TimelineSvc                    |         0 |         0 |         0
AlgTimingAuditor     INFO PodioInput                     |     67.34 |         3 |     0.202
AlgTimingAuditor     INFO AlgExecStateSvc                |         0 |         0 |         0
AlgTimingAuditor     INFO MyAIDAProcessor                |     56.44 |         3 |    0.1693
AlgTimingAuditor     INFO  RndmGenSvc                    |         0 |         0 |         0
AlgTimingAuditor     INFO   RndmGenSvc.Engine            |         0 |         0 |         0
AlgTimingAuditor     INFO ToolSvc                        |         0 |         0 |         0
AlgTimingAuditor     INFO ToolSvc.InputConversion        |         0 |         0 |         0
AlgTimingAuditor     INFO MyStatusmonitor                |   0.02489 |         3 | 7.467e-05
AlgTimingAuditor     INFO MySplitCollectionByLayer       |   0.04234 |         3 |  0.000127
AlgTimingAuditor     INFO VXDPlanarDigiProcessor_CMOSVXD |    0.5061 |         3 |  0.001518
AlgTimingAuditor     INFO SITPlanarDigiProcessor         |    0.4672 |         3 |  0.001402
AlgTimingAuditor     INFO EDM4hepOutput                  |     97.03 |         3 |    0.2911
AlgTimingAuditor     INFO HistogramDataSvc               |         0 |         0 |         0
AlgTimingAuditor     INFO  HistogramPersistencySvc       |         0 |         0 |         0
AlgTimingAuditor     INFO -------------------------------------------------------------------

TimelineSvc

Using the TimelineSvc it is possible to get the exact start and end times for each algorithm and event. It’s output can be used for very detailed analysis later. It can be configured as

from Configurables import TimelineSvc, EventDataSvc
from k4FWCore import ApplicationMgr

# List of your algorithms that you want to run
algList = []

timelineSvc = TimelineSvc(RecordTimeline=True, DumpTimeline=True, TimelineFile="timeline.csv")

appMgr = ApplicationMgr(
    TopAlg=algList,
    EvtSel="NONE",
    ExtSvc=[EventDataSvc("EventDataSvc", timelineSvc)]
)

This will create timelines.csv file that looks similar to

#start end algorithm thread slot event
1745848335520532076 1745848335574872001 PodioInput 135806878369600 0 0
1745848335574879058 1745848335631430347 MyAIDAProcessor 135806878369600 0 0
1745848335631436925 1745848335631466797 MyStatusmonitor 135806878369600 0 0
1745848335631467617 1745848335631525405 MySplitCollectionByLayer 135806878369600 0 0
1745848335631526275 1745848335632537227 VXDPlanarDigiProcessor_CMOSVXD5 135806878369600 0 0
1745848335632538493 1745848335633010729 SITPlanarDigiProcessor 135806878369600 0 0
1745848335633012309 1745848335633141450 FTDPixelPlanarDigiProcessor 135806878369600 0 0
1745848335633142527 1745848335633573502 FTDStripPlanarDigiProcessor 135806878369600 0 0
1745848335633574995 1745848335634521760 FTDDDSpacePointBuilder 135806878369600 0 0

each line has

• the start time of the algorithm in nanoseconds

• the end time of the algorithm in nanoseconds

• the algorithm name

• the thread-id

• the (thread) slot in which the event was processed in Gaudi

• the event number

Note

The event number is a sequential number inside Gaudi and does not necessarily correspond with the event number that can be obtained from the EventHeader

Visualization using hivetimeline.py

The hivetimeline.py tool that comes with Gaudi can be used to visualize the output of the TimelineSvc. It has some limitations, e.g. the number of algorithms it supports for visualization, but it might be useful to have a first quick look.