High Level Trigger Timing Summary: hltTimingSummary

Introduction

hltTimingSummary is a utility designed to summarize timing information for trigger paths in a High Level Trigger configuration. By default, timing information is presented in wall clock time, but it is also possible to display results in CPU time.

IMPORTANT: The new version of the hltTimingSummary macro creates only a root file with the timing information. In order to avoid the long time that the former macro consumed (approx 50 min for a full study), the pdf creation is now performed with the timingPdfMaker.py script. With this new version, this process takes approx 15 min for a full study, but it is mainly the only change in the hltTimingSummary macro.

timingPdfMaker.py will be provided in HLTrigger/Tools/scripts in order to obtain some output pdf files. Different options of this script could help you to analyze this information in an easier way, otherwise summary plots are only available from the root file generated with hltTimingSummary. Usage information is provided here.

If you choose to check out HLTrigger/Tools (formerly DataFormats/HLTReco in releases < CMSSW_3_9_X) and compile your release with this package, you will create the hltTimingSummary executable at $CMSSW_BASE/bin/$SCRAM_ARCH/hltTimingSummary (formerly $CMSSW_BASE/test/$SCRAM_ARCH in releases < CMSSW_3_9_X). Otherwise, look for the executable at $CMSSW_RELEASE_BASE/bin/$SCRAM_ARCH/hltTimingSummary (formerly $CMSSW_RELEASE_BASE/test/$SCRAM_ARCH in releases < CMSSW_3_9_X).

Features of the hltTimingSummary macro

The hltTimingSummary macro has several features that should benefit the user:

• The input file is not required to reside on the local disk. For example, castor files may be analyzed using the standard rfio: syntax.
• The user has the option of producing a (short) text file summary of the macro. If this summary is produced, it will be include in the main pdf file produce with timingPdfMaker.py. Although this text file is not intended to replace the root output and pdf files create with timingPdfMaker.py, it includes some very useful summary information:
  • Average path time
  • Longest event time, slowest modules
  • List of modules skipped, etc.
• The user may redetermine path rejection factors by specifying a "filter" within the path. These filters are specified in the same fashion as the skipped modules.
• The user may specify not only the range of the timing histograms, but the user may now also specify the bin width of the histograms.

Using the macro

In order use the macro, HLTPerformanceInfo objects need to be available in your root input file. In order to achieve this, you will need to first perform a CPU-timing measurement. Please refer to the HLTCpuTimingInstructions for guidelines on how to do this using data and/or Monte Carlo simulations.

Some examples and more information with detailed explanations can be found in our HLTCpuTimingFAQ page.

Please note that in this version of the package (HLTrigger/Tools V00-00-03), the pdf creation process has been removed. Running hltTimingSummary as described below, will give you only a root file with the timing information. In order to obtain useful pdf files, please use timingPdfMaker as described here. It is highly recommend to use this version in order to avoid the long time that the regular former macro consumed (for releases < CMSSW_4_4_X). (Former macro takes approx 50 min for a full study, but this new version takes approx only 15 min).

This version differs from the former version (for releases < CMSSW_4_4_X) in these aspects: (a) it allows plotting the total time distribution for events that were accepted by the HLT and events that were rejected by the HLT, (b) Fixes a bug found when using the -r option, (c) adds the cumulative average module time for each path, (d) removes all former pdf capabilities in favor of a more efficient script.

Follow these instructions to get the latest stable version of the developing macro:

1. Setup your favorite CMSSW area.
2. Add the package HLTrigger/Tools from the release:

   cd $CMSSW_BASE/src/
   addpkg HLTrigger/Tools V00-00-03
      

1. Compile:

   scramv1 build
      

2. Execute hltTimingSummary macro using the executable $CMSSW_BASE/bin/$SCRAM_ARCH/hltTimingSummary. It can be used to parse the information contained in the output root file. For more information about this macro, please see its usage:

   Available options for hltTimingSummary:
     -h [ --help ]             Print this help message
     -i [ --infile ] arg       Input file name (Default is hlt.root)
     -o [ --outfile ] arg      Sets output files to <UserName>.root/
                               .txt (default is hltTimingSummary)
     -s [ --summary ]          Creates user-friendly timing summary file 
                               <UserName>-summary.txt.  See "-o" option for 
                               <UserName>
     -c [ --cpu ]              Results presented as CPU time (in msec).  Default 
                               is wall clock.
     -t [ --time ] arg         All relevant histogram time axes run from 0 to 
                               <UserValue> (in msec)
     -b [ --bin ] arg          Bin size (in msec) for relevant timing histograms, 
                               specified by the user
     -f [ --noFirst ]          Skip ANY event where a module is run for the first 
                               time (By default, run over all events)
     -y [ --logY ]             plot log scale y-axis for those plots that have 
                               events as entries
     -r [ --recalc ] arg       Recalculate rejection factor starting from 
                               specified list of filters/modules
     -e [ --excludeMod ] arg   Exclude a list of modules from the timing 
                               calculation
     -x [ --excludePath ] arg  Exclude a list of paths from the timing calculation
     -l [ --timelimit ] arg    Events where total time exceeds user-specified 
                               limit (in msec) listed in summary file
     -g [ --modPrint ] arg     Print event and run number of the user's input 
                               modules
     -a [ --pathlimit ] arg    Events where any path time exceeds user-specified 
                               limit (in msec) listed in summary file
     -m [ --modulelimit ] arg  Events where any module time exceeds user-specified
                               limit (in msec) listed in summary file
     -q [ --timeSpecific ] arg Overplots events with total time exceeds 
                               user-specified limit (in msec) for each pathTime: 
                               minTime,maxTimeAminTime,maxTimeA... 
                               Example:23,45A200,300
   
   Sample hltTimingSummary usage::
   "hltTimingSummary -t 50 -b 5 -r filter1" inputs hlt.root, outputs hltTimingsummary.root.
                            Timing histograms run from 0 to 50 msec with 5 msec bins.
                            Rejection factor recalculated for paths including filter1.
   "hltTimingSummary -i in.root -f -e exclude.txt -o out -s" inputs in.root, outputs out.root
                            and out-summary.txt.
                            Also skips events where modules are first run, and excludes 
                            the modules listed in exclude.txt from timing calculations.
   
   NOTE: To exclude files or use filters, the following formats are acceptable:
         - A comma-separated list of modules (e.g. "hltTimingSummary -e a,b,c")
         - A text file, where each excluded module appears on its own line
           (e.g. "hltTimingSummary -r file.txt")
   
   Examples of more advanced options:
   
   "hltTimingSummary -i in.root -o out -m 10 -g myModule -x myPath" inputs in.root, outputs out.root
                            and out-summary.txt.
                            Also prints out Run and Event numbers of events with at least one module
                            run more than 10 msec in out-summary.txt, and prints out the Run and 
                            Event numbers of events with the module, myModule, runs more than 10 msec, and 
                            exclude the path, myPath, from timing calculation.
   "hltTimingSummary -i in.root -o out -q 30,100A500,99999" inputs in.root, outputs out.root
                            and out-summary.txt.
                            Also plots 2 average path time plots: 
                            1) for events with total time ranged from 30 to 100 msec,
                            2) for events with total time ranged from 500 msec to infinity; and
                            plots stacked histograms for path time plots for each path with
                            colors corresponding to the colors in the average path time plots.
   
         

Using a root file (containing the necessary HLTPerformanceInfo information) as input, the hltTimingSummary tool outputs only a root file containing all summary histograms. Some pdf files would be created using the timingPdfMaker, it is highly recommended to use this macro to display these histograms in a more organized fashion.

A few notes:

