Long startup time for simplest workflows

[felicepantaleo]

Developing reconstruction algorithms for Phase-2 is becoming more and more difficult and frustrating as CMSSW startup times have increased in the last few years.
This is what happens when we want to reconstruct 10 events of a single charged pion shot in front of HGCAL with a single thread.
The workflow is 24896.0_CloseByPGun_CE_E_Front_120um+2026D98 using CMSSW_13_2_0_pre3
It takes 4.5 minutes to launch the job, 30 seconds to reconstruct 10 events with a single thread.
Reducing the startup time would reduce drastically the number of coffees we have every day while increasing morale.

$ date && cmsRun step3_RAW2DIGI_RECO_RECOSIM_PAT_VALIDATION_DQM.py 
**Don Okt 19 10:55:37 CEST 2023**
19-Oct-2023 10:57:51 CEST  Initiating request to open file file:step2_16065463_0.root
19-Oct-2023 10:58:06 CEST  Successfully opened file file:step2_16065463_0.root
2023-10-19 10:58:48.203903: I tensorflow/core/platform/cpu_feature_guard.cc:142] This TensorFlow binary is optimized with oneAPI Deep Neural Network Library (oneDNN) to use the following CPU instructions in performance-critical operations:  SSE4.1 SSE4.2 AVX AVX2 AVX512F FMA
To enable them in other operations, rebuild TensorFlow with the appropriate compiler flags.
Begin processing the 1st record. Run 1, Event 1, LumiSection 1 on stream 0 at 19-Oct-2023 11:00:50.708 CEST
%MSG-w UndefinedPartonMode:  HadronAndPartonSelector:selectedHadronsAndPartons  19-Oct-2023 11:00:52 CEST Run: 1 Event: 1
Could not automatically determine the hadronizer type and set the correct parton selection mode. Parton-based jet flavour will not be defined.
%MSG
#--------------------------------------------------------------------------
#                         FastJet release 3.4.1
#                 M. Cacciari, G.P. Salam and G. Soyez                  
#     A software package for jet finding and analysis at colliders      
#                           http://fastjet.fr                           
#                                                                             
# Please cite EPJC72(2012)1896 [arXiv:1111.6097] if you use this package
# for scientific work and optionally PLB641(2006)57 [hep-ph/0512210].   
#                                                                       
# FastJet is provided without warranty under the GNU GPL v2 or higher.  
# It uses T. Chan's closest pair algorithm, S. Fortune's Voronoi code
# and 3rd party plugin jet algorithms. See COPYING file for details.
#--------------------------------------------------------------------------
%MSG-w UndefinedPartonMode:  HadronAndPartonSelector:patJetPartons  19-Oct-2023 11:00:52 CEST Run: 1 Event: 1
Could not automatically determine the hadronizer type and set the correct parton selection mode. Parton-based jet flavour will not be defined.
%MSG
%MSG-w UndefinedPartonMode:   HadronAndPartonSelector:selectedHadronsAndPartonsForGenJetsFlavourInfos  19-Oct-2023 11:01:05 CEST Run: 1 Event: 1
Could not automatically determine the hadronizer type and set the correct parton selection mode. Parton-based jet flavour will not be defined.
%MSG
Begin processing the 2nd record. Run 1, Event 2, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:05.542 CEST
Begin processing the 3rd record. Run 1, Event 3, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:08.168 CEST
Begin processing the 4th record. Run 1, Event 4, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:10.733 CEST
Begin processing the 5th record. Run 1, Event 5, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:13.286 CEST
Begin processing the 6th record. Run 1, Event 6, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:15.435 CEST
Begin processing the 7th record. Run 1, Event 8, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:17.857 CEST
Begin processing the 8th record. Run 1, Event 7, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:20.059 CEST
Begin processing the 9th record. Run 1, Event 9, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:22.279 CEST
Begin processing the 10th record. Run 1, Event 11, LumiSection 1 on stream 0 at 19-Oct-2023 11:01:25.115 CEST

@waredjeb @makortel fyi

[cmsbuild]

A new Issue was created by @felicepantaleo Felice Pantaleo.

@antoniovilela, @makortel, @Dr15Jones, @rappoccio, @smuzaffar, @sextonkennedy can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[makortel]

assign core,upgrade

[cmsbuild]

New categories assigned: core,upgrade

@Dr15Jones,@AdrianoDee,@makortel,@smuzaffar,@srimanob you have been requested to review this Pull request/Issue and eventually sign? Thanks

[Dr15Jones]

So I used my recent changes to the Tracer service to gather statistics on your job. What I found was the following break down

 51s parsing python
  8.4s setting up source
 19.7s constructing the 2200 modules
  0.05s in begin job
  0.05s in begin stream
143s in CondDBESSource to find the conditions for the first Run
  0.0003s source reading begin run
 24s in global Begin Run
    1.8s in dqmCSCClient
    2.1s in XMLIdealGeometryESSource
    0.9s in hcalParameters
    1.6s in EcalBarrelGeometryEP
    0.9s in hgcalEEParametersInitialize
    1.1s in hgcalHESiParametersInitialize
    1.2s in gemGeometry
    2.7s in TrackerAlignmentRcd
    1.0s in ecalMonitorTask
    4.2s in VolumeBasedMagneticFieldESProducer
    1.0s in trackerGeometry

  0.2s in CondDBESSource to find conditions for first lumi

50s in stream begin Run
    48.3s in mtdNumberingGeometry
 0.002s source reading begin lumi
 0.02s in global begin lumi
 0.2s in stream begin lumi
 0.004s source reading first event

