Slow processing of reconstruction configuration

[Dr15Jones]

Using python's cProfile package I determined that 44% of the time reading in a standard reconstruction configuration is spent in miniAOD_customizeAllMC. The time in that routine is dominated by the three (indirect) calls to runMetCorAndUncForMiniAODProduction and that routine is dominated by the three calls to RunMETCorrectionsAndUncertainties.__call__. The __call__ each make one call to RunMETCorrectionsAndUncertainties.toolCode. From there, the timing gets distributed across multiple calls

PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:262(toolCode)
ncalls  tottime  cumtime
       9    0.000    0.001  PhysicsTools/PatAlgos/tools/helpers.py:121(removeIfInSequence)
       9    0.000    1.415 PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:442(produceMET)
       9    0.001   10.190  PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:475(getCorrectedMET)
       9    0.000    5.699  PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:1398(getJetCollectionForCorsAndUncs)
       3    0.001    2.788  PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:1431(ak4JetReclustering)

digging deeper

PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:475(getCorrectedMET)  
      9    0.000    0.000  /cvmfs/cms-ib.cern.ch/week1/slc6_amd64_gcc630/cms/cmssw-patch/CMSSW_9_3_X_2017-08-16-1100/python/PhysicsTools/PatAlgos/tools/helpers.py:12(getPatAlgosToolsTask)
     99    0.000    5.597  PhysicsTools/PatAlgos/tools/helpers.py:27(addToProcessAndTask)
     12    0.000    3.448  PhysicsTools/PatAlgos/tools/helpers.py:251(cloneProcessingSnippet)
      3    0.825    1.116  PhysicsTools/PatUtils/tools/runMETCorrectionsAndUncertainties.py:664(addIntermediateMETs)

several of the branches have time in addToProcessAndTask which gives

PhysicsTools/PatAlgos/tools/helpers.py:27(addToProcessAndTask)  
     476    0.001    0.002  FWCore/ParameterSet/SequenceTypes.py:1247(add)
     476    0.000    0.000  {getattr}
     476    0.001   14.462  {setattr}

The next largest contribution (at 21% of the time) is loading DQMOfflineMC_cff.py which all comes from DQMOffline_cff.py. The time in DQMOffline_cff is split fairly fine (note: entries with less than 0.1 cumtime have been removed)

DQMOffline_cff.py:1(<module>)
 ncalls  tottime  cumtime
      1    0.068    6.198  DQMOffline_Trigger_cff.py:1(<module>)
      1    0.039    0.227  DQMPhysics_cff.py:1(<module>)
      1    0.006    0.338  DQMSequences_cfi.py:1(<module>)
      1    0.022    2.199  L1TriggerDqmOffline_cff.py:1(<module>)
      1    0.026    1.126  SiPixelOfflineDQM_source_cff.py:1(<module>)
      1    0.045    0.340  SiStripSourceConfigTier0_cff.py:1(<module>)
      1    0.038    1.103  TrackingSourceConfig_Tier0_cff.py:1(<module>)
      1    0.012    0.700  dqmAnalyzer_cff.py:1(<module>)
      1    0.019    0.216  ecal_dqm_source_offline_cff.py:1(<module>)
      1    0.006    0.115  egammaDQMOffline_cff.py:1(<module>)
      1    0.027    0.362  jetMETDQMOfflineSource_cff.py:1(<module>)
      1    0.013    0.203  miniAODDQM_cff.py:1(<module>)
      1    0.015    0.318  muonMonitors_cff.py:1(<module>)

The time in DQMOffline_Trigger_cff.py is just split evenly in other module loads

DQMOffline_Trigger_cff.py:1(<module>) 
  ncalls  tottime  cumtime
       1    0.004    0.476  BTaggingMonitoring_cff.py:1(<module>)
       1    0.008    0.292  EgHLTOfflineSource_cfi.py:1(<module>)
       1    0.005    0.245  EgammaMonitoring_cff.py:1(<module>)
       1    0.015    1.393  ExoticaMonitoring_cff.py:1(<module>)
       1    0.002    0.185  FSQHLTOfflineSource_cfi.py:1(<module>)
       1    0.000    0.105  HILowLumiHLTOfflineSource_cfi.py:1(<module>)
       1    0.028    0.103  HLTObjectsMonitor_cfi.py:1(<module>)
       1    0.007    0.368  HiggsMonitoring_cff.py:1(<module>)
       1    0.004    0.219  JetMETHLTOfflineAnalyzer_cff.py:1(<module>)
       1    0.006    0.263  JetMETPromptMonitor_cff.py:1(<module>)
       1    0.003    0.180  SiPixel_OfflineMonitoring_cff.py:1(<module>)
       1    0.025    0.626  SusyMonitoring_cff.py:1(<module>)
       1    0.001    0.444  TopMonitoring_cff.py:1(<module>)
       1    0.000    0.248  TrackingMonitoringPA_cff.py:1(<module>)
       1    0.001    0.493  TrackingMonitoring_cff.py:1(<module>)

[cmsbuild]

A new Issue was created by @Dr15Jones Chris Jones.

@davidlange6, @Dr15Jones, @smuzaffar can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[Dr15Jones]

assign reconstruction

[cmsbuild]

New categories assigned: reconstruction

@slava77,@perrotta you have been requested to review this Pull request/Issue and eventually sign? Thanks

[davidlange6]

see also #18800

[slava77]

@Dr15Jones
how do I use cProfile?

[Dr15Jones]

@slava77 I'm afraid I no longer remember. I originally figured it out by scanning the documentation.

[makortel]

assign xpog

[cmsbuild]

New categories assigned: xpog

@vlimant,@simonepigazzini you have been requested to review this Pull request/Issue and eventually sign? Thanks

[makortel]

The cost of miniAOD_customizeAllMC() came up in #43062

[vlimant]

I am not surprised that this kind of configuration is extra slow ... and likely could be avoided