• The --time option above is used to set the maximum time on the x-axis for timing histograms. By default the macro selects the timing range designed to contain all (or most) of the events. In some instances, a "slowest event" takes much more time than the average event. As a result, this event (and possibly a few other "very slow" events) may fall outside the default range. If you wish to include all events, or restrict the timing range further, this option allows you to do so. In all cases, overflow events are included when computing the histogram average value.
• In most (but not all) cases, the first time a module runs usually takes the longest time. With the -f option, every event where a module runs for the first time is removed from all timing plots. As an example, consider a path p = {a,b,c,d,e}. If modules a-c first run at event 1, but modules d and e don't run until event 100, then both event 1 and event 100 will be excluded from all timing plots.
• If you don't want to know the timing information for modules a,b in the above path, the -e option lets you exclude these modules from your timing plots. Including the option -e a,b (or alternatively, -e skip.txt where skip.txt is a two-line text file with a on line one, and b on line two) will skip modules a and b from timing calculations, and the timing plots will only consider modules c-e.
• If you want to calculate path success rate (or rejection) after a filter, you may use the -r option to redefine the "starting point" for the path. The results will be reflected in the pathRejection and pathSuccessFraction plots only. Module rejection factors will not be modified.
• By default, all plots are produced using wall clock time. If you would rather compute results using CPU time, include the --cpu option in the command line. CAUTION: CPU time resolution is on the order of several milliseconds. While this should have little to no impact on the summary plots, the event-by-event plots may look very different when compared to plots created using wall-clock time. Please keep this limitation in mind when looking at your results!

Generating useful pdf files: timingPdfMaker

The $CMSSW_RELEASE_BASE/src/HLTrigger/Tools/scripts/timingPdfMaker.py script (formerly CMSSW_RELEASE_BASE/src/HLTrigger/Tools/scripts/addBookmarks.csh) has been developed in order generate some pdf files that organize the plots that result from using the hltTimingSummary macro. The scrip is available in release >CMSSW_4_4_X. A description of the plots that are included in the pdf, please see below. If using an older release, please follow these instructions:

1. For releases < CMSSW_4_4_X:

   cvs co HLTrigger/Tools/scripts/timingPdfMaker.py
      

2. Find your root file generated with hltTimingSummary. Assuming that your root file (outputTiming.root) is located in $CMSSW_BASE/src:

   timingPdfMaker.py -i outputTiming.root [option]
      

   The script may be used as described below:

   'Usage: timingPdfMaker.py -i <file1> [option]'
   'e.g.:  timingPdfMaker.py -i outputTiming.root -t'
   'e.g.:  timingPdfMaker.py -i outputTiming.root -s HLT_Jet300_v5'
   
   -----Options-----
    -i          Input File.
    -o          Output File (Optional, otherwise it will take input file name).
    -t          For only main time info per event. It will take less than 1 min. 
    -p         For path time info. It will take approx 25 min.
    -m          For module time info. It will take approx 25 min.
    -s Path_Name            (For an specific path). It will take less than 1 min.
    For -p or -m option, the process needs like 200 Mb in disk space,
    but please dont be afraid. Before the process ends, all the temporal files
    will be erased.
      

Mainly, this script draws and saves plots from the root file created in the hltTimingSummary macro, organizes the information in a tex file, generates the pdf file and finally erases all temporary files created in previous steps. As described above, the script generates four kind of pdf files:

• Main Info: Containing totalTime plot, information printed in summary.txt file (if it was generated) and plots (moduleInPathTimeSummary, moduleInPathScaledTimeSummary, pathTime, incPathTime) for the 10 slowest paths.
• Paths Info: Containing moduleInPathTimeSummary, moduleInPathScaledTimeSummary, failedModule, pathTime and incPathTIme plots.
• Module Info: This option generates two pdfs: Time per event modules (-modules.pdf) containing moduleTime plots, and Running Time per event modules (-runningModules.pdf) containing moduleScaledTime plots.
• Specific Path Info: Containing totalTime plot, moduleInPathTimeSummary, moduleInPathScaledTimeSummary, pathTime, incPathTime for the Path specified and moduleInPathScaledTime for modules in the Path specified.

There are some plots (like moduleTimeSummary or pathTimeSummary) that are NOT included in any pdf file. Because of the length of the information displayed, it is almost imposible to show them in a size of a pdf paper with a correct visibility. Those plots are only available via root file (the output of the HLTTimingSummary macro). Please access them directly from such a file if you need that information

For a complete information of the plots, please see below.

Summary of the plots in hltTimingSummary root file and pdf files.

Some of these plots are not easy to describe in one line, and so a lengthier description of each plot is found below. All times are given in msec.

1. Summary of plots found in pdf files:
   • The cumulative time for all modules in the event are shown in the totalTime plot. This total time does not include any events or modules optionally skipped by the user.
   • The moduleInPathTimeSummary_pathName and moduleInPathScaledTimeSummary_pathName plots summarize module time and module running time as a function of the relevant path. Module "running" time does not include events when the module is not run (such as when it appears behind a filter), while the average module time includes all events. Consequently, events as described above, where a module does not run and thus has zero time, are included in module time, but not in module "running" time calculations.
   • The failedModule_pathName plots give path failure information as a function of module. In this fashion, you can determine which module is responsible for failure. The moduleInPathRejection_pathName plots give the module rejection factors for each path. We make use of red bins (thanks to moduleInPathRejectAll_pathName) to acknowledge modules that reject all events.
   • (pathTime_pathName) shows the cumulative time for each path (there is one plot per path). If only one path exists in the event, this plot should be an exact copy of the totalTime plot.
   • The incremental path timing plots (incPathTime_pathName) summarize the time spent that is unique to a particular path. Any module that appears in more than one path (presc4, according to the example) is not included in the result. Such a module will not be included in any path's time, so be careful!.
   • Module time per event (moduleTime_moduleName) give the timing information for each module. This includes events where the module did not run. To skip these events, and only consider events where the module ran (in the example on this page, the module presc3 only runs 250 times), you need to look at the moduleScaledTime_moduleName= plots.
   • The module timing plots in moduleInPathScaledTime_pathName_moduleName present module running time broken down according to path. (Note that there are no moduleInPathTime_pathName_moduleName plots, as these would essentially repeat the information included in the moduleInPathScaledTime_pathName_moduleName, adding only zero-time events when the module in question did not run in the path).
2. Summary of plots found only in the root file:
   • The pathTimeSummary and incPathTimeSummary plots summarize the average path time, and average incremental path time, over all events. Note that "incremental time" is the time due to modules not found in other paths. Given two paths p1 = {a,b} and p2 = {b,c}, the "pathTime" for p1 is given by a+b, while the "incremental path time" is from a alone.
   • The moduleTimeSummary and moduleScaledTimeSummary plots summarize the average module time, and average module running time, for all events.
   • The pathSuccessFraction plot summarizes the fraction (in %) of path success. The relative path success (pathVsPathSummary) plot summarizes path success relative to other paths. This 2D plot can be read as "For what fraction of path X successes does path Y also succeed?", where X/Y refer to the x/y-axis of the plot. If, for example, path p2 succeeds only 50% of the time, while path p1 never fails, then (x,y) = (p1,p2) will return 0.5, but (x,y) = (p2,p1) will be equal to 1.0. If there is only one path, the path vs. path summary is not included in the pdf file. If a path includes a filter specified by the user, the results of pathSuccessFraction will be recalculated, but no changes are made to pathVsPathSummary.
   • pathRejection essentially inverts the information presented in pathSuccessFraction. If A events enter the path and B events pass, pathSuccessFraction plots B/A and pathRejection plots A/B. NOTE: If a path rejects all events, pathRejection plots A (and not infinity). To avoid any confusion, paths with full rejection are plotted in red (this information is included in the root file as pathRejectAll).
   • The uniquePathSuccessFraction records the frequency the event passes based on only one path. In our example, in 50% of all events, p0 is the only successful path. This information is recorded on this plot (and this plot does not show up if there is only one path in the job).
   • The (moduleInPathRejectTime_pathName) plots calculate the module Rejection shown in previous plots divided by running time.

Review status

Responsible: Main.bdahmes
Last reviewed by: Most recent reviewer