317s from start to start processing first event

So the obvious speed ups would be to

• use a more efficient configuration file, either from .dumpPython or one where you pickle to results and always re-read from the pickle file.
• choose a different way to get your conditions. You could choose https://github.com/cms-sw/cmssw/tree/master/CondCore/CondHDF5ESSource#readme
• optimize mtdNumberingGeometry

[srimanob]

Thanks very much @Dr15Jones for analysis.
FYI @cms-sw/mtd-dpg-l2 @fabiocos on mtdNumberingGeometry

[makortel]

I investigated the first 3 steps of the workflow with VTune (as @felicepantaleo told me it felt like all the steps have long startup time). On step 1 (GEN-SIM) the job divides clearly into three phases

The first phase is the overall job startup (shown in the top thread), taking about 102 seconds wall clock time, and 85 seconds of CPU time. The CPU time divides into

• 2 seconds of reading the configuration
• 19 seconds of constructing the EventProcessor (i.e. module construction and all that)
• 63 seconds spent in EventSetup
  • 40 seconds spent in MuonOffsetESProducer
  • 5 seconds in HcalSimParametersESModule
  • 4 seconds in VolumeBasedMagneticFieldESProducerFromDB
  • 4 seconds in XMLIdealGeometryESSource
  • 4 seconds in HGCalParametersESModule
  • 3 seconds in EcalSimParametersESModule
  • rest is 1 second or below

Here is flame graph of what happens in MuonOffsetESProducer

The question is then, does it really need to be this expensive? @cms-sw/geometry-l2

---

Second phase (middle thread in the timeline) is the Geant4 initialization in the OscarMTMasterThread, taking about 50 seconds. I don't know if there is anything that could be easily done there, but here is the flame graph of that anyway @cms-sw/simulation-l2

---

Third phase (mostly in the bottom thread in the timeline) is the actual event processing (most time spent in Geant4, so shows in a separate non-TBB thread), taking about 45 seconds for 10 events.

[makortel]

assign geometry

[cmsbuild]

New categories assigned: geometry

@Dr15Jones,@civanch,@bsunanda,@makortel,@mdhildreth you have been requested to review this Pull request/Issue and eventually sign? Thanks

[makortel]

The step 2 (DIGI-HLT) took in total 240 seconds wall clock time and 220 second CPU time.

The configuration defines 901 EDModules, 208 ESModules, 57 (End)Paths, 116 Sequences, and 157 Tasks.

The startup phase (72 seconds CPU time) divides into

• 5 seconds of reading configuration
• 46 seconds in EventProcessor constructor
  • 27 seconds in StreamSchedule constructor, i.e. loading libraries, creating modules, registering data products (of which a lot of time is spent in cling), and all that
    • 12 seconds spent in Maker::makeModule, of which 8 seconds in creating edm::stream modules. This 8 seconds increases with the number of streams, but is run serially!
      • 3 seconds in L1TPFCaloProducer constructor
        • Most of the time seems to be spent in reading data from a ROOT file via l1tpf::corrector::init_()
      • 2 seconds in DTTrigPhase2Prod constructor
        • Most of the time seems to be spent in GlobalCoordsObtainer::generate_luts()
      • 2 seconds in l1tpf::PFClusterProducerFromHGC3DClusters constructor
        • Most of the time seems to be spent in creating cut parser, and creating expression parser in l1tpf::HGC3DClusterEgID constructor
      • 0.3 seconds in MixingModule constructor, rest is below that
  • 1 second constructing the source

@cms-sw/l1-l2 Is there anything that could be done to speed up the constructors of the aforementioned 3 L1T modules?

---

Next is beginRun transition (including most, if not all, of EventSetup), about 100 seconds of CPU time, divided into

• EventSetup
  • 58 seconds in MTDGeometricTimingDetESModule::produce() (which @Dr15Jones also noted above)
  • 7.0 seconds in getting the CondDB data
    • notably 4 seconds for SiPixelGainCalibrationOffline, rest are below 1 second
  • 4.3 seconds in magneticfield::VolumeBasedMagneticFieldESProducerFromDB::produce()
  • 4.3 seconds in XMLIdealGeometryESSource::produceGeom()
  • 4.0 seconds in HGCalParametersESModule::produce()
  • 3.3 seconds in TrackerDigiGeometryESModule::produce()
  • 2.7 seconds in CaloGeometryEP<EcalBarrelGeometry, DDCompactView>::produceAligned()
  • 2.0 seconds in DTGeometryESModule::produce()
  • 1.7 seconds in CSCGeometryESModule::produce()
  • 1.7 seconds in GEMGeometryESModule::produce()
  • 1.5 seconds in HcalParametersESModule::produce()
  • 1.2 seconds in HGCalGeometryESProducer::produce()
  • 1.1 seconds in HcalTPGCoderULUT::produce()
  • 1.0 seconds in RPCGeometryESModule::produce()
  • 0.6 seconds in MuonGeometryConstantsESModule::produce()
  • rest is smaller
• EDModule beginRun
  • 3 seconds in trklet::TrackletEventProcessor::init()

---

Then comes the event data processing, 63 seconds for 10 events

• 4.6 seconds in OutputModule writing the data
• 56 seconds in EDModules
  • 45 seconds in MixingModule
    • 41 seconds in HGCDigiProducer::finalizeEvent()
    • 2.7 seconds in HcalDigiProducer::finalizeEvent()
    • 0.5 seconds in EcalDigiProducer::finalizeEvent()
  • rest: