diff --git a/Calibration/IsolatedParticles/test/HLT_IsoTrig_Data_New1.py b/Calibration/IsolatedParticles/test/HLT_IsoTrig_Data_New1.py index 97920e71d4b85..884b8e0bf8b50 100644 --- a/Calibration/IsolatedParticles/test/HLT_IsoTrig_Data_New1.py +++ b/Calibration/IsolatedParticles/test/HLT_IsoTrig_Data_New1.py @@ -171,37 +171,14 @@ # instrument the menu with the FastTimerService process.load( "HLTrigger.Timer.FastTimerService_cfi" ) -# this is currently ignored in 7.x, and alway uses the real tim clock -process.FastTimerService.useRealTimeClock = True - -# enable specific features -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True - # print a text summary at the end of the job -process.FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printJobSummary = True # enable per-event DQM plots process.FastTimerService.enableDQM = True -# enable per-path DQM plots -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True - # enable per-module DQM plots process.FastTimerService.enableDQMbyModule = True -process.FastTimerService.enableDQMbyModuleType = True - -# enable per-event DQM sumary plots -process.FastTimerService.enableDQMSummary = True # enable per-event DQM plots by lumisection process.FastTimerService.enableDQMbyLumiSection = True diff --git a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New0.py b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New0.py index 3d49d0b7d81c8..36acb6b7fa710 100644 --- a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New0.py +++ b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New0.py @@ -133,37 +133,14 @@ process.load( "HLTrigger.Timer.FastTimerService_cfi" ) process.load ("HLTrigger.Timer.fastTimerServiceClient_cfi" ) -# this is currently ignored in 7.x, and alway uses the real tim clock -process.FastTimerService.useRealTimeClock = False - -# enable specific features -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True - # print a text summary at the end of the job -process.FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printJobSummary = True # enable per-event DQM plots process.FastTimerService.enableDQM = True -# enable per-path DQM plots -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True - # enable per-module DQM plots process.FastTimerService.enableDQMbyModule = True -#process.FastTimerService.enableDQMbyModuleType = True - -# enable per-event DQM sumary plots -process.FastTimerService.enableDQMSummary = True # enable per-event DQM plots by lumisection process.FastTimerService.enableDQMbyLumiSection = True diff --git a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New1.py b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New1.py index e4fae8c598296..f7e463bb1fe4a 100644 --- a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New1.py +++ b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New1.py @@ -144,37 +144,14 @@ process.load( "HLTrigger.Timer.FastTimerService_cfi" ) process.load ("HLTrigger.Timer.fastTimerServiceClient_cfi" ) -# this is currently ignored in 7.x, and alway uses the real tim clock -process.FastTimerService.useRealTimeClock = False - -# enable specific features -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True - # print a text summary at the end of the job -process.FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printJobSummary = True # enable per-event DQM plots process.FastTimerService.enableDQM = True -# enable per-path DQM plots -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True - # enable per-module DQM plots process.FastTimerService.enableDQMbyModule = True -#process.FastTimerService.enableDQMbyModuleType = True - -# enable per-event DQM sumary plots -process.FastTimerService.enableDQMSummary = True # enable per-event DQM plots by lumisection process.FastTimerService.enableDQMbyLumiSection = True diff --git a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New2.py b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New2.py index 331b900f6cadb..7ddfc17972764 100644 --- a/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New2.py +++ b/Calibration/IsolatedParticles/test/HLT_IsoTrig_MC_New2.py @@ -247,37 +247,14 @@ process.load( "HLTrigger.Timer.FastTimerService_cfi" ) process.load ("HLTrigger.Timer.fastTimerServiceClient_cfi" ) -# this is currently ignored in 7.x, and alway uses the real tim clock -process.FastTimerService.useRealTimeClock = False - -# enable specific features -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True - # print a text summary at the end of the job -process.FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printJobSummary = True # enable per-event DQM plots process.FastTimerService.enableDQM = True -# enable per-path DQM plots -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True - # enable per-module DQM plots process.FastTimerService.enableDQMbyModule = True -#process.FastTimerService.enableDQMbyModuleType = True - -# enable per-event DQM sumary plots -process.FastTimerService.enableDQMSummary = True # enable per-event DQM plots by lumisection process.FastTimerService.enableDQMbyLumiSection = True diff --git a/DQMOffline/Configuration/python/DQMOffline_cff.py b/DQMOffline/Configuration/python/DQMOffline_cff.py index c78c1479f9131..7cf3d2ba65c64 100644 --- a/DQMOffline/Configuration/python/DQMOffline_cff.py +++ b/DQMOffline/Configuration/python/DQMOffline_cff.py @@ -3,7 +3,6 @@ from DQMServices.Components.DQMMessageLogger_cfi import * from DQMServices.Components.DQMDcsInfo_cfi import * from DQMServices.Components.DQMFastTimerService_cff import * -from DQMServices.Components.DQMFastTimerServiceLuminosity_cfi import * from DQMOffline.Ecal.ecal_dqm_source_offline_cff import * from DQM.HcalTasks.OfflineSourceSequence_pp import * @@ -75,7 +74,7 @@ DQMOffline = cms.Sequence( DQMOfflinePreDPG * DQMOfflinePrePOG * HLTMonitoring * - dqmFastTimerServiceLuminosity * + # dqmFastTimerServiceLuminosity * DQMMessageLogger ) _ctpps_2016_DQMOffline = DQMOffline.copy() diff --git a/DQMServices/Components/python/DQMFastTimerServiceLuminosity_cfi.py b/DQMServices/Components/python/DQMFastTimerServiceLuminosity_cfi.py deleted file mode 100644 index e384d247c83f1..0000000000000 --- a/DQMServices/Components/python/DQMFastTimerServiceLuminosity_cfi.py +++ /dev/null @@ -1,10 +0,0 @@ -import FWCore.ParameterSet.Config as cms - -# set the luminosity for the FastTimerService from SCAL -import HLTrigger.Timer.ftsLuminosityFromScalers_cfi as __ftsLuminosityFromScalers_cfi -dqmFastTimerServiceLuminosity = __ftsLuminosityFromScalers_cfi.ftsLuminosityFromScalers.clone() -dqmFastTimerServiceLuminosity.name = 'luminosity' -dqmFastTimerServiceLuminosity.title = 'instantaneous luminosity (from SCAL)' -dqmFastTimerServiceLuminosity.source = 'scalersRawToDigi' -dqmFastTimerServiceLuminosity.range = 1.e34 -dqmFastTimerServiceLuminosity.resolution = 1.e31 diff --git a/DQMServices/Components/python/DQMFastTimerService_cff.py b/DQMServices/Components/python/DQMFastTimerService_cff.py index 56c3975c62083..d706d2e9823ad 100644 --- a/DQMServices/Components/python/DQMFastTimerService_cff.py +++ b/DQMServices/Components/python/DQMFastTimerService_cff.py @@ -3,37 +3,16 @@ # instrument the process with the FastTimerService from HLTrigger.Timer.FastTimerService_cfi import FastTimerService -# this is currently ignored in 7.x, and always uses the real time clock -FastTimerService.useRealTimeClock = False - -# enable specific features -FastTimerService.enableTimingPaths = True -FastTimerService.enableTimingModules = False -FastTimerService.enableTimingExclusive = False - # print a text summary at the end of the job -FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -FastTimerService.skipFirstPath = False +FastTimerService.printEventSummary = False +FastTimerService.printRunSummary = False +FastTimerService.printJobSummary = True # enable per-event DQM plots FastTimerService.enableDQM = True -# enable per-path DQM plots -FastTimerService.enableDQMbyPathActive = True -FastTimerService.enableDQMbyPathTotal = True -FastTimerService.enableDQMbyPathOverhead = False -FastTimerService.enableDQMbyPathDetails = True -FastTimerService.enableDQMbyPathCounters = True -FastTimerService.enableDQMbyPathExclusive = False - -# enable per-module DQM plots +# disable per-module DQM plots FastTimerService.enableDQMbyModule = False -FastTimerService.enableDQMbyModuleType = False - -# enable per-event DQM sumary plots -FastTimerService.enableDQMSummary = True # enable per-event DQM plots by lumisection FastTimerService.enableDQMbyLumiSection = True diff --git a/HLTrigger/Configuration/python/Tools/confdb.py b/HLTrigger/Configuration/python/Tools/confdb.py index a3b93eed4f218..f7d40f52fa7bd 100755 --- a/HLTrigger/Configuration/python/Tools/confdb.py +++ b/HLTrigger/Configuration/python/Tools/confdb.py @@ -661,39 +661,23 @@ def instrumentTiming(self): # instrument the menu with the modules and EndPath needed for timing studies """ + self.data += '\n# configure the FastTimerService\n' if not 'FastTimerService' in self.data: - self.data += '\n# configure the FastTimerService\n' self.loadCff('HLTrigger.Timer.FastTimerService_cfi') - else: - self.data += '\n# configure the FastTimerService\n' - - self.data += """# this is currently ignored in CMSSW 7.x, always using the real time clock -%(process)s.FastTimerService.useRealTimeClock = True -# enable specific features -%(process)s.FastTimerService.enableTimingPaths = True -%(process)s.FastTimerService.enableTimingModules = True -%(process)s.FastTimerService.enableTimingExclusive = True -# print a text summary at the end of the job -%(process)s.FastTimerService.enableTimingSummary = True -# skip the first path (disregard the time spent loading event and conditions data) -%(process)s.FastTimerService.skipFirstPath = True + + self.data += """# print a text summary at the end of the job +%(process)s.FastTimerService.printJobSummary = True + # enable DQM plots %(process)s.FastTimerService.enableDQM = True -# enable most per-path DQM plots -%(process)s.FastTimerService.enableDQMbyPathActive = True -%(process)s.FastTimerService.enableDQMbyPathTotal = True -%(process)s.FastTimerService.enableDQMbyPathOverhead = False -%(process)s.FastTimerService.enableDQMbyPathDetails = True -%(process)s.FastTimerService.enableDQMbyPathCounters = True -%(process)s.FastTimerService.enableDQMbyPathExclusive = True + # disable per-module DQM plots %(process)s.FastTimerService.enableDQMbyModule = False -%(process)s.FastTimerService.enableDQMbyModuleType = False -# enable per-event DQM sumary plots -%(process)s.FastTimerService.enableDQMSummary = True + # enable per-event DQM plots by lumisection %(process)s.FastTimerService.enableDQMbyLumiSection = True %(process)s.FastTimerService.dqmLumiSectionsRange = 2500 + # set the time resolution of the DQM plots %(process)s.FastTimerService.dqmTimeRange = 1000. %(process)s.FastTimerService.dqmTimeResolution = 5. @@ -701,6 +685,7 @@ def instrumentTiming(self): %(process)s.FastTimerService.dqmPathTimeResolution = 0.5 %(process)s.FastTimerService.dqmModuleTimeRange = 40. %(process)s.FastTimerService.dqmModuleTimeResolution = 0.2 + # set the base DQM folder for the plots %(process)s.FastTimerService.dqmPath = 'HLT/TimerService' %(process)s.FastTimerService.enableDQMbyProcesses = True diff --git a/HLTrigger/Timer/BuildFile.xml b/HLTrigger/Timer/BuildFile.xml index 6a65e680ce30c..065b6fd72d825 100644 --- a/HLTrigger/Timer/BuildFile.xml +++ b/HLTrigger/Timer/BuildFile.xml @@ -6,7 +6,7 @@ - + diff --git a/HLTrigger/Timer/interface/EDMModuleType.h b/HLTrigger/Timer/interface/EDMModuleType.h new file mode 100644 index 0000000000000..34f16b72a6a0c --- /dev/null +++ b/HLTrigger/Timer/interface/EDMModuleType.h @@ -0,0 +1,37 @@ +#ifndef HLTrigger_Timer_interface_EDMModuleType_h +#define HLTrigger_Timer_interface_EDMModuleType_h + +#include "DataFormats/Provenance/interface/ModuleDescription.h" + +namespace edm { + +enum class EDMModuleType { + kUnknown, + kSource, + kESSource, + kESProducer, + kEDAnalyzer, + kEDProducer, + kEDFilter, + kOutputModule +}; + +constexpr +const char * module_type_desc[] { + "Unknown", + "Source", + "ESSource", + "ESProducer", + "EDAnalyzer", + "EDProducer", + "EDFilter", + "OutputModule" +}; + +EDMModuleType edmModuleTypeEnum(edm::ModuleDescription const & module); + +const char * edmModuleType(edm::ModuleDescription const & module); + +} // namespace edm + +#endif // not defined HLTrigger_Timer_interface_EDMModuleType_h diff --git a/HLTrigger/Timer/interface/FastTimer.h b/HLTrigger/Timer/interface/FastTimer.h deleted file mode 100644 index 491fdb48749d8..0000000000000 --- a/HLTrigger/Timer/interface/FastTimer.h +++ /dev/null @@ -1,44 +0,0 @@ -#ifndef FastTimer_h -#define FastTimer_h - -// C++ headers -#include - -class FastTimer { -public: - typedef std::chrono::high_resolution_clock Clock; - typedef std::chrono::nanoseconds Duration; - enum class State { - kStopped, - kRunning, - kPaused - }; - - FastTimer(); - - void start(); - void pause(); - void resume(); - void stop(); - void reset(); - - Duration value() const; - Duration untilNow() const; - double seconds() const; - double secondsUntilNow() const; - State state() const; - Clock::time_point const & getStartTime() const; - Clock::time_point const & getStopTime() const; - void setStartTime(Clock::time_point const &); - void setStopTime(Clock::time_point const &); - -private: - std::string const & describe() const; - - Clock::time_point m_start; - Clock::time_point m_stop; - Duration m_duration; - State m_state; -}; - -#endif // ! FastTimer_h diff --git a/HLTrigger/Timer/interface/FastTimerService.h b/HLTrigger/Timer/interface/FastTimerService.h index cbd18929caa5b..2d8035ce5f55e 100644 --- a/HLTrigger/Timer/interface/FastTimerService.h +++ b/HLTrigger/Timer/interface/FastTimerService.h @@ -10,6 +10,14 @@ #include #include +// boost headers +#include + +// tbb headers +#include +#include + + // CMSSW headers #include "FWCore/ServiceRegistry/interface/ActivityRegistry.h" #include "FWCore/ServiceRegistry/interface/Service.h" @@ -28,23 +36,13 @@ #include "DataFormats/Provenance/interface/ModuleDescription.h" #include "DQMServices/Core/interface/DQMStore.h" #include "DQMServices/Core/interface/MonitorElement.h" -#include "HLTrigger/Timer/interface/FastTimer.h" +#include "HLTrigger/Timer/interface/ProcessCallGraph.h" /* -procesing time is diveded into +procesing time is divided into - source - - pre-event processing overhead - - event processing - - post-event processing overhead - -until lumi-processing and run-processing are taken into account, they will count as inter-event overhead - -event processing time is diveded into - - trigger processing (from the begin of the first path to the end of the last path) - - trigger overhead - - endpath processing (from the begin of the first endpath to the end of the last endpath) - - endpath overhead + - event processing, sum of the time spent in all the modules */ /* @@ -86,690 +84,383 @@ class FastTimerService { FastTimerService(const edm::ParameterSet &, edm::ActivityRegistry & ); ~FastTimerService(); - // reserve plots for timing vs. luminosity - these should only be called before any begin run (actually, before any preStreamBeginRun) - unsigned int reserveLuminosityPlots(std::string const & name, std::string const & title, std::string const & label, double range, double resolution); - unsigned int reserveLuminosityPlots(std::string && name, std::string && title, std::string && label, double range, double resolution); - - // set the event luminosity - void setLuminosity(unsigned int stream_id, unsigned int luminosity_id, double value); - - // query the current module/path/event - // Note: these functions incur in a "per-call timer overhead" (see above), currently of the order of 340ns - double currentModuleTime(edm::StreamID) const; // return the time spent since the last preModuleEvent() event - double currentPathTime(edm::StreamID) const; // return the time spent since the last prePathEvent() event - double currentEventTime(edm::StreamID) const; // return the time spent since the last preEvent() event +private: + double queryModuleTime_(edm::StreamID, unsigned int id) const; - // query the time spent in a module/path (available after it has run) - double queryModuleTime(edm::StreamID, const edm::ModuleDescription &) const; - double queryModuleTime(edm::StreamID, unsigned int id) const; - double queryModuleTimeByLabel(edm::StreamID, const std::string &) const; - double queryModuleTimeByType(edm::StreamID, const std::string &) const; - /* FIXME re-implement taking into account subprocesses - double queryPathActiveTime(edm::StreamID, const std::string &) const; - double queryPathExclusiveTime(edm::StreamID, const std::string &) const; - double queryPathTotalTime(edm::StreamID, const std::string &) const; - */ - - // query the time spent in the current event's - // - source (available during event processing) - // - all paths (available during endpaths) - // - all endpaths (available after all endpaths have run) - // - processing (available after the event has been processed) +public: + // query the time spent in a module/path/process (available after it has run) double querySourceTime(edm::StreamID) const; double queryEventTime(edm::StreamID) const; - /* FIXME re-implement taking into account subprocesses - double queryPathsTime(edm::StreamID) const; - double queryEndPathsTime(edm::StreamID) const; - */ - - /* FIXME not yet implemented - // try to assess the overhead which may not be included in the source, paths and event timers - double queryPreSourceOverhead(edm::StreamID) const; // time spent after the previous event's postEvent and this event's preSource - double queryPreEventOverhead(edm::StreamID) const; // time spent after this event's postSource and preEvent - double queryPreEndPathsOverhead(edm::StreamID) const; // time spent after the last path's postPathEvent and the first endpath's prePathEvent - */ + double queryEventTime(edm::StreamID, std::string const& process) const; + double queryModuleTime(edm::StreamID, const edm::ModuleDescription & module) const; + double queryModuleTime(edm::StreamID, unsigned int id) const; + double queryModuleTimeByLabel(edm::StreamID, std::string const& module) const; + double queryModuleTimeByLabel(edm::StreamID, std::string const& process, const std::string & module) const; + double queryPathTime(edm::StreamID, std::string const& path) const; + double queryPathTime(edm::StreamID, std::string const& process, std::string const& path) const; + double queryHighlightTime(edm::StreamID sid, std::string const& label) const; private: - void preallocate(edm::service::SystemBounds const &); + void ignoredSignal(std::string signal) const; + void unsupportedSignal(std::string signal) const; + + // these signal pairs are not guaranteed to happen in the same thread + + void preallocate(edm::service::SystemBounds const&); + + void preBeginJob(edm::PathsAndConsumesOfModulesBase const&, edm::ProcessContext const&); + void postBeginJob(); + void postEndJob(); - void preGlobalBeginRun(edm::GlobalContext const &); - void preStreamBeginRun(edm::StreamContext const &); - void postStreamBeginRun(edm::StreamContext const &); - void postStreamEndRun(edm::StreamContext const &); - void postStreamBeginLumi(edm::StreamContext const &); - void postStreamEndLumi(edm::StreamContext const& ); - void postGlobalEndRun(edm::GlobalContext const &); - void preModuleBeginJob(edm::ModuleDescription const &); - void preSourceEvent( edm::StreamID ); - void postSourceEvent( edm::StreamID ); - void preEvent(edm::StreamContext const &); - void postEvent(edm::StreamContext const &); - void prePathEvent(edm::StreamContext const &, edm::PathContext const &); - void postPathEvent(edm::StreamContext const &, edm::PathContext const &,edm:: HLTPathStatus const &); - void preModuleEvent(edm::StreamContext const &, edm::ModuleCallingContext const &); - void postModuleEvent(edm::StreamContext const &, edm::ModuleCallingContext const &); - void preModuleEventDelayedGet(edm::StreamContext const &, edm::ModuleCallingContext const &); - void postModuleEventDelayedGet(edm::StreamContext const &, edm::ModuleCallingContext const &); -public: - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); + void preGlobalBeginRun(edm::GlobalContext const&); + void postGlobalBeginRun(edm::GlobalContext const&); -private: + void preGlobalEndRun(edm::GlobalContext const&); + void postGlobalEndRun(edm::GlobalContext const&); - struct LuminosityDescription { - std::string name; - std::string title; - std::string label; - double range; - double resolution; - - LuminosityDescription(std::string const & _name, std::string const & _title, std::string const & _label, double _range, double _resolution) : - name(_name), - title(_title), - label(_label), - range(_range), - resolution(_resolution) - { } - - LuminosityDescription(std::string && _name, std::string && _title, std::string const & _label, double _range, double _resolution) : - name(_name), - title(_title), - label(_label), - range(_range), - resolution(_resolution) - { } - }; + void preStreamBeginRun(edm::StreamContext const&); + void postStreamBeginRun(edm::StreamContext const&); + void preStreamEndRun(edm::StreamContext const&); + void postStreamEndRun(edm::StreamContext const&); - struct PathInfo; + void preGlobalBeginLumi(edm::GlobalContext const&); + void postGlobalBeginLumi(edm::GlobalContext const&); - struct ModuleInfo { - FastTimer timer; // per-event timer - double time_active; // time actually spent in this module - double summary_active; - TH1F * dqm_active; - PathInfo * run_in_path; // the path inside which the module was atually active - uint32_t counter; // count how many times the module was scheduled to run + void preGlobalEndLumi(edm::GlobalContext const&); + void postGlobalEndLumi(edm::GlobalContext const&); - public: - ModuleInfo() : - timer(), - time_active(0.), - summary_active(0.), - dqm_active(nullptr), - run_in_path(nullptr), - counter(0) - { } - - ~ModuleInfo() { - reset(); - } - - // reset the timers and DQM plots - void reset() { - timer.reset(); - time_active = 0.; - summary_active = 0.; - // the DQM plots are owned by the DQMStore - dqm_active = nullptr; - run_in_path = nullptr; - counter = 0; - } - }; + void preStreamBeginLumi(edm::StreamContext const&); + void postStreamBeginLumi(edm::StreamContext const&); - struct PathInfo { - std::vector modules; // list of all modules contributing to the path (duplicate modules stored as null pointers) - ModuleInfo * first_module; // first module actually run in this path - FastTimer timer; // per-event timer - double time_active; // time actually spent in this path - double time_exclusive; // time actually spent in this path, in modules that are not run on any other paths - double time_premodules; // time spent between "begin path" and the first "begin module" - double time_intermodules; // time spent between modules - double time_postmodules; // time spent between the last "end module" and "end path" - double time_overhead; // sum of time_premodules, time_intermodules, time_postmodules - double time_total; // sum of the time spent in all modules which would have run in this path (plus overhead) - double summary_active; - double summary_premodules; - double summary_intermodules; - double summary_postmodules; - double summary_overhead; - double summary_total; - uint32_t last_run; // index of the last module run in this path, plus one - uint32_t index; // index of the Path or EndPath in the "schedule" - bool accept; // flag indicating if the path acepted the event - TH1F * dqm_active; // see time_active - TH1F * dqm_exclusive; // see time_exclusive - TH1F * dqm_premodules; // see time_premodules - TH1F * dqm_intermodules; // see time_intermodules - TH1F * dqm_postmodules; // see time_postmodules - TH1F * dqm_overhead; // see time_overhead - TH1F * dqm_total; // see time_total - TH1F * dqm_module_counter; // for each module in the path, track how many times it ran - TH1F * dqm_module_active; // for each module in the path, track the active time spent - TH1F * dqm_module_total; // for each module in the path, track the total time spent + void preStreamEndLumi(edm::StreamContext const&); + void postStreamEndLumi(edm::StreamContext const&); - public: - PathInfo() : - modules(), - first_module(nullptr), - timer(), - time_active(0.), - time_exclusive(0.), - time_premodules(0.), - time_intermodules(0.), - time_postmodules(0.), - time_overhead(0.), - time_total(0.), - summary_active(0.), - summary_premodules(0.), - summary_intermodules(0.), - summary_postmodules(0.), - summary_overhead(0.), - summary_total(0.), - last_run(0), - index(0), - accept(false), - dqm_active(nullptr), - dqm_exclusive(nullptr), - dqm_premodules(nullptr), - dqm_intermodules(nullptr), - dqm_postmodules(nullptr), - dqm_overhead(nullptr), - dqm_total(nullptr), - dqm_module_counter(nullptr), - dqm_module_active(nullptr), - dqm_module_total(nullptr) - { } - - ~PathInfo() { - reset(); - } - - // reset the timers and DQM plots - void reset() { - first_module = nullptr; - timer.reset(); - time_active = 0.; - time_exclusive = 0.; - time_premodules = 0.; - time_intermodules = 0.; - time_postmodules = 0.; - time_overhead = 0.; - time_total = 0.; - summary_active = 0.; - summary_premodules = 0.; - summary_intermodules = 0.; - summary_postmodules = 0.; - summary_overhead = 0.; - summary_total = 0.; - last_run = 0; - index = 0; - accept = false; - - // the DQM plots are owned by the DQMStore - dqm_active = nullptr; - dqm_premodules = nullptr; - dqm_intermodules = nullptr; - dqm_postmodules = nullptr; - dqm_overhead = nullptr; - dqm_total = nullptr; - dqm_module_counter = nullptr; - dqm_module_active = nullptr; - dqm_module_total = nullptr; - } - }; + void preEvent(edm::StreamContext const&); + void postEvent(edm::StreamContext const&); - // the vector is indexed by the peudo-process id, the paths by their path name - template - using PathMap = std::vector>; + void prePathEvent(edm::StreamContext const&, edm::PathContext const&); + void postPathEvent(edm::StreamContext const&, edm::PathContext const&, edm::HLTPathStatus const&); - // key on ModuleDescription::id() - template - using ModuleMap = std::vector; + void preModuleEventPrefetching(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleEventPrefetching(edm::StreamContext const&, edm::ModuleCallingContext const&); - // timer configuration - bool m_use_realtime; - bool m_enable_timing_paths; - bool m_enable_timing_modules; - bool m_enable_timing_exclusive; - const bool m_enable_timing_summary; - const bool m_skip_first_path; + // these signal pairs are guaranteed to be called within the same thread - // dqm configuration - bool m_enable_dqm; // non const because the availability of the DQMStore can only be checked during the begin job - const bool m_enable_dqm_bypath_active; // require per-path timers - const bool m_enable_dqm_bypath_total; // require per-path and per-module timers - const bool m_enable_dqm_bypath_overhead; // require per-path and per-module timers - const bool m_enable_dqm_bypath_details; // require per-path and per-module timers - const bool m_enable_dqm_bypath_counters; - const bool m_enable_dqm_bypath_exclusive; - const bool m_enable_dqm_bymodule; // require per-module timers - const bool m_enable_dqm_bymoduletype; // require per-module timers - const bool m_enable_dqm_summary; - const bool m_enable_dqm_byls; - const bool m_enable_dqm_bynproc; - - unsigned int m_concurrent_runs; - unsigned int m_concurrent_streams; - unsigned int m_concurrent_threads; - unsigned int m_module_id; // pseudo module id for the FastTimerService, needed by the thread-safe DQMStore - - const double m_dqm_eventtime_range; - const double m_dqm_eventtime_resolution; - const double m_dqm_pathtime_range; - const double m_dqm_pathtime_resolution; - const double m_dqm_moduletime_range; - const double m_dqm_moduletime_resolution; - std::string m_dqm_path; - - struct ProcessDescription { - std::string name; - std::string first_path; // the framework does not provide a pre/postPaths or pre/postEndPaths signal, - std::string last_path; // so we emulate them keeping track of the first and last non-empty Path and EndPath - std::string first_endpath; - std::string last_endpath; - edm::ParameterSetID pset; + //void preOpenFile(std::string const&, bool); + //void postOpenFile(std::string const&, bool); + + //void preCloseFile(std::string const&, bool); + //void postCloseFile(std::string const&, bool); + + void preSourceConstruction(edm::ModuleDescription const&); + //void postSourceConstruction(edm::ModuleDescription const&); + + void preSourceRun(); + void postSourceRun(); + + void preSourceLumi(); + void postSourceLumi(); + + void preSourceEvent(edm::StreamID); + void postSourceEvent(edm::StreamID); + + //void preModuleConstruction(edm::ModuleDescription const&); + //void postModuleConstruction(edm::ModuleDescription const&); + + //void preModuleBeginJob(edm::ModuleDescription const&); + //void postModuleBeginJob(edm::ModuleDescription const&); + + //void preModuleEndJob(edm::ModuleDescription const&); + //void postModuleEndJob(edm::ModuleDescription const&); + + //void preModuleBeginStream(edm::StreamContext const&, edm::ModuleCallingContext const&); + //void postModuleBeginStream(edm::StreamContext const&, edm::ModuleCallingContext const&); + + //void preModuleEndStream(edm::StreamContext const&, edm::ModuleCallingContext const&); + //void postModuleEndStream(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleGlobalBeginRun(edm::GlobalContext const&, edm::ModuleCallingContext const&); + void postModuleGlobalBeginRun(edm::GlobalContext const&, edm::ModuleCallingContext const&); + + void preModuleGlobalEndRun(edm::GlobalContext const&, edm::ModuleCallingContext const&); + void postModuleGlobalEndRun(edm::GlobalContext const&, edm::ModuleCallingContext const&); + + void preModuleGlobalBeginLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&); + void postModuleGlobalBeginLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&); + + void preModuleGlobalEndLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&); + void postModuleGlobalEndLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&); + + void preModuleStreamBeginRun(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleStreamBeginRun(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleStreamEndRun(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleStreamEndRun(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleStreamBeginLumi(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleStreamBeginLumi(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleStreamEndLumi(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleStreamEndLumi(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleEvent(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleEvent(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preModuleEventDelayedGet(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postModuleEventDelayedGet(edm::StreamContext const&, edm::ModuleCallingContext const&); + + void preEventReadFromSource(edm::StreamContext const&, edm::ModuleCallingContext const&); + void postEventReadFromSource(edm::StreamContext const&, edm::ModuleCallingContext const&); + +public: + static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); + +private: + // highlight a group of modules + struct GroupOfModules { + public: + std::string label; + std::vector modules; }; - struct Timing { - double presource; // time spent between the end of the previous Event, LumiSection or Run, and the beginning of the Source - double source; // time spent processing the Source - double preevent; // time spent between the end of the Source and the new Event, LumiSection or Run - double event; // time spent processing the Event - unsigned int count; // number of processed events (used by the per-run and per-job accounting) - - Timing() : - presource (0.), - source (0.), - preevent (0.), - event (0.), - count (0) - { } - - void reset() { - presource = 0.; - source = 0.; - preevent = 0.; - event = 0.; - count = 0; - } - - Timing & operator+=(Timing const & other) { - presource += other.presource; - source += other.source; - preevent += other.preevent; - event += other.event; - count += other.count; - - return *this; - } - - Timing operator+(Timing const & other) const { - Timing result = *this; - result += other; - return result; - } + // resources being monitored by the service + struct Resources { + public: + Resources(); + void reset(); + Resources & operator+=(Resources const& other); + Resources operator+(Resources const& other) const; + public: + boost::chrono::nanoseconds time_thread; + boost::chrono::nanoseconds time_real; }; - struct TimingPerProcess { - double preevent; // time spent between the end of the Source and the new Event, Lumisection or Run - double event; // time spent processing the Event - double all_paths; // time spent processing all Paths - double all_endpaths; // time spent processing all EndPaths - double interpaths; // time spent between the Paths (and EndPaths - i.e. the sum of all the entries in the following vector) - std::vector paths_interpaths; // time spent between the beginning of the Event and the first Path, between Paths, and between the last (End)Path and the end of the Event - - TimingPerProcess() : - preevent (0.), - event (0.), - all_paths (0.), - all_endpaths (0.), - interpaths (0.), - paths_interpaths() - { } - - void reset() { - preevent = 0.; - event = 0.; - all_paths = 0.; - all_endpaths = 0.; - interpaths = 0.; - paths_interpaths.assign(paths_interpaths.size(), 0.); - } - - TimingPerProcess & operator+=(TimingPerProcess const & other) { - assert( paths_interpaths.size() == other.paths_interpaths.size() ); - - preevent += other.preevent; - event += other.event; - all_paths += other.all_paths; - all_endpaths += other.all_endpaths; - interpaths += other.interpaths; - for (unsigned int i = 0; i < paths_interpaths.size(); ++i) - paths_interpaths[i] += other.paths_interpaths[i]; - return *this; - } - - TimingPerProcess operator+(TimingPerProcess const & other) const { - TimingPerProcess result = *this; - result += other; - return result; - } + struct ResourcesPerModule { + public: + ResourcesPerModule(); + void reset(); + ResourcesPerModule & operator+=(ResourcesPerModule const& other); + ResourcesPerModule operator+(ResourcesPerModule const& other) const; + public: + Resources total; + unsigned events; }; - // set of summary plots, over all subprocesses - struct SummaryPlots { - TH1F * presource; - TH1F * source; - TH1F * preevent; - TH1F * event; - - SummaryPlots() : - presource (nullptr), - source (nullptr), - preevent (nullptr), - event (nullptr) - { } - - void reset() { - // the DQM plots are owned by the DQMStore - presource = nullptr; - source = nullptr; - preevent = nullptr; - event = nullptr; - } - - void fill(Timing const & value) { - // convert on the fly from seconds to ms - presource ->Fill( 1000. * value.presource ); - source ->Fill( 1000. * value.source ); - preevent ->Fill( 1000. * value.preevent ); - event ->Fill( 1000. * value.event ); - } + struct ResourcesPerPath { + public: + ResourcesPerPath(); + void reset(); + ResourcesPerPath & operator+=(ResourcesPerPath const& other); + ResourcesPerPath operator+(ResourcesPerPath const& other) const; + public: + Resources active; // resources used by all modules on this path + Resources total; // resources used by all modules on this path, and their dependencies + unsigned last; // one-past-the last module that ran on this path + bool status; // whether the path accepted or rejected the event }; - // set of summary plots, per subprocess - struct SummaryPlotsPerProcess { - TH1F * preevent; - TH1F * event; - TH1F * all_paths; - TH1F * all_endpaths; - TH1F * interpaths; - - SummaryPlotsPerProcess() : - preevent (nullptr), - event (nullptr), - all_paths (nullptr), - all_endpaths (nullptr), - interpaths (nullptr) - { } - - void reset() { - // the DQM plots are owned by the DQMStore - preevent = nullptr; - event = nullptr; - all_paths = nullptr; - all_endpaths = nullptr; - interpaths = nullptr; - } - - void fill(TimingPerProcess const & value) { - // convert on the fly from seconds to ms - preevent ->Fill( 1000. * value.preevent ); - event ->Fill( 1000. * value.event ); - all_paths ->Fill( 1000. * value.all_paths ); - all_endpaths ->Fill( 1000. * value.all_endpaths ); - interpaths ->Fill( 1000. * value.interpaths ); - } + struct ResourcesPerProcess { + public: + ResourcesPerProcess(ProcessCallGraph::ProcessType const& process); + void reset(); + ResourcesPerProcess & operator+=(ResourcesPerProcess const& other); + ResourcesPerProcess operator+(ResourcesPerProcess const& other) const; + public: + Resources total; + std::vector paths; + std::vector endpaths; }; - // set of summary profiles vs. luminosity, over all subprocesses - struct SummaryProfiles { - TProfile * presource; - TProfile * source; - TProfile * preevent; - TProfile * event; - - SummaryProfiles() : - presource (nullptr), - source (nullptr), - preevent (nullptr), - event (nullptr) - { } - - void reset() { - // the DQM plots are owned by the DQMStore - presource = nullptr; - source = nullptr; - preevent = nullptr; - event = nullptr; - } - - void fill(double x, Timing const & value) { - presource ->Fill( x, 1000. * value.presource ); - source ->Fill( x, 1000. * value.source ); - preevent ->Fill( x, 1000. * value.preevent ); - event ->Fill( x, 1000. * value.event ); - } + struct ResourcesPerJob { + public: + ResourcesPerJob(); + ResourcesPerJob(ProcessCallGraph const& job, std::vector const& groups); + void reset(); + ResourcesPerJob & operator+=(ResourcesPerJob const& other); + ResourcesPerJob operator+(ResourcesPerJob const& other) const; + public: + Resources total; + std::vector highlight; + std::vector modules; + std::vector processes; + unsigned events; }; - // set of summary profiles vs. luminosity, per subprocess - struct SummaryProfilesPerProcess { - TProfile * preevent; - TProfile * event; - TProfile * all_paths; - TProfile * all_endpaths; - TProfile * interpaths; - - SummaryProfilesPerProcess() : - preevent (nullptr), - event (nullptr), - all_paths (nullptr), - all_endpaths (nullptr), - interpaths (nullptr) - { } - - ~SummaryProfilesPerProcess() { - reset(); - } - - void reset() { - // the DQM plots are owned by the DQMStore - preevent = nullptr; - event = nullptr; - all_paths = nullptr; - all_endpaths = nullptr; - interpaths = nullptr; - } - - void fill(double x, TimingPerProcess const & value) { - preevent ->Fill( x, 1000. * value.preevent ); - event ->Fill( x, 1000. * value.event ); - all_paths ->Fill( x, 1000. * value.all_paths ); - all_endpaths ->Fill( x, 1000. * value.all_endpaths ); - interpaths ->Fill( x, 1000. * value.interpaths ); - } + // per-thread measurements + struct Measurement { + public: + Measurement(); + void measure(); + void measure_and_store(Resources & store); + + public: + #ifdef DEBUG_THREAD_CONCURRENCY + std::thread::id id; + #endif // DEBUG_THREAD_CONCURRENCY + boost::chrono::thread_clock::time_point time_thread; + boost::chrono::high_resolution_clock::time_point time_real; }; - // set of profile plots by path, per subprocess - struct PathProfilesPerProcess { - TProfile * active_time; - TProfile * total_time; - TProfile * exclusive_time; - TProfile * interpaths; - - PathProfilesPerProcess() : - active_time (nullptr), - total_time (nullptr), - exclusive_time(nullptr), - interpaths (nullptr) - {} - - ~PathProfilesPerProcess() { - reset(); - } - - void reset() { - // the DQM plots are owned by the DQMStore - active_time = nullptr; - total_time = nullptr; - exclusive_time = nullptr; - interpaths = nullptr; - } + // plots associated to each module or other element (path, process, etc) + class PlotsPerElement { + public: + PlotsPerElement(); + void reset(); + void book(DQMStore::IBooker &, std::string const& name, std::string const& title, double range, double resolution, unsigned int lumisections, bool byls); + void fill(Resources const&, unsigned int lumisection); + void fill_fraction(Resources const&, Resources const&, unsigned int lumisection); + + private: + // resources spent in the module + TH1F * time_thread_; + TProfile * time_thread_byls_; + TH1F * time_real_; + TProfile * time_real_byls_; + }; + // plots associated to each path or endpath + class PlotsPerPath { + public: + PlotsPerPath(); + void reset(); + void book(DQMStore::IBooker &, ProcessCallGraph const&, ProcessCallGraph::PathType const&, double range, double resolution, unsigned int lumisections, bool byls); + void fill(ProcessCallGraph::PathType const&, ResourcesPerJob const&, ResourcesPerPath const&, unsigned int lumisection); + + private: + // resources spent in all the modules in the path, including their dependencies + PlotsPerElement total_; + + // Note: + // a TH1F has 7 significant digits, while a 24-hour long run could process + // order of 10 billion events; a 64-bit long integer would work and might + // be better suited than a double, but there is no "TH1L" in ROOT. + + // how many times each module and their dependencies has run + TH1D * module_counter_; + // resources spent in each module and their dependencies + TH1D * module_time_thread_total_; + TH1D * module_time_real_total_; }; - struct StreamData { - // timers - FastTimer timer_event; // track time spent in each event - FastTimer timer_source; // track time spent in the source - FastTimer timer_paths; // track time spent in all paths - FastTimer timer_endpaths; // track time spent in all endpaths - FastTimer timer_path; // track time spent in each path - FastTimer::Clock::time_point timer_last_path; // record the stop of the last path run - FastTimer::Clock::time_point timer_last_transition; // record the last transition (end source, end event, end lumi, end run) - - // time accounting per-event - Timing timing; - std::vector timing_perprocess; - - // luminosity per event - std::vector luminosity; - - // overall plots - SummaryPlots dqm; // whole event summary plots - std::vector dqm_byluminosity; // whole event plots vs. "luminosity" - std::vector dqm_perprocess; // per-process event summary plots - std::vector> dqm_perprocess_byluminosity; // per-process plots vs. "luminosity" - - // plots by path - std::vector dqm_paths; - - // per-path, per-module and per-module-type accounting - PathInfo * current_path; - ModuleInfo * current_module; - PathMap paths; - std::unordered_map modules; - std::unordered_map moduletypes; - ModuleMap fast_modules; // these assume that module ids are constant throughout the whole job, - ModuleMap fast_moduletypes; - - StreamData() : - // timers - timer_event(), - timer_source(), - timer_paths(), - timer_endpaths(), - timer_path(), - timer_last_path(), - timer_last_transition(), - // time accounting per-event - timing(), - timing_perprocess(), - // luminosity per event - luminosity(), - // overall plots - dqm(), - dqm_byluminosity(), - dqm_perprocess(), - dqm_perprocess_byluminosity(), - // plots by path - dqm_paths(), - // per-path, per-module and per-module-type accounting - current_path(nullptr), - current_module(nullptr), - paths(), - modules(), - moduletypes(), - fast_modules(), - fast_moduletypes() - { } - - // called in FastTimerService::postStreamEndRun() - void reset() { - // timers - timer_event.reset(); - timer_source.reset(); - timer_paths.reset(); - timer_endpaths.reset(); - timer_path.reset(); - timer_last_path = FastTimer::Clock::time_point(); - timer_last_transition = FastTimer::Clock::time_point(); - // time accounting per-event - timing.reset(); - for (auto & timing: timing_perprocess) - timing.reset(); - // luminosity per event - for (auto & lumi: luminosity) - lumi = 0; - // overall plots - dqm.reset(); - for (auto & plots: dqm_byluminosity) - plots.reset(); - for (auto & perprocess_plots: dqm_perprocess) - perprocess_plots.reset(); - for (auto & process_plots: dqm_perprocess_byluminosity) - for (auto & plots: process_plots) - plots.reset(); - // plots by path - for (auto & plots: dqm_paths) - plots.reset(); - // per-path, per-module and per-module-type accounting - current_path = nullptr; - current_module = nullptr; - for (auto & map: paths) - for (auto & keyval: map) - keyval.second.reset(); - for (auto & keyval: modules) - keyval.second.reset(); - for (auto & keyval: moduletypes) - keyval.second.reset(); - } + class PlotsPerProcess { + public: + PlotsPerProcess(ProcessCallGraph::ProcessType const&); + void reset(); + void book(DQMStore::IBooker &, ProcessCallGraph const&, ProcessCallGraph::ProcessType const&, + double event_range, double event_resolution, double path_range, double path_resolution, + unsigned int lumisections, bool byls); + void fill(ProcessCallGraph::ProcessType const&, ResourcesPerJob const&, ResourcesPerProcess const&, unsigned int ls); + + private: + // resources spent in all the modules of the (sub)process + PlotsPerElement event_; + // resources spent in each path and endpath + std::vector paths_; + std::vector endpaths_; + }; + class PlotsPerJob { + public: + PlotsPerJob(ProcessCallGraph const& job, std::vector const& groups); + void reset(); + void book(DQMStore::IBooker &, ProcessCallGraph const&, std::vector const&, + double event_range, double event_resolution, double path_range, double path_resolution, + double module_range, double module_resolution, unsigned int lumisections, + bool bymodule, bool byls); + void fill(ProcessCallGraph const&, ResourcesPerJob const&, unsigned int ls); + + private: + // resources spent in all the modules of the job + PlotsPerElement event_; + // resources spent in the highlighted modules + std::vector highlight_; + // resources spent in each module + std::vector modules_; + // resources spent in each (sub)process + std::vector processes_; }; - // process descriptions - std::vector m_process; - // description of the luminosity axes - std::vector m_dqm_luminosity; + // keep track of the dependencies among modules + ProcessCallGraph callgraph_; - // stream data - std::vector m_stream; + // per-stream information + std::vector streams_; + std::vector stream_plots_; // summary data - std::vector m_run_summary; // whole event time accounting per-run - Timing m_job_summary; // whole event time accounting per-run - std::vector> m_run_summary_perprocess; // per-process time accounting per-job - std::vector m_job_summary_perprocess; // per-process time accounting per-job - std::mutex m_summary_mutex; // synchronise access to the summary objects across different threads + ResourcesPerJob job_summary_; // whole event time accounting per-job + std::vector run_summary_; // whole event time accounting per-run + std::mutex summary_mutex_; // synchronise access to the summary objects across different threads + + // per-thread quantities, lazily allocated + tbb::enumerable_thread_specific, tbb::ets_key_per_instance> + threads_; + + // atomic variables to keep track of the completion of each step, process by process + std::unique_ptr[]> subprocess_event_check_; + std::unique_ptr[]> subprocess_lumisection_check_; + std::unique_ptr[]> subprocess_run_check_; + std::unique_ptr[]> subprocess_global_run_check_; - static - double delta(FastTimer::Clock::time_point const & first, FastTimer::Clock::time_point const & second) - { - return std::chrono::duration_cast>(second - first).count(); - } + // retrieve the current thread's per-thread quantities + Measurement & thread(); - // associate to a path all the modules it contains - void fillPathMap(unsigned int pid, std::string const & name, std::vector const & modules); + // job configuration + unsigned int concurrent_runs_; + unsigned int concurrent_streams_; + unsigned int concurrent_threads_; - // find the first and last non-empty paths, optionally skipping the first one - std::pair findFirstLast(unsigned int pid, std::vector const & paths, bool skip = false); + // logging configuration + const bool print_event_summary_; // print the time spent in each process, path and module after every event + const bool print_run_summary_; // print the time spent in each process, path and module for each run + const bool print_job_summary_; // print the time spent in each process, path and module for the whole job - // print a timing summary for the run or job - void printSummary(Timing const & summary, std::string const & label) const; - void printProcessSummary(Timing const & total, TimingPerProcess const & summary, std::string const & label, std::string const & process) const; + // dqm configuration + unsigned int module_id_; // pseudo module id for the FastTimerService, needed by the thread-safe DQMStore + + bool enable_dqm_; // non const, depends on the availability of the DQMStore + const bool enable_dqm_bymodule_; + const bool enable_dqm_byls_; + const bool enable_dqm_bynproc_; + + const double dqm_eventtime_range_; + const double dqm_eventtime_resolution_; + const double dqm_pathtime_range_; + const double dqm_pathtime_resolution_; + const double dqm_moduletime_range_; + const double dqm_moduletime_resolution_; + const unsigned int dqm_lumisections_range_; + std::string dqm_path_; + + std::vector + highlight_module_psets_; // non-const, cleared in postBeginJob() + std::vector highlight_modules_; // non-const, filled in postBeginJob() + + // log unsupported signals + mutable tbb::concurrent_unordered_set unsupported_signals_; // keep track of unsupported signals received + + // print the resource usage summary for en event, a run, or the while job + template + void printEvent(T& out, ResourcesPerJob const&) const; + + template + void printSummary(T& out, ResourcesPerJob const&, std::string const& label) const; - // assign a "process id" to a process, given its ProcessContext - static - unsigned int processID(edm::ProcessContext const *); + // check if this is the first process being signalled + bool isFirstSubprocess(edm::StreamContext const&); + bool isFirstSubprocess(edm::GlobalContext const&); + // check if this is the lest process being signalled + bool isLastSubprocess(std::atomic& check); }; #endif // ! FastTimerService_h diff --git a/HLTrigger/Timer/interface/ProcessCallGraph.h b/HLTrigger/Timer/interface/ProcessCallGraph.h new file mode 100644 index 0000000000000..5813ff74817d5 --- /dev/null +++ b/HLTrigger/Timer/interface/ProcessCallGraph.h @@ -0,0 +1,199 @@ +#ifndef HLTrigger_Timer_interface_ProcessCallGraph_h +#define HLTrigger_Timer_interface_ProcessCallGraph_h + +/* + * + */ + +#include +#include +#include +#include + +// boost optional (used by boost graph) results in some false positives with -Wmaybe-uninitialized +#pragma GCC diagnostic push +#pragma GCC diagnostic ignored "-Wmaybe-uninitialized" +#include +#include +#include +#pragma GCC diagnostic pop + +#include "DataFormats/Provenance/interface/ModuleDescription.h" +#include "FWCore/ServiceRegistry/interface/PathsAndConsumesOfModulesBase.h" +#include "FWCore/ServiceRegistry/interface/ProcessContext.h" +#include "HLTrigger/Timer/interface/EDMModuleType.h" + +class ProcessCallGraph { +public: + + struct NodeType { + edm::ModuleDescription module_; + edm::EDMModuleType type_; + bool scheduled_; + }; + + // directed graph, with `NodeType` properties attached to each vertex + using GraphType = boost::subgraph, + // graph properties, used to name each boost::subgraph + boost::property + >>; + + // store the details of each path: name, modules on the path, and their dependencies + struct PathType { + std::string name_; + std::vector modules_on_path_; + std::vector modules_and_dependencies_; + std::vector last_dependency_of_module_; // one-after-the-last dependency of each module, as indices into modules_and_dependencies_ + + PathType() = default; + + PathType(std::string const & name, std::vector const & mop, std::vector const & mad, std::vector const & ldom) : + name_(name), + modules_on_path_(mop), + modules_and_dependencies_(mad), + last_dependency_of_module_(ldom) + { } + + PathType(std::string && name, std::vector && mop, std::vector && mad, std::vector && ldom) : + name_(std::move(name)), + modules_on_path_(std::move(mop)), + modules_and_dependencies_(std::move(mad)), + last_dependency_of_module_(std::move(ldom)) + { } + + PathType(PathType const & other) = default; + + PathType(PathType && other) = default; + + ~PathType() = default; + + PathType & operator=(PathType const & other) = default; + + }; + + // store the details of each process: name, modules call subgraph, modules, paths and endpaths, subprocess pids + struct ProcessType { + std::string name_; + GraphType const & graph_; + std::vector modules_; + std::vector paths_; + std::vector endPaths_; + std::vector subprocesses_; + + ProcessType() = delete; + + ProcessType( + std::string const & name, + GraphType const & graph, + std::vector const & modules, + std::vector const & paths, + std::vector const & endPaths, + std::vector const & subprocesses = {} + ) : + name_(name), + graph_(graph), + modules_(modules), + paths_(paths), + endPaths_(endPaths), + subprocesses_(subprocesses) + { } + + ProcessType( + std::string && name, + GraphType const & graph, + std::vector && modules, + std::vector && paths, + std::vector && endPaths, + std::vector && subprocesses = {} + ) : + name_(std::move(name)), + graph_(graph), + modules_(std::move(modules)), + paths_(std::move(paths)), + endPaths_(std::move(endPaths)), + subprocesses_(std::move(subprocesses)) + { } + + ProcessType(ProcessType const & other) = default; + ProcessType(ProcessType && other) = default; + + ProcessType & operator=(ProcessType const & other) = default; + ProcessType & operator=(ProcessType && other) = default; + }; + +public: + // default c'tor + ProcessCallGraph(); + + // to be called from preSourceConstruction(...) + void preSourceConstruction(edm::ModuleDescription const &); + + // to be called from preBeginJob(...) + void preBeginJob(edm::PathsAndConsumesOfModulesBase const &, edm::ProcessContext const &); + + // number of modules stored in the call graph + unsigned int size() const; + + // retrieve the ModuleDescription associated to the Source + edm::ModuleDescription const & source() const; + + // retrieve the ModuleDescription associated to the given id + edm::ModuleDescription const & module(unsigned int module) const; + + // retrieve the full information for a given module + NodeType const & operator[](unsigned int module) const; + + // find the dependencies of the given module + std::vector depends(unsigned int module) const; + + // find the dependencies of all modules in the given path + std::pair, std::vector> dependencies(std::vector const & path); + + // retrieve the "process id" of a process, given its ProcessContex + unsigned int processId(edm::ProcessContext const &) const; + + // retrieve the "process id" of a process, given its name + unsigned int processId(std::string const &) const; + + // retrieve the processes + std::vector const & processes() const; + + // retrieve information about a process, given its "process id" + ProcessType const & processDescription(unsigned int) const; + + // retrieve information about a process, given its ProcessContex + ProcessType const & processDescription(edm::ProcessContext const &) const; + + // retrieve information about a process, given its name + ProcessType const & processDescription(std::string const &) const; + +private: + + // register a (sub)process and assigns it a "process id" + unsigned int registerProcess(edm::ProcessContext const &); + +private: + + GraphType graph_; + + // module id of the Source + unsigned int source_; + + // map each (sub)process name to a "process id" + std::unordered_map process_id_; + + // description of each process + std::vector process_description_; + +}; + +#endif // not defined HLTrigger_Timer_interface_ProcessCallGraph_h diff --git a/HLTrigger/Timer/plugins/FTSLuminosityFromLumiSummary.cc b/HLTrigger/Timer/plugins/FTSLuminosityFromLumiSummary.cc deleted file mode 100644 index 8273ca0dd049a..0000000000000 --- a/HLTrigger/Timer/plugins/FTSLuminosityFromLumiSummary.cc +++ /dev/null @@ -1,163 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDAnalyzer.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/Framework/interface/EventSetup.h" -#include "FWCore/Framework/interface/ESHandle.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" -#include "DataFormats/Luminosity/interface/LumiSummary.h" -#include "RecoLuminosity/LumiProducer/interface/LumiCorrectionParam.h" - -class FTSLuminosityFromLumiSummary : public edm::global::EDAnalyzer<> { -public: - explicit FTSLuminosityFromLumiSummary(edm::ParameterSet const &); - ~FTSLuminosityFromLumiSummary(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - enum class Type { - InstantaneousLuminosity, - Pileup, - Invalid = -1 - }; - - static Type parse(std::string const & type) { - if (type == "InstantaneousLuminosity") - return Type::InstantaneousLuminosity; - else if (type == "Pileup") - return Type::Pileup; - else - return Type::Invalid; - } - - edm::EDGetTokenT m_token; - double m_cross_section; - Type m_type; - unsigned int m_lumi_id; - std::vector m_value; // values are per-stream, computed in the StreamBeginLuminosityBlock and used in each event - - virtual void preallocStreams(unsigned int size) override; - virtual void doStreamBeginLuminosityBlock_(edm::StreamID id, edm::LuminosityBlock const & lumi, edm::EventSetup const & setup) override; - virtual void analyze(edm::StreamID sid, edm::Event const & event, const edm::EventSetup & setup) const override; -}; - -FTSLuminosityFromLumiSummary::FTSLuminosityFromLumiSummary(edm::ParameterSet const & config) : - m_token(consumes(config.getParameter("source"))), - m_cross_section(config.getParameter("crossSection")), - m_type(parse(config.getParameter("type"))), - m_lumi_id((unsigned int) -1) -{ - if (not edm::Service().isAvailable()) - return; - - std::string const & name = config.getParameter("name"); - std::string const & title = config.getParameter("title"); - std::string const & label = config.getParameter("label"); - double range = config.getParameter("range"); - double resolution = config.getParameter("resolution"); - - m_lumi_id = edm::Service()->reserveLuminosityPlots(name, title, label, range, resolution); -} - -FTSLuminosityFromLumiSummary::~FTSLuminosityFromLumiSummary() -{ -} - -void FTSLuminosityFromLumiSummary::preallocStreams(unsigned int size) -{ - m_value.resize(size, 0.); -} - -void FTSLuminosityFromLumiSummary::doStreamBeginLuminosityBlock_(edm::StreamID sid, edm::LuminosityBlock const & lumi, edm::EventSetup const & setup) -{ - m_value[sid] = 0.; - - edm::ESHandle corrector; - setup.getData(corrector); - if (not corrector.isValid()) { - edm::LogError("FTSLuminosityFromLumiSummary") << "unable to calibrate the raw luminosity values, please add a LumiCorrectionSource ESProducer to your configuration"; - return; - } - - edm::Handle h_summary; - if (lumi.getByToken(m_token, h_summary)) { - double correction = corrector->getCorrection(h_summary->avgInsDelLumi()); - /* - std::cerr << "LumiSummary loaded" << std::endl; - std::cerr << " uncorrected luminosity: " << h_summary->avgInsDelLumi() << std::endl; - std::cerr << " correction factor: " << correction << std::endl; - std::cerr << " corrected luminosity: " << h_summary->avgInsDelLumi() * correction * 1.e30 << std::endl; - std::cerr << " integrated luminosity: " << h_summary->intgDelLumi() * correction * 1.e30 << std::endl; - std::cerr << " colliding bunches: " << corrector->ncollidingbunches() << std::endl; - std::cerr << " orbits: " << h_summary->numOrbit() << std::endl; - std::cerr << " pileup: " << h_summary->intgDelLumi() * correction * m_cross_section * 1.e3 / h_summary->numOrbit() / corrector->ncollidingbunches() << std::endl; - */ - switch (m_type) { - case Type::InstantaneousLuminosity: - m_value[sid] = h_summary->avgInsDelLumi() * correction * 1.e30; - break; - case Type::Pileup: - // integrated luminosity [nb-1] * pp cross section [mb] * 10^6 nb/mb / 2^18 orbits / number of colliding bunches - m_value[sid] = h_summary->intgDelLumi() * correction * m_cross_section * 1.e3 / h_summary->numOrbit() / corrector->ncollidingbunches(); - break; - case Type::Invalid: - m_value[sid] = 0.; - break; - } - } -} - -void -FTSLuminosityFromLumiSummary::analyze(edm::StreamID sid, edm::Event const & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return; - - edm::Service()->setLuminosity(sid, m_lumi_id, m_value[sid]); -} - -void -FTSLuminosityFromLumiSummary::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - // instantaneous luminosity - { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("lumiProducer")); - desc.add("crossSection", 69.3); - desc.add("type", "InstantaneousLuminosity"); - desc.add("name", "luminosity"); - desc.add("title", "instantaneous luminosity"); - desc.add("label", "instantaneous luminosity [cm^{-2}s^{-1}]"); - desc.add("range", 8.e33); - desc.add("resolution", 1.e31); - descriptions.add("ftsLuminosityFromLumiSummary", desc); - } - // pileup - { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("lumiProducer")); - desc.add("crossSection", 69.3); - desc.add("type", "Pileup"); - desc.add("name", "pileup"); - desc.add("title", "pileup"); - desc.add("label", "pileup"); - desc.add("range", 40); - desc.add("resolution", 1); - descriptions.add("ftsPileupFromLumiSummary", desc); - } -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FTSLuminosityFromLumiSummary); diff --git a/HLTrigger/Timer/plugins/FTSLuminosityFromPileupSummaryInfo.cc b/HLTrigger/Timer/plugins/FTSLuminosityFromPileupSummaryInfo.cc deleted file mode 100644 index f6604ce214aa7..0000000000000 --- a/HLTrigger/Timer/plugins/FTSLuminosityFromPileupSummaryInfo.cc +++ /dev/null @@ -1,91 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDAnalyzer.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" -#include "SimDataFormats/PileupSummaryInfo/interface/PileupSummaryInfo.h" - -class FTSLuminosityFromPileupSummaryInfo : public edm::global::EDAnalyzer<> { -public: - explicit FTSLuminosityFromPileupSummaryInfo(edm::ParameterSet const &); - ~FTSLuminosityFromPileupSummaryInfo(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - edm::EDGetTokenT> m_token; - unsigned int m_lumi_id; - - void analyze(edm::StreamID sid, edm::Event const & event, const edm::EventSetup & setup) const override; -}; - -FTSLuminosityFromPileupSummaryInfo::FTSLuminosityFromPileupSummaryInfo(edm::ParameterSet const & config) : - m_token(consumes>(config.getParameter("source"))), - m_lumi_id((unsigned int) -1) -{ - if (not edm::Service().isAvailable()) - return; - - std::string const & name = config.getParameter("name"); - std::string const & title = config.getParameter("title"); - std::string const & label = config.getParameter("label"); - double range = config.getParameter("range"); - double resolution = config.getParameter("resolution"); - - m_lumi_id = edm::Service()->reserveLuminosityPlots(name, title, label, range, resolution); -} - -FTSLuminosityFromPileupSummaryInfo::~FTSLuminosityFromPileupSummaryInfo() -{ -} - -void -FTSLuminosityFromPileupSummaryInfo::analyze(edm::StreamID sid, edm::Event const & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return; - - double value = 0.; - edm::Handle> h_summary; - if (event.getByToken(m_token, h_summary)) { - for (PileupSummaryInfo const & pileup: *h_summary) { - // only use the in-time pileup - if (pileup.getBunchCrossing() == 0) { - // use the per-event in-time pileup - value = pileup.getPU_NumInteractions(); - // use the average pileup - // value = pileup.getTrueNumInteractions(); - break; - } - } - } - - edm::Service()->setLuminosity(sid, m_lumi_id, value); -} - -void -FTSLuminosityFromPileupSummaryInfo::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("addPileupInfo")); - desc.add("name", "pileup"); - desc.add("title", "in-time pileup"); - desc.add("label", "in-time pileup"); - desc.add("range", 40); - desc.add("resolution", 1); - descriptions.add("ftsLuminosityFromPileupSummaryInfo", desc); -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FTSLuminosityFromPileupSummaryInfo); diff --git a/HLTrigger/Timer/plugins/FTSLuminosityFromPixelClusters.cc b/HLTrigger/Timer/plugins/FTSLuminosityFromPixelClusters.cc deleted file mode 100644 index c61a8e9b42160..0000000000000 --- a/HLTrigger/Timer/plugins/FTSLuminosityFromPixelClusters.cc +++ /dev/null @@ -1,81 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDAnalyzer.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" -#include "DataFormats/SiPixelCluster/interface/SiPixelCluster.h" - -class FTSLuminosityFromPixelClusters : public edm::global::EDAnalyzer<> { -public: - explicit FTSLuminosityFromPixelClusters(edm::ParameterSet const &); - ~FTSLuminosityFromPixelClusters(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - edm::EDGetTokenT m_token; - unsigned int m_lumi_id; - - void analyze(edm::StreamID sid, edm::Event const & event, const edm::EventSetup & setup) const override; -}; - -FTSLuminosityFromPixelClusters::FTSLuminosityFromPixelClusters(edm::ParameterSet const & config) : - m_token(consumes(config.getParameter("source"))), - m_lumi_id((unsigned int) -1) -{ - if (not edm::Service().isAvailable()) - return; - - std::string const & name = config.getParameter("name"); - std::string const & title = config.getParameter("title"); - std::string const & label = config.getParameter("label"); - double range = config.getParameter("range"); - double resolution = config.getParameter("resolution"); - - m_lumi_id = edm::Service()->reserveLuminosityPlots(name, title, label, range, resolution); -} - -FTSLuminosityFromPixelClusters::~FTSLuminosityFromPixelClusters() -{ -} - -void -FTSLuminosityFromPixelClusters::analyze(edm::StreamID sid, edm::Event const & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return; - - double value = 0.; - edm::Handle h_clusters; - if (event.getByToken(m_token, h_clusters)) - value = h_clusters->dataSize(); - - edm::Service()->setLuminosity(sid, m_lumi_id, value); -} - -void -FTSLuminosityFromPixelClusters::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("siPixelClusters")); - desc.add("name", "clusters"); - desc.add("title", "pixel clusters"); - desc.add("label", "pixel clusters"); - desc.add("range", 20000); - desc.add("resolution", 500); - descriptions.add("ftsLuminosityFromPixelClusters", desc); -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FTSLuminosityFromPixelClusters); diff --git a/HLTrigger/Timer/plugins/FTSLuminosityFromScalers.cc b/HLTrigger/Timer/plugins/FTSLuminosityFromScalers.cc deleted file mode 100644 index 719d207bc4d4b..0000000000000 --- a/HLTrigger/Timer/plugins/FTSLuminosityFromScalers.cc +++ /dev/null @@ -1,125 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDAnalyzer.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" -#include "DataFormats/Scalers/interface/LumiScalers.h" - -class FTSLuminosityFromScalers : public edm::global::EDAnalyzer<> { -public: - explicit FTSLuminosityFromScalers(edm::ParameterSet const &); - ~FTSLuminosityFromScalers(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - enum class Type { - InstantaneousLuminosity, - Pileup, - Invalid = -1 - }; - - static Type parse(std::string const & type) { - if (type == "InstantaneousLuminosity") - return Type::InstantaneousLuminosity; - else if (type == "Pileup") - return Type::Pileup; - else - return Type::Invalid; - } - - edm::EDGetTokenT m_token; - Type m_type; - unsigned int m_lumi_id; - - void analyze(edm::StreamID sid, edm::Event const & event, const edm::EventSetup & setup) const override; -}; - -FTSLuminosityFromScalers::FTSLuminosityFromScalers(edm::ParameterSet const & config) : - m_token(consumes(config.getParameter("source"))), - m_type(parse(config.getParameter("type"))), - m_lumi_id((unsigned int) -1) -{ - if (not edm::Service().isAvailable()) - return; - - std::string const & name = config.getParameter("name"); - std::string const & title = config.getParameter("title"); - std::string const & label = config.getParameter("label"); - double range = config.getParameter("range"); - double resolution = config.getParameter("resolution"); - - m_lumi_id = edm::Service()->reserveLuminosityPlots(name, title, label, range, resolution); -} - -FTSLuminosityFromScalers::~FTSLuminosityFromScalers() -{ -} - -void -FTSLuminosityFromScalers::analyze(edm::StreamID sid, edm::Event const & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return; - - double value = 0.; - edm::Handle h_luminosity; - if (event.getByToken(m_token, h_luminosity) and not h_luminosity->empty()) { - switch (m_type) { - case Type::InstantaneousLuminosity: - value = h_luminosity->front().instantLumi() * 1.e30; - break; - case Type::Pileup: - value = h_luminosity->front().pileup(); - break; - case Type::Invalid: - value = 0.; - break; - } - } - - edm::Service()->setLuminosity(sid, m_lumi_id, value); -} - -void -FTSLuminosityFromScalers::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - // instantaneous luminosity - { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("scalersRawToDigi")); - desc.add("type", "InstantaneousLuminosity"); - desc.add("name", "luminosity"); - desc.add("title", "instantaneous luminosity"); - desc.add("label", "instantaneous luminosity [cm^{-2}s^{-1}]"); - desc.add("range", 8.e33); - desc.add("resolution", 1.e31); - descriptions.add("ftsLuminosityFromScalers", desc); - } - // pileup - { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("scalersRawToDigi")); - desc.add("type", "Pileup"); - desc.add("name", "pileup"); - desc.add("title", "pileup"); - desc.add("label", "pileup"); - desc.add("range", 40); - desc.add("resolution", 1); - descriptions.add("ftsPileupFromScalers", desc); - } -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FTSLuminosityFromScalers); diff --git a/HLTrigger/Timer/plugins/FTSLuminosityFromVertices.cc b/HLTrigger/Timer/plugins/FTSLuminosityFromVertices.cc deleted file mode 100644 index 801e08d3a2368..0000000000000 --- a/HLTrigger/Timer/plugins/FTSLuminosityFromVertices.cc +++ /dev/null @@ -1,82 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDAnalyzer.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" -#include "DataFormats/VertexReco/interface/Vertex.h" -#include "DataFormats/VertexReco/interface/VertexFwd.h" - -class FTSLuminosityFromVertices : public edm::global::EDAnalyzer<> { -public: - explicit FTSLuminosityFromVertices(edm::ParameterSet const &); - ~FTSLuminosityFromVertices(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - edm::EDGetTokenT m_token; - unsigned int m_lumi_id; - - void analyze(edm::StreamID sid, edm::Event const & event, const edm::EventSetup & setup) const override; -}; - -FTSLuminosityFromVertices::FTSLuminosityFromVertices(edm::ParameterSet const & config) : - m_token(consumes(config.getParameter("source"))), - m_lumi_id((unsigned int) -1) -{ - if (not edm::Service().isAvailable()) - return; - - std::string const & name = config.getParameter("name"); - std::string const & title = config.getParameter("title"); - std::string const & label = config.getParameter("label"); - double range = config.getParameter("range"); - double resolution = config.getParameter("resolution"); - - m_lumi_id = edm::Service()->reserveLuminosityPlots(name, title, label, range, resolution); -} - -FTSLuminosityFromVertices::~FTSLuminosityFromVertices() -{ -} - -void -FTSLuminosityFromVertices::analyze(edm::StreamID sid, edm::Event const & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return; - - double value = 0.; - edm::Handle collection; - if (event.getByToken(m_token, collection)) - value = collection->size(); - - edm::Service()->setLuminosity(sid, m_lumi_id, value); -} - -void -FTSLuminosityFromVertices::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - edm::ParameterSetDescription desc; - desc.add("source", edm::InputTag("siPixelClusters")); - desc.add("name", "vertices"); - desc.add("title", "reconstructed vertices"); - desc.add("label", "reconstructed vertices"); - desc.add("range", 40); - desc.add("resolution", 1); - descriptions.add("ftsLuminosityFromVertices", desc); -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FTSLuminosityFromVertices); diff --git a/HLTrigger/Timer/plugins/FastTimerFilter.cc b/HLTrigger/Timer/plugins/FastTimerFilter.cc deleted file mode 100644 index 221e907bebcc4..0000000000000 --- a/HLTrigger/Timer/plugins/FastTimerFilter.cc +++ /dev/null @@ -1,76 +0,0 @@ -// C++ headers -#include -#include - -// CMSSW headers -#include "FWCore/Framework/interface/Frameworkfwd.h" -#include "FWCore/Framework/interface/global/EDFilter.h" -#include "FWCore/Framework/interface/Event.h" -#include "FWCore/Framework/interface/Run.h" -#include "FWCore/Framework/interface/LuminosityBlock.h" -#include "FWCore/ParameterSet/interface/ParameterSet.h" -#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" -#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" -#include "FWCore/ParameterSet/interface/Registry.h" -#include "FWCore/ServiceRegistry/interface/Service.h" -#include "HLTrigger/Timer/interface/FastTimerService.h" - -class FastTimerFilter : public edm::global::EDFilter<> { -public: - explicit FastTimerFilter(edm::ParameterSet const &); - ~FastTimerFilter(); - - static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - -private: - const double m_time_limit_event; - const double m_time_limit_path; - const double m_time_limit_allpaths; - - bool filter(edm::StreamID sid, edm::Event & event, const edm::EventSetup & setup) const override; -}; - -FastTimerFilter::FastTimerFilter(edm::ParameterSet const & config) : - m_time_limit_event( config.getParameter( "timeLimitPerEvent" )), - m_time_limit_path( config.getParameter( "timeLimitPerPath" )), - m_time_limit_allpaths( config.getParameter( "timeLimitPerAllPaths" )) -{ -} - -FastTimerFilter::~FastTimerFilter() -{ -} - -bool -FastTimerFilter::filter(edm::StreamID sid, edm::Event & event, edm::EventSetup const & setup) const -{ - if (not edm::Service().isAvailable()) - return false; - - /* FIXME re-enable - FastTimerService const & fts = * edm::Service(); - if (m_time_limit_allpaths > 0. and fts.queryPathsTime(sid) > m_time_limit_allpaths) - return true; - if (m_time_limit_event > 0. and fts.currentEventTime(sid) > m_time_limit_event) - return true; - if (m_time_limit_path > 0. and fts.currentPathTime(sid) > m_time_limit_path) - return true; - */ - - return false; -} - -void -FastTimerFilter::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - // The following says we do not know what parameters are allowed so do no validation - // Please change this to state exactly what you do use, even if it is no parameters - edm::ParameterSetDescription desc; - desc.add("timeLimitPerEvent", 0.); - desc.add("timeLimitPerPath", 0.); - desc.add("timeLimitPerAllPaths", 120.); - descriptions.addDefault(desc); -} - -//define this as a plug-in -#include "FWCore/Framework/interface/MakerMacros.h" -DEFINE_FWK_MODULE(FastTimerFilter); diff --git a/HLTrigger/Timer/plugins/ThroughputService.cc b/HLTrigger/Timer/plugins/ThroughputService.cc index 04efe2beab523..fc8636c5060b6 100644 --- a/HLTrigger/Timer/plugins/ThroughputService.cc +++ b/HLTrigger/Timer/plugins/ThroughputService.cc @@ -43,7 +43,7 @@ ThroughputService::preallocate(edm::service::SystemBounds const & bounds) m_stream_histograms.resize( bounds.maxNumberOfStreams() ); - // assign a pseudo module id to the FastTimerService + // assign a pseudo module id to the ThroughputService m_module_id = edm::ModuleDescription::getUniqueID(); } diff --git a/HLTrigger/Timer/plugins/ThroughputService.h b/HLTrigger/Timer/plugins/ThroughputService.h index ba8a8ec2bbd33..89660ea685097 100644 --- a/HLTrigger/Timer/plugins/ThroughputService.h +++ b/HLTrigger/Timer/plugins/ThroughputService.h @@ -24,7 +24,6 @@ #include "DataFormats/Provenance/interface/EventID.h" #include "DataFormats/Provenance/interface/Timestamp.h" #include "DataFormats/Provenance/interface/ModuleDescription.h" -#include "HLTrigger/Timer/interface/FastTimer.h" class ThroughputService { public: @@ -64,7 +63,7 @@ class ThroughputService { double m_time_resolution; // DQM service-related data members - unsigned int m_module_id; // pseudo module id for the FastTimerService, needed by the thread-safe DQMStore + unsigned int m_module_id; // pseudo module id for the ThroughputService, needed by the thread-safe DQMStore std::string m_dqm_path; }; diff --git a/HLTrigger/Timer/src/EDMModuleType.cc b/HLTrigger/Timer/src/EDMModuleType.cc new file mode 100644 index 0000000000000..3fb45b796e394 --- /dev/null +++ b/HLTrigger/Timer/src/EDMModuleType.cc @@ -0,0 +1,40 @@ +#include + +#include "DataFormats/Provenance/interface/ModuleDescription.h" +#include "FWCore/ParameterSet/interface/ParameterSet.h" +#include "FWCore/ParameterSet/interface/Registry.h" +#include "HLTrigger/Timer/interface/EDMModuleType.h" + +namespace edm { + +EDMModuleType edmModuleTypeEnum(edm::ModuleDescription const & module) +{ + auto const & registry = * edm::pset::Registry::instance(); + auto const & pset = * registry.getMapped(module.parameterSetID()); + + if (not pset.existsAs("@module_edm_type")) + return EDMModuleType::kUnknown; + + std::string const & t = pset.getParameter("@module_edm_type"); + for (EDMModuleType v: { + EDMModuleType::kSource, + EDMModuleType::kESSource, + EDMModuleType::kESProducer, + EDMModuleType::kEDAnalyzer, + EDMModuleType::kEDProducer, + EDMModuleType::kEDFilter, + EDMModuleType::kOutputModule + }) { + if (t == module_type_desc[static_cast>(v)]) + return v; + } + return EDMModuleType::kUnknown; +} + + +const char * edmModuleType(edm::ModuleDescription const & module) +{ + return module_type_desc[static_cast>(edmModuleTypeEnum(module))]; +} + +} // namespace edm diff --git a/HLTrigger/Timer/src/FastTimer.cc b/HLTrigger/Timer/src/FastTimer.cc deleted file mode 100644 index 3d2297a5097fa..0000000000000 --- a/HLTrigger/Timer/src/FastTimer.cc +++ /dev/null @@ -1,136 +0,0 @@ -// C++ headers -#include -#include -#include -#include - -#include "HLTrigger/Timer/interface/FastTimer.h" - -FastTimer::FastTimer() : - m_start(), - m_stop(), - m_duration(Duration::zero()), - m_state(State::kStopped) -{ } - -// start the timer - only if it was not running -void FastTimer::start() { - if (m_state == State::kStopped) { - m_start = Clock::now(); - m_stop = Clock::time_point(); - m_duration = Duration::zero(); - m_state = State::kRunning; - } else { - std::cerr << "attempting to start a " << describe() << " timer" << std::endl; - } -} - -// stop the timer - only if it was running -void FastTimer::stop() { - if (m_state == State::kRunning) { - m_stop = Clock::now(); - m_duration += std::chrono::duration_cast(m_stop - m_start); - m_state = State::kStopped; - } else { - std::cerr << "attempting to stop a " << describe() << " timer" << std::endl; - } -} - -// pause the timer - only if it was running -void FastTimer::pause() { - if (m_state == State::kRunning) { - m_stop = Clock::now(); - m_duration += std::chrono::duration_cast(m_stop - m_start); - m_state = State::kPaused; - } else { - std::cerr << "attempting to pause a " << describe() << " timer" << std::endl; - } -} - -// resume the timer - only if it was not running -void FastTimer::resume() { - if (m_state == State::kPaused) { - m_start = Clock::now(); - m_stop = Clock::time_point(); - m_state = State::kRunning; - } else { - std::cerr << "attempting to resume a " << describe() << " timer" << std::endl; - } -} - -// reset the timer -void FastTimer::reset() { - m_start = Clock::time_point(); - m_stop = Clock::time_point(); - m_duration = Duration::zero(); - m_state = State::kStopped; -} - -// read the accumulated time -FastTimer::Duration FastTimer::value() const { - return m_duration; -} - -// read the accumulated time, in seconds -double FastTimer::seconds() const { - return std::chrono::duration_cast>(m_duration).count(); -} - -// if the timer is stopped, read the accumulate time -// if the timer is running, also add the time up to "now" -FastTimer::Duration FastTimer::untilNow() const { - return m_duration + ( (m_state == State::kRunning) ? std::chrono::duration_cast(Clock::now() - m_start) : Duration::zero() ); -} - -double FastTimer::secondsUntilNow() const { - return std::chrono::duration_cast>(untilNow()).count(); -} - -// return the current state -FastTimer::State FastTimer::state() const { - return m_state; -} - -// descrbe the current state -std::string const & FastTimer::describe() const { - static const std::vector states{ "stopped", "running", "paused", "unknown" }; - - switch (m_state) { - case FastTimer::State::kStopped: - case FastTimer::State::kRunning: - case FastTimer::State::kPaused: - return states[static_cast(m_state)]; - - default: - return states.back(); - } -} - -FastTimer::Clock::time_point const & FastTimer::getStartTime() const { - return m_start; -} - -FastTimer::Clock::time_point const & FastTimer::getStopTime() const { - return m_stop; -} - -void FastTimer::setStartTime(FastTimer::Clock::time_point const & time) { - if (m_state == State::kStopped) { - m_start = time; - m_stop = Clock::time_point(); - m_duration = Duration::zero(); - m_state = State::kRunning; - } else { - std::cerr << "attempting to start a " << describe() << " timer" << std::endl; - } -} - -void FastTimer::setStopTime(FastTimer::Clock::time_point const & time) { - if (m_state == State::kRunning) { - m_stop = time; - m_duration += std::chrono::duration_cast(m_stop - m_start); - m_state = State::kStopped; - } else { - std::cerr << "attempting to stop a " << describe() << " timer" << std::endl; - } -} diff --git a/HLTrigger/Timer/src/FastTimerService.cc b/HLTrigger/Timer/src/FastTimerService.cc index d5621e2103adb..6dd044fbc6150 100644 --- a/HLTrigger/Timer/src/FastTimerService.cc +++ b/HLTrigger/Timer/src/FastTimerService.cc @@ -15,9 +15,7 @@ // boost headers #include - -// tbb headers -#include +#include // CMSSW headers #include "FWCore/ParameterSet/interface/ParameterSet.h" @@ -38,1425 +36,1607 @@ #include "HLTrigger/Timer/interface/FastTimerService.h" -FastTimerService::FastTimerService(const edm::ParameterSet & config, edm::ActivityRegistry & registry) : - // configuration - // FIXME - reimplement support for cpu time vs. real time - m_use_realtime( config.getUntrackedParameter( "useRealTimeClock" ) ), - m_enable_timing_paths( config.getUntrackedParameter( "enableTimingPaths" ) ), - m_enable_timing_modules( config.getUntrackedParameter( "enableTimingModules" ) ), - m_enable_timing_exclusive( config.getUntrackedParameter( "enableTimingExclusive" ) ), - m_enable_timing_summary( config.getUntrackedParameter( "enableTimingSummary" ) ), - m_skip_first_path( config.getUntrackedParameter( "skipFirstPath" ) ), - // dqm configuration - m_enable_dqm( config.getUntrackedParameter( "enableDQM" ) ), - m_enable_dqm_bypath_active( config.getUntrackedParameter( "enableDQMbyPathActive" ) ), - m_enable_dqm_bypath_total( config.getUntrackedParameter( "enableDQMbyPathTotal" ) ), - m_enable_dqm_bypath_overhead( config.getUntrackedParameter( "enableDQMbyPathOverhead" ) ), - m_enable_dqm_bypath_details( config.getUntrackedParameter( "enableDQMbyPathDetails" ) ), - m_enable_dqm_bypath_counters( config.getUntrackedParameter( "enableDQMbyPathCounters" ) ), - m_enable_dqm_bypath_exclusive( config.getUntrackedParameter( "enableDQMbyPathExclusive" ) ), - m_enable_dqm_bymodule( config.getUntrackedParameter( "enableDQMbyModule" ) ), - m_enable_dqm_bymoduletype( config.getUntrackedParameter( "enableDQMbyModuleType" ) ), - m_enable_dqm_summary( config.getUntrackedParameter( "enableDQMSummary" ) ), - m_enable_dqm_byls( config.getUntrackedParameter( "enableDQMbyLumiSection" ) ), - m_enable_dqm_bynproc( config.getUntrackedParameter( "enableDQMbyProcesses" ) ), - // job configuration - m_concurrent_runs( 0 ), - m_concurrent_streams( 0 ), - m_concurrent_threads( 0 ), - m_module_id( edm::ModuleDescription::invalidID() ), - m_dqm_eventtime_range( config.getUntrackedParameter( "dqmTimeRange" ) ), // ms - m_dqm_eventtime_resolution( config.getUntrackedParameter( "dqmTimeResolution" ) ), // ms - m_dqm_pathtime_range( config.getUntrackedParameter( "dqmPathTimeRange" ) ), // ms - m_dqm_pathtime_resolution( config.getUntrackedParameter( "dqmPathTimeResolution" ) ), // ms - m_dqm_moduletime_range( config.getUntrackedParameter( "dqmModuleTimeRange" ) ), // ms - m_dqm_moduletime_resolution( config.getUntrackedParameter( "dqmModuleTimeResolution" ) ), // ms - m_dqm_path( config.getUntrackedParameter("dqmPath" ) ), - // description of the process(es) - m_process(), - // description of the luminosity axes - m_dqm_luminosity(), - // DQM - these are initialized at preStreamBeginRun(), to make sure the DQM service has been loaded - m_stream(), - // summary data - m_run_summary(), - m_job_summary(), - m_run_summary_perprocess(), - m_job_summary_perprocess() -{ - // enable timers if required by DQM plots - m_enable_timing_paths = m_enable_timing_paths or - m_enable_dqm_bypath_active or - m_enable_dqm_bypath_total or - m_enable_dqm_bypath_overhead or - m_enable_dqm_bypath_details or - m_enable_dqm_bypath_counters or - m_enable_dqm_bypath_exclusive; - - m_enable_timing_modules = m_enable_timing_modules or - m_enable_dqm_bymodule or - m_enable_dqm_bymoduletype or - m_enable_dqm_bypath_total or - m_enable_dqm_bypath_overhead or - m_enable_dqm_bypath_details or - m_enable_dqm_bypath_counters or - m_enable_dqm_bypath_exclusive; - - m_enable_timing_exclusive = m_enable_timing_exclusive or - m_enable_dqm_bypath_exclusive; - - - registry.watchPreallocate( this, & FastTimerService::preallocate ); - registry.watchPreModuleBeginJob( this, & FastTimerService::preModuleBeginJob ); - registry.watchPreGlobalBeginRun( this, & FastTimerService::preGlobalBeginRun ); - registry.watchPreStreamBeginRun( this, & FastTimerService::preStreamBeginRun ); - registry.watchPostStreamBeginRun( this, & FastTimerService::postStreamBeginRun ); - registry.watchPostStreamEndRun( this, & FastTimerService::postStreamEndRun ); - registry.watchPostStreamBeginLumi(this, & FastTimerService::postStreamBeginLumi ); - registry.watchPostStreamEndLumi( this, & FastTimerService::postStreamEndLumi ); - registry.watchPostEndJob( this, & FastTimerService::postEndJob ); - registry.watchPostGlobalEndRun( this, & FastTimerService::postGlobalEndRun ); - registry.watchPreSourceEvent( this, & FastTimerService::preSourceEvent ); - registry.watchPostSourceEvent( this, & FastTimerService::postSourceEvent ); - registry.watchPreEvent( this, & FastTimerService::preEvent ); - registry.watchPostEvent( this, & FastTimerService::postEvent ); - /* Disable until can handle more than one thread per event - // watch per-path events - registry.watchPrePathEvent( this, & FastTimerService::prePathEvent ); - registry.watchPostPathEvent( this, & FastTimerService::postPathEvent ); - // watch per-module events if enabled - if (m_enable_timing_modules) { - registry.watchPreModuleEvent( this, & FastTimerService::preModuleEvent ); - registry.watchPostModuleEvent( this, & FastTimerService::postModuleEvent ); - registry.watchPreModuleEventDelayedGet( this, & FastTimerService::preModuleEventDelayedGet ); - registry.watchPostModuleEventDelayedGet( this, & FastTimerService::postModuleEventDelayedGet ); +/////////////////////////////////////////////////////////////////////////////// + +namespace { + + // convert any std::chrono::duration to milliseconds + template + double ms(std::chrono::duration duration) + { + return std::chrono::duration_cast>(duration).count();; + } + + // convert any boost::chrono::duration to milliseconds + template + double ms(boost::chrono::duration duration) + { + return boost::chrono::duration_cast>(duration).count();; } - */ - // if requested, reserve plots for timing vs. lumisection - // there is no need to store the id, as it wil always be 0 - if (m_enable_dqm_byls) - reserveLuminosityPlots("ls", "lumisection", "lumisection", config.getUntrackedParameter("dqmLumiSectionsRange"), 1.); +} // namespace + +/////////////////////////////////////////////////////////////////////////////// + +// resources being monitored by the service + +// Resources +FastTimerService::Resources::Resources() : + time_thread(boost::chrono::nanoseconds::zero()), + time_real(boost::chrono::nanoseconds::zero()) +{ } + +void +FastTimerService::Resources::reset() { + time_thread = boost::chrono::nanoseconds::zero(); + time_real = boost::chrono::nanoseconds::zero(); } -FastTimerService::~FastTimerService() -{ +FastTimerService::Resources & +FastTimerService::Resources::operator+=(Resources const& other) { + time_thread += other.time_thread; + time_real += other.time_real; + return *this; } -// reserve plots for timing vs. luminosity -unsigned int FastTimerService::reserveLuminosityPlots(std::string const & name, std::string const & title, std::string const & label, double range, double resolution) -{ - // FIXME check that this is only called before any preStreamBeginRun - // FIXME check that this is not called with the same "name" twice - m_dqm_luminosity.push_back(LuminosityDescription(name, title, label, range, resolution)); +FastTimerService::Resources +FastTimerService::Resources::operator+(Resources const& other) const { + Resources result(*this); + result += other; + return result; +} + +// ResourcesPerModule + +FastTimerService::ResourcesPerModule::ResourcesPerModule() + = default; - // resize the luminosity per event buffer - for (auto & stream: m_stream) - stream.luminosity.resize(m_dqm_luminosity.size(), 0); +void +FastTimerService::ResourcesPerModule::reset() { + total.reset(); + events = 0; +} - return m_dqm_luminosity.size() - 1; +FastTimerService::ResourcesPerModule & +FastTimerService::ResourcesPerModule::operator+=(ResourcesPerModule const& other) { + total += other.total; + events += other.events; + return *this; } -unsigned int FastTimerService::reserveLuminosityPlots(std::string && name, std::string && title, std::string && label, double range, double resolution) -{ - // FIXME check that this is only called before any preStreamBeginRun - // FIXME check that this is not called with the same "name" twice - m_dqm_luminosity.push_back(LuminosityDescription(name, title, label, range, resolution)); +FastTimerService::ResourcesPerModule +FastTimerService::ResourcesPerModule::operator+(ResourcesPerModule const& other) const { + ResourcesPerModule result(*this); + result += other; + return result; +} - // resize the luminosity per event buffer - for (auto & stream: m_stream) - stream.luminosity.resize(m_dqm_luminosity.size(), 0); - return m_dqm_luminosity.size() - 1; +// ResourcesPerPath + +FastTimerService::ResourcesPerPath::ResourcesPerPath() + = default; + +void +FastTimerService::ResourcesPerPath::reset() { + active.reset(); + total.reset(); + last = 0; + status = false; } -// set the event luminosity -void FastTimerService::setLuminosity(unsigned int stream_id, unsigned int luminosity_id, double value) -{ - // FIXME check that the luminosity id is valid ? - m_stream[stream_id].luminosity[luminosity_id] = value; +FastTimerService::ResourcesPerPath & +FastTimerService::ResourcesPerPath::operator+=(ResourcesPerPath const& other) { + active += other.active; + total += other.total; + last = 0; // summing these makes no sense, reset them instead + status = false; + return *this; } -void FastTimerService::preGlobalBeginRun(edm::GlobalContext const & gc) -{ - unsigned int pid = processID(gc.processContext()); - unsigned int rid = gc.runIndex(); +FastTimerService::ResourcesPerPath +FastTimerService::ResourcesPerPath::operator+(ResourcesPerPath const& other) const { + ResourcesPerPath result(*this); + result += other; + return result; +} - edm::service::TriggerNamesService & tns = * edm::Service(); - uint32_t size_p = tns.getTrigPaths().size(); - uint32_t size_e = tns.getEndPaths().size(); - uint32_t size = size_p + size_e; - // resize the path maps - for (auto & stream: m_stream) - if (stream.paths.size() <= pid) - stream.paths.resize(pid+1); - for (uint32_t i = 0; i < size_p; ++i) { - std::string const & label = tns.getTrigPath(i); - for (auto & stream: m_stream) - stream.paths[pid][label].index = i; - } - for (uint32_t i = 0; i < size_e; ++i) { - std::string const & label = tns.getEndPath(i); - for (auto & stream: m_stream) - stream.paths[pid][label].index = size_p + i; - } - for (auto & stream: m_stream) { - // resize the stream buffers to account the number of subprocesses - if (stream.timing_perprocess.size() <= pid) - stream.timing_perprocess.resize(pid+1); - stream.timing_perprocess[pid].paths_interpaths.assign(size + 1, 0.); - // resize the stream plots to account the number of subprocesses - if (stream.dqm_perprocess.size() <= pid) - stream.dqm_perprocess.resize(pid+1); - if (stream.dqm_perprocess_byluminosity.size() <= pid) - stream.dqm_perprocess_byluminosity.resize(pid+1); - if (stream.dqm_paths.size() <= pid) - stream.dqm_paths.resize(pid+1); - } - for (auto & summary: m_run_summary_perprocess) { - if (summary.size() <= pid) - summary.resize(pid+1); - summary[pid].paths_interpaths.assign(size + 1, 0); - } - if (m_job_summary_perprocess.size() <= pid) - m_job_summary_perprocess.resize(pid+1); - m_job_summary_perprocess[pid].paths_interpaths.assign(size + 1, 0.); +// ResourcesPerProcess - // reset the run summaries - if (pid == 0) - m_run_summary[rid].reset(); - m_run_summary_perprocess[rid][pid].reset(); +FastTimerService::ResourcesPerProcess::ResourcesPerProcess(ProcessCallGraph::ProcessType const& process) : + total(), + paths(process.paths_.size()), + endpaths(process.endPaths_.size()) +{ +} - // associate to each path all the modules it contains - for (uint32_t i = 0; i < tns.getTrigPaths().size(); ++i) - fillPathMap( pid, tns.getTrigPath(i), tns.getTrigPathModules(i) ); - for (uint32_t i = 0; i < tns.getEndPaths().size(); ++i) - fillPathMap( pid, tns.getEndPath(i), tns.getEndPathModules(i) ); +void +FastTimerService::ResourcesPerProcess::reset() { + total.reset(); + for (auto & path: paths) + path.reset(); + for (auto & path: endpaths) + path.reset(); +} - // cache the names of the process, and of first and last non-empty path and endpath - if (m_process.size() <= pid) - m_process.resize(pid+1); - m_process[pid].name = gc.processContext()->processName(); - std::tie(m_process[pid].first_path, m_process[pid].last_path) = findFirstLast(pid, tns.getTrigPaths(), m_skip_first_path and pid == 0); - std::tie(m_process[pid].first_endpath, m_process[pid].last_endpath) = findFirstLast(pid, tns.getEndPaths()); +FastTimerService::ResourcesPerProcess & +FastTimerService::ResourcesPerProcess::operator+=(ResourcesPerProcess const& other) { + total += other.total; + assert(paths.size() == other.paths.size()); + for (unsigned int i: boost::irange(0ul, paths.size())) + paths[i] += other.paths[i]; + assert(endpaths.size() == other.endpaths.size()); + for (unsigned int i: boost::irange(0ul, endpaths.size())) + endpaths[i] += other.endpaths[i]; + return *this; } -void FastTimerService::preStreamBeginRun(edm::StreamContext const & sc) -{ - std::string const & process_name = sc.processContext()->processName(); - unsigned int pid = processID(sc.processContext()); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; +FastTimerService::ResourcesPerProcess +FastTimerService::ResourcesPerProcess::operator+(ResourcesPerProcess const& other) const { + ResourcesPerProcess result(*this); + result += other; + return result; +} - if (not m_enable_dqm) - return; - if (not edm::Service().isAvailable()) { - // the DQMStore is not available, disable all DQM plots - m_enable_dqm = false; - return; - } +// ResourcesPerJob - edm::service::TriggerNamesService & tns = * edm::Service(); - uint32_t size_p = tns.getTrigPaths().size(); - uint32_t size_e = tns.getEndPaths().size(); - uint32_t size = size_p + size_e; - - int eventbins = (int) std::ceil(m_dqm_eventtime_range / m_dqm_eventtime_resolution); - int pathbins = (int) std::ceil(m_dqm_pathtime_range / m_dqm_pathtime_resolution); - int modulebins = (int) std::ceil(m_dqm_moduletime_range / m_dqm_moduletime_resolution); - - // define a callback that can book the histograms - auto bookTransactionCallback = [&, this] (DQMStore::IBooker & booker) { - - // event summary plots - if (m_enable_dqm_summary) { - // whole event - if (pid == 0) { - booker.setCurrentFolder(m_dqm_path); - stream.dqm.presource = booker.book1D("presource", "Pre-Source processing time", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - stream.dqm.presource ->StatOverflows(true); - stream.dqm.presource ->SetXTitle("processing time [ms]"); - stream.dqm.source = booker.book1D("source", "Source processing time", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - stream.dqm.source ->StatOverflows(true); - stream.dqm.source ->SetXTitle("processing time [ms]"); - stream.dqm.preevent = booker.book1D("preevent", "Pre-Event processing time", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - stream.dqm.preevent ->StatOverflows(true); - stream.dqm.preevent ->SetXTitle("processing time [ms]"); - stream.dqm.event = booker.book1D("event", "Event processing time", eventbins, 0., m_dqm_eventtime_range)->getTH1F(); - stream.dqm.event ->StatOverflows(true); - stream.dqm.event ->SetXTitle("processing time [ms]"); - } +FastTimerService::ResourcesPerJob::ResourcesPerJob() + = default; - // per subprocess - booker.setCurrentFolder(m_dqm_path + "/process " + process_name); - stream.dqm_perprocess[pid].preevent = booker.book1D("preevent", "Pre-Event processing time", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - stream.dqm_perprocess[pid].preevent ->StatOverflows(true); - stream.dqm_perprocess[pid].preevent ->SetXTitle("processing time [ms]"); - stream.dqm_perprocess[pid].event = booker.book1D("event", "Event processing time", eventbins, 0., m_dqm_eventtime_range)->getTH1F(); - stream.dqm_perprocess[pid].event ->StatOverflows(true); - stream.dqm_perprocess[pid].event ->SetXTitle("processing time [ms]"); - stream.dqm_perprocess[pid].all_paths = booker.book1D("all_paths", "Paths processing time", eventbins, 0., m_dqm_eventtime_range)->getTH1F(); - stream.dqm_perprocess[pid].all_paths ->StatOverflows(true); - stream.dqm_perprocess[pid].all_paths ->SetXTitle("processing time [ms]"); - stream.dqm_perprocess[pid].all_endpaths = booker.book1D("all_endpaths", "EndPaths processing time", pathbins, 0., m_dqm_pathtime_range)->getTH1F(); - stream.dqm_perprocess[pid].all_endpaths ->StatOverflows(true); - stream.dqm_perprocess[pid].all_endpaths ->SetXTitle("processing time [ms]"); - stream.dqm_perprocess[pid].interpaths = booker.book1D("interpaths", "Time spent between paths", pathbins, 0., m_dqm_eventtime_range)->getTH1F(); - stream.dqm_perprocess[pid].interpaths ->StatOverflows(true); - stream.dqm_perprocess[pid].interpaths ->SetXTitle("processing time [ms]"); - } +FastTimerService::ResourcesPerJob::ResourcesPerJob(ProcessCallGraph const& job, std::vector const& groups) : + total(), + highlight( groups.size() ), + modules( job.size() ), + processes(), + events(0) +{ + processes.reserve(job.processes().size()); + for (auto const& process: job.processes()) + processes.emplace_back(process); +} - // plots by path - if (m_enable_timing_paths) { - booker.setCurrentFolder(m_dqm_path + "/process " + process_name); - stream.dqm_paths[pid].active_time = booker.bookProfile("paths_active_time", "Additional time spent in each path", size, -0.5, size-0.5, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - stream.dqm_paths[pid].active_time ->StatOverflows(true); - stream.dqm_paths[pid].active_time ->SetYTitle("processing time [ms]"); - stream.dqm_paths[pid].total_time = booker.bookProfile("paths_total_time", "Total time spent in each path", size, -0.5, size-0.5, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - stream.dqm_paths[pid].total_time ->StatOverflows(true); - stream.dqm_paths[pid].total_time ->SetYTitle("processing time [ms]"); - stream.dqm_paths[pid].exclusive_time = booker.bookProfile("paths_exclusive_time", "Exclusive time spent in each path", size, -0.5, size-0.5, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - stream.dqm_paths[pid].exclusive_time ->StatOverflows(true); - stream.dqm_paths[pid].exclusive_time ->SetYTitle("processing time [ms]"); - stream.dqm_paths[pid].interpaths = booker.bookProfile("paths_interpaths", "Time spent between each path", size+1, -0.5, size+0.5, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - stream.dqm_paths[pid].interpaths ->StatOverflows(true); - stream.dqm_paths[pid].interpaths ->SetYTitle("processing time [ms]"); - - for (uint32_t i = 0; i < size_p; ++i) { - std::string const & label = tns.getTrigPath(i); - stream.dqm_paths[pid].active_time ->GetXaxis()->SetBinLabel(i + 1, label.c_str()); - stream.dqm_paths[pid].total_time ->GetXaxis()->SetBinLabel(i + 1, label.c_str()); - stream.dqm_paths[pid].exclusive_time ->GetXaxis()->SetBinLabel(i + 1, label.c_str()); - stream.dqm_paths[pid].interpaths ->GetXaxis()->SetBinLabel(i + 1, label.c_str()); - } - for (uint32_t i = 0; i < size_e; ++i) { - std::string const & label = tns.getEndPath(i); - stream.dqm_paths[pid].active_time ->GetXaxis()->SetBinLabel(i + size_p + 1, label.c_str()); - stream.dqm_paths[pid].total_time ->GetXaxis()->SetBinLabel(i + size_p + 1, label.c_str()); - stream.dqm_paths[pid].exclusive_time ->GetXaxis()->SetBinLabel(i + size_p + 1, label.c_str()); - stream.dqm_paths[pid].interpaths ->GetXaxis()->SetBinLabel(i + size_p + 1, label.c_str()); - } - stream.dqm_paths[pid].interpaths ->GetXaxis()->SetBinLabel(size+1, ""); - } +void +FastTimerService::ResourcesPerJob::reset() { + total.reset(); + for (auto & module: highlight) + module.reset(); + for (auto & module: modules) + module.reset(); + for (auto & process: processes) + process.reset(); + events = 0; +} - // plots vs. instantaneous luminosity - if (not m_dqm_luminosity.empty()) { - if (pid == 0) { - // resize the plots vs. luminosity - stream.dqm_byluminosity.resize(m_dqm_luminosity.size()); - - // whole event - booker.setCurrentFolder(m_dqm_path); - for (unsigned int i = 0; i < m_dqm_luminosity.size(); ++i) { - auto & plots = stream.dqm_byluminosity[i]; - int lumibins = (int) std::ceil(m_dqm_luminosity[i].range / m_dqm_luminosity[i].resolution); - plots.presource = booker.bookProfile("presource_by" + m_dqm_luminosity[i].name, "Pre-Source processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.presource ->StatOverflows(true); - plots.presource ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.presource ->SetYTitle("processing time [ms]"); - plots.source = booker.bookProfile("source_by" + m_dqm_luminosity[i].name, "Source processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.source ->StatOverflows(true); - plots.source ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.source ->SetYTitle("processing time [ms]"); - plots.preevent = booker.bookProfile("preevent_by" + m_dqm_luminosity[i].name, "Pre-Event processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.preevent ->StatOverflows(true); - plots.preevent ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.preevent ->SetYTitle("processing time [ms]"); - plots.event = booker.bookProfile("event_by" + m_dqm_luminosity[i].name, "Event processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, eventbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.event ->StatOverflows(true); - plots.event ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.event ->SetYTitle("processing time [ms]"); - } - } +FastTimerService::ResourcesPerJob & +FastTimerService::ResourcesPerJob::operator+=(ResourcesPerJob const& other) { + total += other.total; + assert(highlight.size() == other.highlight.size()); + for (unsigned int i: boost::irange(0ul, highlight.size())) + highlight[i] += other.highlight[i]; + assert(modules.size() == other.modules.size()); + for (unsigned int i: boost::irange(0ul, modules.size())) + modules[i] += other.modules[i]; + assert(processes.size() == other.processes.size()); + for (unsigned int i: boost::irange(0ul, processes.size())) + processes[i] += other.processes[i]; + events += other.events; + return *this; +} - // resize the plots vs. luminosity - stream.dqm_perprocess_byluminosity[pid].resize(m_dqm_luminosity.size()); - - // per subprocess - booker.setCurrentFolder(m_dqm_path + "/process " + process_name); - for (unsigned int i = 0; i < m_dqm_luminosity.size(); ++i) { - auto & plots = stream.dqm_perprocess_byluminosity[pid][i]; - int lumibins = (int) std::ceil(m_dqm_luminosity[i].range / m_dqm_luminosity[i].resolution); - plots.preevent = booker.bookProfile("preevent_by" + m_dqm_luminosity[i].name, "Pre-Event processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.preevent ->StatOverflows(true); - plots.preevent ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.preevent ->SetYTitle("processing time [ms]"); - plots.event = booker.bookProfile("event_by" + m_dqm_luminosity[i].name, "Event processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, eventbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.event ->StatOverflows(true); - plots.event ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.event ->SetYTitle("processing time [ms]"); - plots.all_paths = booker.bookProfile("all_paths_by" + m_dqm_luminosity[i].name, "Paths processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, eventbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.all_paths ->StatOverflows(true); - plots.all_paths ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.all_paths ->SetYTitle("processing time [ms]"); - plots.all_endpaths = booker.bookProfile("all_endpaths_by" + m_dqm_luminosity[i].name, "EndPaths processing time vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.all_endpaths ->StatOverflows(true); - plots.all_endpaths ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.all_endpaths ->SetYTitle("processing time [ms]"); - plots.interpaths = booker.bookProfile("interpaths_by" + m_dqm_luminosity[i].name, "Time spent between paths vs. " + m_dqm_luminosity[i].title, lumibins, 0., m_dqm_luminosity[i].range, pathbins, 0., std::numeric_limits::infinity(), " ")->getTProfile(); - plots.interpaths ->StatOverflows(true); - plots.interpaths ->SetXTitle(m_dqm_luminosity[i].label.c_str()); - plots.interpaths ->SetYTitle("processing time [ms]"); - } - } +FastTimerService::ResourcesPerJob +FastTimerService::ResourcesPerJob::operator+(ResourcesPerJob const& other) const { + ResourcesPerJob result(*this); + result += other; + return result; +} - // per-path and per-module accounting - if (m_enable_timing_paths) { - booker.setCurrentFolder(m_dqm_path + "/process " + process_name + "/Paths"); - for (auto & keyval: stream.paths[pid]) { - std::string const & pathname = keyval.first; - PathInfo & pathinfo = keyval.second; - - if (m_enable_dqm_bypath_active) { - pathinfo.dqm_active = booker.book1D(pathname + "_active", pathname + " active time", pathbins, 0., m_dqm_pathtime_range)->getTH1F(); - pathinfo.dqm_active ->StatOverflows(true); - pathinfo.dqm_active ->SetXTitle("processing time [ms]"); - } - - if (m_enable_dqm_bypath_total) { - pathinfo.dqm_total = booker.book1D(pathname + "_total", pathname + " total time", pathbins, 0., m_dqm_pathtime_range)->getTH1F(); - pathinfo.dqm_total ->StatOverflows(true); - pathinfo.dqm_total ->SetXTitle("processing time [ms]"); - } - - if (m_enable_dqm_bypath_overhead) { - pathinfo.dqm_premodules = booker.book1D(pathname + "_premodules", pathname + " pre-modules overhead", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - pathinfo.dqm_premodules ->StatOverflows(true); - pathinfo.dqm_premodules ->SetXTitle("processing time [ms]"); - pathinfo.dqm_intermodules = booker.book1D(pathname + "_intermodules", pathname + " inter-modules overhead", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - pathinfo.dqm_intermodules ->StatOverflows(true); - pathinfo.dqm_intermodules ->SetXTitle("processing time [ms]"); - pathinfo.dqm_postmodules = booker.book1D(pathname + "_postmodules", pathname + " post-modules overhead", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - pathinfo.dqm_postmodules ->StatOverflows(true); - pathinfo.dqm_postmodules ->SetXTitle("processing time [ms]"); - pathinfo.dqm_overhead = booker.book1D(pathname + "_overhead", pathname + " overhead time", modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - pathinfo.dqm_overhead ->StatOverflows(true); - pathinfo.dqm_overhead ->SetXTitle("processing time [ms]"); - } - - if (m_enable_dqm_bypath_details or m_enable_dqm_bypath_counters) { - // book histograms for modules-in-paths statistics - - // find histograms X-axis labels - uint32_t id; - std::vector const & modules = ((id = tns.findTrigPath(pathname)) != tns.getTrigPaths().size()) ? tns.getTrigPathModules(id) : - ((id = tns.findEndPath(pathname)) != tns.getEndPaths().size()) ? tns.getEndPathModules(id) : - std::vector(); - - // use a mutex to prevent two threads from assigning to the same element at the same time - static std::mutex dup_mutex; - // use a tbb::concurrent_vector because growing does not invalidate existing iterators and pointers - static tbb::concurrent_vector dup; - // lock, and fill the first 32 elements - if (dup.empty()) { - std::lock_guard lock(dup_mutex); - if (dup.empty()) { - dup.resize(32); - for (unsigned int i = 0; i < 32; ++i) - dup[i] = (boost::format("(dup.) (%d)") % i).str(); - } - } - // lock, and fill as many elements as needed - if (modules.size() > dup.size()) { - std::lock_guard lock(dup_mutex); - unsigned int old_size = dup.size(); - unsigned int new_size = modules.size(); - if (new_size > old_size) { - dup.resize(new_size); - for (unsigned int i = old_size; i < new_size; ++i) - dup[i] = (boost::format("(dup.) (%d)") % i).str(); - } - } - - std::vector labels(modules.size(), nullptr); - for (uint32_t i = 0; i < modules.size(); ++i) - labels[i] = (pathinfo.modules[i]) ? modules[i].c_str() : dup[i].c_str(); - - // book counter histograms - if (m_enable_dqm_bypath_counters) { - pathinfo.dqm_module_counter = booker.book1D(pathname + "_module_counter", pathname + " module counter", modules.size() + 1, -0.5, modules.size() + 0.5)->getTH1F(); - // find module labels - for (uint32_t i = 0; i < modules.size(); ++i) - pathinfo.dqm_module_counter->GetXaxis()->SetBinLabel( i+1, labels[i] ); - pathinfo.dqm_module_counter->GetXaxis()->SetBinLabel( modules.size() + 1, "" ); - } - // book detailed timing histograms - if (m_enable_dqm_bypath_details) { - pathinfo.dqm_module_active = booker.book1D(pathname + "_module_active", pathname + " module active", modules.size(), -0.5, modules.size() - 0.5)->getTH1F(); - pathinfo.dqm_module_active ->SetYTitle("cumulative processing time [ms]"); - pathinfo.dqm_module_total = booker.book1D(pathname + "_module_total", pathname + " module total", modules.size(), -0.5, modules.size() - 0.5)->getTH1F(); - pathinfo.dqm_module_total ->SetYTitle("cumulative processing time [ms]"); - // find module labels - for (uint32_t i = 0; i < modules.size(); ++i) { - pathinfo.dqm_module_active ->GetXaxis()->SetBinLabel( i+1, labels[i] ); - pathinfo.dqm_module_total ->GetXaxis()->SetBinLabel( i+1, labels[i] ); - } - } - } - - // book exclusive path time histograms - if (m_enable_dqm_bypath_exclusive) { - pathinfo.dqm_exclusive = booker.book1D(pathname + "_exclusive", pathname + " exclusive time", pathbins, 0., m_dqm_pathtime_range)->getTH1F(); - pathinfo.dqm_exclusive ->StatOverflows(true); - pathinfo.dqm_exclusive ->SetXTitle("processing time [ms]"); - } - } - } +// per-thread measurements - if (m_enable_dqm_bymodule) { - booker.setCurrentFolder(m_dqm_path + "/Modules"); - for (auto & keyval: stream.modules) { - std::string const & label = keyval.first; - ModuleInfo & module = keyval.second; - module.dqm_active = booker.book1D(label, label, modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - module.dqm_active->StatOverflows(true); - module.dqm_active->SetXTitle("processing time [ms]"); - } - } +// Measurement - if (m_enable_dqm_bymoduletype) { - booker.setCurrentFolder(m_dqm_path + "/ModuleTypes"); - for (auto & keyval: stream.moduletypes) { - std::string const & label = keyval.first; - ModuleInfo & module = keyval.second; - module.dqm_active = booker.book1D(label, label, modulebins, 0., m_dqm_moduletime_range)->getTH1F(); - module.dqm_active->StatOverflows(true); - module.dqm_active->SetXTitle("processing time [ms]"); - } - } +FastTimerService::Measurement::Measurement() + = default; - }; +void +FastTimerService::Measurement::measure() { + #ifdef DEBUG_THREAD_CONCURRENCY + id = std::this_thread::get_id(); + #endif // DEBUG_THREAD_CONCURRENCY + time_thread = boost::chrono::thread_clock::now(); + time_real = boost::chrono::high_resolution_clock::now(); +} - // book MonitorElement's for this stream - edm::Service()->bookTransaction(bookTransactionCallback, sc.eventID().run(), sid, m_module_id); +void +FastTimerService::Measurement::measure_and_store(Resources & store) { + #ifdef DEBUG_THREAD_CONCURRENCY + assert(std::this_thread::get_id() == id); + #endif // DEBUG_THREAD_CONCURRENCY + auto new_time_thread = boost::chrono::thread_clock::now(); + auto new_time_real = boost::chrono::high_resolution_clock::now(); + store.time_thread = new_time_thread - time_thread; + store.time_real = new_time_real - time_real; + time_thread = new_time_thread; + time_real = new_time_real; } +/////////////////////////////////////////////////////////////////////////////// + +FastTimerService::PlotsPerElement::PlotsPerElement() : + time_thread_(nullptr), + time_thread_byls_(nullptr), + time_real_(nullptr), + time_real_byls_(nullptr) +{ +} void -FastTimerService::preallocate(edm::service::SystemBounds const & bounds) +FastTimerService::PlotsPerElement::reset() { - m_concurrent_runs = bounds.maxNumberOfConcurrentRuns(); - m_concurrent_streams = bounds.maxNumberOfStreams(); - m_concurrent_threads = bounds.maxNumberOfThreads(); + // the plots are owned by the DQMStore + time_thread_ = nullptr; + time_thread_byls_ = nullptr; + time_real_ = nullptr; + time_real_byls_ = nullptr; +} - if (m_enable_dqm_bynproc) - m_dqm_path += (boost::format("/Running %d processes") % m_concurrent_threads).str(); +void +FastTimerService::PlotsPerElement::book( + DQMStore::IBooker & booker, + std::string const& name, + std::string const& title, + double range, + double resolution, + unsigned int lumisections, + bool byls) +{ + int bins = (int) std::ceil(range / resolution); + std::string y_title = (boost::format("events / %.1f ms") % resolution).str(); + + time_thread_ = booker.book1D( + name + " time_thread", + title + " processing time (cpu)", + bins, 0., range + )->getTH1F(); + time_thread_->StatOverflows(true); + time_thread_->SetXTitle("processing time [ms]"); + time_thread_->SetYTitle(y_title.c_str()); + + time_real_ = booker.book1D( + name + " time_real", + title + " processing time (real)", + bins, 0., range + )->getTH1F(); + time_real_->StatOverflows(true); + time_real_->SetXTitle("processing time [ms]"); + time_real_->SetYTitle(y_title.c_str()); + + if (not byls) + return; - m_run_summary.resize(m_concurrent_runs); - m_run_summary_perprocess.resize(m_concurrent_runs); - m_stream.resize(m_concurrent_streams); + time_thread_byls_ = booker.bookProfile( + name + " time_thread_byls", + title + " processing time (cpu) vs. lumisection", + lumisections, 0.5, lumisections + 0.5, + bins, 0., std::numeric_limits::infinity(), + " ")->getTProfile(); + time_thread_byls_->StatOverflows(true); + time_thread_byls_->SetXTitle("lumisection"); + time_thread_byls_->SetYTitle("processing time [ms]"); + + time_real_byls_ = booker.bookProfile( + name + " time_real_byls", + title + " processing time (real) vs. lumisection", + lumisections, 0.5, lumisections + 0.5, + bins, 0., std::numeric_limits::infinity(), + " ")->getTProfile(); + time_real_byls_->StatOverflows(true); + time_real_byls_->SetXTitle("lumisection"); + time_real_byls_->SetYTitle("processing time [ms]"); +} - // assign a pseudo module id to the FastTimerService - m_module_id = edm::ModuleDescription::getUniqueID(); - for (auto & stream: m_stream) { - stream.fast_modules.resize( m_module_id, nullptr); - stream.fast_moduletypes.resize(m_module_id, nullptr); - } +void +FastTimerService::PlotsPerElement::fill(Resources const& data, unsigned int lumisection) +{ + if (time_thread_) + time_thread_->Fill(ms(data.time_thread)); - // resize the luminosity per event buffer - for (auto & stream: m_stream) - stream.luminosity.resize(m_dqm_luminosity.size(), 0); -} + if (time_thread_byls_) + time_thread_byls_->Fill(lumisection, ms(data.time_thread)); + if (time_real_) + time_real_->Fill(ms(data.time_real)); -void -FastTimerService::postStreamBeginRun(edm::StreamContext const & sc) { - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; - stream.timer_last_transition = FastTimer::Clock::now(); + if (time_real_byls_) + time_real_byls_->Fill(lumisection, ms(data.time_real)); } void -FastTimerService::postStreamEndRun(edm::StreamContext const & sc) +FastTimerService::PlotsPerElement::fill_fraction(Resources const& data, Resources const& part, unsigned int lumisection) { - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; + float total; + float fraction; - if (m_enable_dqm) { - DQMStore * store = edm::Service().operator->(); - assert(store); - store->mergeAndResetMEsRunSummaryCache(sc.eventID().run(), sid, m_module_id); - } + total = ms(data.time_thread); + fraction = (total > 0.) ? (ms(part.time_thread) / total) : 0.; + if (time_thread_) + time_thread_->Fill(total, fraction); - stream.reset(); - stream.timer_last_transition = FastTimer::Clock::now(); + if (time_thread_byls_) + time_thread_byls_->Fill(lumisection, total, fraction); + + total = ms(data.time_real); + fraction = (total > 0.) ? (ms(part.time_real) / total) : 0.; + if (time_real_) + time_real_->Fill(total, fraction); + + if (time_real_byls_) + time_real_byls_->Fill(lumisection, total, fraction); } -void -FastTimerService::postStreamBeginLumi(edm::StreamContext const & sc) { - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; - stream.timer_last_transition = FastTimer::Clock::now(); + +FastTimerService::PlotsPerPath::PlotsPerPath() : + total_(), + module_counter_(nullptr), + module_time_thread_total_(nullptr), + module_time_real_total_(nullptr) +{ } void -FastTimerService::postStreamEndLumi(edm::StreamContext const & sc) { - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; +FastTimerService::PlotsPerPath::reset() +{ + // the plots are owned by the DQMStore + total_.reset(); + module_counter_ = nullptr; + module_time_thread_total_ = nullptr; + module_time_real_total_ = nullptr; +} - if (m_enable_dqm) { - DQMStore * store = edm::Service().operator->(); - assert(store); - store->mergeAndResetMEsLuminositySummaryCache(sc.eventID().run(),sc.eventID().luminosityBlock(),sid, m_module_id); +void +FastTimerService::PlotsPerPath::book( + DQMStore::IBooker & booker, + ProcessCallGraph const& job, + ProcessCallGraph::PathType const& path, + double range, + double resolution, + unsigned int lumisections, + bool byls) +{ + const std::string basedir = booker.pwd(); + booker.setCurrentFolder(basedir + "/path " + path.name_); + + total_.book(booker, "path", path.name_, range, resolution, lumisections, byls); + + unsigned int bins = path.modules_and_dependencies_.size(); + module_counter_ = booker.book1DD( + "module_counter", + "module counter", + bins + 1, -0.5, bins + 0.5 + )->getTH1D(); + module_counter_->SetYTitle("processing time [ms]"); + module_time_thread_total_ = booker.book1DD( + "module_time_thread_total", + "total module time (cpu)", + bins, -0.5, bins - 0.5 + )->getTH1D(); + module_time_thread_total_->SetYTitle("processing time [ms]"); + module_time_real_total_ = booker.book1DD( + "module_time_real_total", + "total module time (real)", + bins, -0.5, bins - 0.5 + )->getTH1D(); + module_time_real_total_->SetYTitle("processing time [ms]"); + for (unsigned int bin: boost::irange(0u, bins)) { + auto const& module = job[path.modules_and_dependencies_[bin]]; + std::string const& label = module.scheduled_ ? module.module_.moduleLabel() : module.module_.moduleLabel() + " (unscheduled)"; + module_counter_ ->GetXaxis()->SetBinLabel(bin + 1, label.c_str()); + module_time_thread_total_->GetXaxis()->SetBinLabel(bin + 1, label.c_str()); + module_time_real_total_ ->GetXaxis()->SetBinLabel(bin + 1, label.c_str()); } + module_counter_->GetXaxis()->SetBinLabel(bins + 1, ""); - stream.timer_last_transition = FastTimer::Clock::now(); + booker.setCurrentFolder(basedir); } void -FastTimerService::postGlobalEndRun(edm::GlobalContext const & gc) +FastTimerService::PlotsPerPath::fill(ProcessCallGraph::PathType const& description, ResourcesPerJob const& data, ResourcesPerPath const& path, unsigned int ls) { - if (m_enable_timing_summary) { - unsigned int pid = processID(gc.processContext()); - unsigned int rid = gc.runIndex(); - unsigned int run = gc.luminosityBlockID().run(); - const std::string label = (boost::format("run %d") % run).str(); + // fill the total path time + total_.fill(path.total, ls); + + // fill the modules that actually ran and the total time spent in each od them + for (unsigned int i = 0; i < path.last; ++i) { + auto const& module = data.modules[description.modules_and_dependencies_[i]]; + module_counter_->Fill(i); + module_time_thread_total_->Fill(i, ms(module.total.time_thread)); + module_time_real_total_->Fill(i, ms(module.total.time_real)); + } + if (path.status) + module_counter_->Fill(path.last); +} - printProcessSummary(m_run_summary[rid], m_run_summary_perprocess[rid][pid], label, m_process[pid].name); - if (pid+1 == m_process.size()) - printSummary(m_run_summary[rid], label); - } +FastTimerService::PlotsPerProcess::PlotsPerProcess(ProcessCallGraph::ProcessType const& process) : + event_(), + paths_(process.paths_.size()), + endpaths_(process.endPaths_.size()) +{ } void -FastTimerService::postEndJob() +FastTimerService::PlotsPerProcess::reset() { - if (m_enable_timing_summary) { - const std::string label = "the whole job"; - for (unsigned int pid = 0; pid < m_process.size(); ++pid) - printProcessSummary(m_job_summary, m_job_summary_perprocess[pid], label, m_process[pid].name); + event_.reset(); + for (auto & path: paths_) + path.reset(); + for (auto & path: endpaths_) + path.reset(); +} - printSummary(m_job_summary, label); +void +FastTimerService::PlotsPerProcess::book( + DQMStore::IBooker & booker, + ProcessCallGraph const& job, + ProcessCallGraph::ProcessType const& process, + double event_range, + double event_resolution, + double path_range, + double path_resolution, + unsigned int lumisections, + bool byls) +{ + const std::string basedir = booker.pwd(); + event_.book(booker, + "process " + process.name_, "process " + process.name_, + event_range, + event_resolution, + lumisections, + byls); + booker.setCurrentFolder(basedir + "/process " + process.name_ + " paths"); + for (unsigned int id: boost::irange(0ul, paths_.size())) + { + paths_[id].book(booker, + job, process.paths_[id], + path_range, + path_resolution, + lumisections, + byls); + } + for (unsigned int id: boost::irange(0ul, endpaths_.size())) + { + endpaths_[id].book(booker, + job, process.endPaths_[id], + path_range, + path_resolution, + lumisections, + byls); } + booker.setCurrentFolder(basedir); } void -FastTimerService::printProcessSummary(Timing const & total, TimingPerProcess const & summary, std::string const & label, std::string const & process) const +FastTimerService::PlotsPerProcess::fill(ProcessCallGraph::ProcessType const& description, ResourcesPerJob const& data, ResourcesPerProcess const& process, unsigned int ls) { - // print a timing summary for the run or job, for each subprocess - std::ostringstream out; - out << std::fixed << std::setprecision(6); - out << "FastReport for " << label << ", process " << process << '\n'; - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.preevent / (double) total.count << " Pre-Event" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.event / (double) total.count << " Event" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.all_paths / (double) total.count << " all Paths" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.all_endpaths / (double) total.count << " all EndPaths" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.interpaths / (double) total.count << " between paths" << '\n'; - edm::LogVerbatim("FastReport") << out.str(); + // fill process event plots + event_.fill(process.total, ls); + + // fill all paths plots + for (unsigned int id: boost::irange(0ul, paths_.size())) + paths_[id].fill(description.paths_[id], data, process.paths[id], ls); + + // fill all endpaths plots + for (unsigned int id: boost::irange(0ul, endpaths_.size())) + endpaths_[id].fill(description.endPaths_[id], data, process.endpaths[id], ls); } -void -FastTimerService::printSummary(Timing const & summary, std::string const & label) const +FastTimerService::PlotsPerJob::PlotsPerJob(ProcessCallGraph const& job, std::vector const& groups) : + event_(), + highlight_(groups.size()), + modules_(job.size()), + processes_() { - // print a timing summary for the run or job - //edm::service::TriggerNamesService & tns = * edm::Service(); + processes_.reserve(job.processes().size()); + for (auto const& process: job.processes()) + processes_.emplace_back(process); +} - std::ostringstream out; - out << std::fixed << std::setprecision(6); - out << "FastReport for " << label << ", over all subprocesses" << '\n'; - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.presource / (double) summary.count << " Pre-Source" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.source / (double) summary.count << " Source" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.preevent / (double) summary.count << " Pre-Event" << '\n'; - out << "FastReport " << std::right << std::setw(10) << summary.event / (double) summary.count << " Event" << '\n'; - edm::LogVerbatim("FastReport") << out.str(); +void +FastTimerService::PlotsPerJob::reset() +{ + event_.reset(); + for (auto & module: highlight_) + module.reset(); + for (auto & module: modules_) + module.reset(); + for (auto & process: processes_) + process.reset(); } -/* - if (m_enable_timing_modules) { - double modules_total = 0.; - for (auto & keyval: m_stream.modules) - modules_total += keyval.second.summary_active; - out << "FastReport " << std::right << std::setw(10) << modules_total / (double) summary.count << " all Modules" << '\n'; - } - out << '\n'; - if (m_enable_timing_paths and not m_enable_timing_modules) { - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Path" << '\n'; - for (auto const & name: tns.getTrigPaths()) - out << "FastReport " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_active / (double) summary.count << " " - << name << '\n'; - out << '\n'; - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active EndPath" << '\n'; - for (auto const & name: tns.getEndPaths()) - out << "FastReport " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_active / (double) summary.count << " " - << name << '\n'; - } else if (m_enable_timing_paths and m_enable_timing_modules) { - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Pre- Inter- Post-mods Overhead Total Path" << '\n'; - for (auto const & name: tns.getTrigPaths()) { - out << "FastReport " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_active / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_premodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_intermodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_postmodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_overhead / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_total / (double) summary.count << " " - << name << '\n'; - } - out << '\n'; - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Pre- Inter- Post-mods Overhead Total EndPath" << '\n'; - for (auto const & name: tns.getEndPaths()) { - out << "FastReport " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_active / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_premodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_intermodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_postmodules / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_overhead / (double) summary.count << " " - << std::right << std::setw(10) << m_stream.paths[pid][name].summary_total / (double) summary.count << " " - << name << '\n'; - } +void +FastTimerService::PlotsPerJob::book( + DQMStore::IBooker & booker, + ProcessCallGraph const& job, + std::vector const& groups, + double event_range, + double event_resolution, + double path_range, + double path_resolution, + double module_range, + double module_resolution, + unsigned int lumisections, + bool bymodule, + bool byls) +{ + const std::string basedir = booker.pwd(); + + // event summary plots + event_.book(booker, + "event", "Event", + event_range, + event_resolution, + lumisections, + byls); + + modules_[job.source().id()].book(booker, + "source", "Source", + module_range, + module_resolution, + lumisections, + byls); + + // plot the time spent in few given groups of modules + for (unsigned int group: boost::irange(0ul, groups.size())) { + auto const & label = groups[group].label; + highlight_[group].book(booker, + "highlight " + label, "Highlight " + label, + event_range, + event_resolution, + lumisections, + byls); } - out << '\n'; - if (m_enable_timing_modules) { - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Module" << '\n'; - for (auto & keyval: m_stream.modules) { - std::string const & label = keyval.first; - ModuleInfo const & module = keyval.second; - out << "FastReport " << std::right << std::setw(10) << module.summary_active / (double) summary.count << " " << label << '\n'; - } - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Module" << '\n'; - out << '\n'; - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Module" << '\n'; - for (auto & keyval: m_stream.moduletypes) { - std::string const & label = keyval.first; - ModuleInfo const & module = keyval.second; - out << "FastReport " << std::right << std::setw(10) << module.summary_active / (double) summary.count << " " << label << '\n'; + + // plots per subprocess (event, modules, paths and endpaths) + for (unsigned int pid: boost::irange(0ul, job.processes().size())) { + auto const& process = job.processDescription(pid); + processes_[pid].book(booker, + job, process, + event_range, + event_resolution, + path_range, + path_resolution, + lumisections, + byls); + + if (bymodule) { + booker.setCurrentFolder(basedir + "/process " + process.name_ + " modules"); + for (unsigned int id: process.modules_) + { + auto const& module_name = job.module(id).moduleLabel(); + modules_[id].book(booker, + module_name, module_name, + module_range, + module_resolution, + lumisections, + byls); + } + booker.setCurrentFolder(basedir); } - //out << "FastReport " << (m_use_realtime ? "(real time) " : "(CPU time) ") << " Active Module" << '\n'; - } -*/ - -void FastTimerService::preModuleBeginJob(edm::ModuleDescription const & module) { - // allocate a counter for each module and module type - for (auto & stream: m_stream) { - if (module.id() >= stream.fast_modules.size()) - stream.fast_modules.resize(module.id() + 1, nullptr); - if (module.id() >= stream.fast_moduletypes.size()) - stream.fast_moduletypes.resize(module.id() + 1, nullptr); - - stream.fast_modules[module.id()] = & stream.modules[module.moduleLabel()];; - stream.fast_moduletypes[module.id()] = & stream.moduletypes[module.moduleName()]; } } -void FastTimerService::preEvent(edm::StreamContext const & sc) { - unsigned int pid = processID(sc.processContext()); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; +void +FastTimerService::PlotsPerJob::fill(ProcessCallGraph const& job, ResourcesPerJob const& data, unsigned int ls) +{ + // fill total event plots + event_.fill(data.total, ls); - // new event, reset the per-event counter - stream.timer_event.start(); + // fill highltight plots + for (unsigned int group: boost::irange(0ul, highlight_.size())) + highlight_[group].fill_fraction(data.total, data.highlight[group], ls); - // account the time spent between the last transition and the beginning of the event - stream.timing_perprocess[pid].preevent = delta(stream.timer_last_transition, stream.timer_event.getStartTime()); + // fill modules plots + for (unsigned int id: boost::irange(0ul, modules_.size())) + modules_[id].fill(data.modules[id].total, ls); + + for (unsigned int pid: boost::irange(0ul, processes_.size())) + processes_[pid].fill(job.processDescription(pid), data, data.processes[pid], ls); +} - // clear the event counters - stream.timing_perprocess[pid].event = 0; - stream.timing_perprocess[pid].all_paths = 0; - stream.timing_perprocess[pid].all_endpaths = 0; - stream.timing_perprocess[pid].interpaths = 0; - stream.timing_perprocess[pid].paths_interpaths.assign(stream.paths[pid].size() + 1, 0); - for (auto & keyval : stream.paths[pid]) { - keyval.second.timer.reset(); - keyval.second.time_active = 0.; - keyval.second.time_exclusive = 0.; - keyval.second.time_premodules = 0.; - keyval.second.time_intermodules = 0.; - keyval.second.time_postmodules = 0.; - keyval.second.time_total = 0.; - } - // copy the start event timestamp as the end of the previous path - // used by the inter-path overhead measurement - stream.timer_last_path = stream.timer_event.getStartTime(); +/////////////////////////////////////////////////////////////////////////////// - // if requested, set the lumisection for timing vs. lumisection plots - if (m_enable_dqm_byls and pid == 0) - setLuminosity(sid, 0, sc.eventID().luminosityBlock()); +FastTimerService::FastTimerService(const edm::ParameterSet & config, edm::ActivityRegistry & registry) : + // configuration + callgraph_(), + // job configuration + concurrent_runs_( 0 ), + concurrent_streams_( 0 ), + concurrent_threads_( 0 ), + print_event_summary_( config.getUntrackedParameter( "printEventSummary" ) ), + print_run_summary_( config.getUntrackedParameter( "printRunSummary" ) ), + print_job_summary_( config.getUntrackedParameter( "printJobSummary" ) ), + // dqm configuration + module_id_( edm::ModuleDescription::invalidID() ), + enable_dqm_( config.getUntrackedParameter( "enableDQM" ) ), + enable_dqm_bymodule_( config.getUntrackedParameter( "enableDQMbyModule" ) ), + enable_dqm_byls_( config.getUntrackedParameter( "enableDQMbyLumiSection" ) ), + enable_dqm_bynproc_( config.getUntrackedParameter( "enableDQMbyProcesses" ) ), + dqm_eventtime_range_( config.getUntrackedParameter( "dqmTimeRange" ) ), // ms + dqm_eventtime_resolution_( config.getUntrackedParameter( "dqmTimeResolution" ) ), // ms + dqm_pathtime_range_( config.getUntrackedParameter( "dqmPathTimeRange" ) ), // ms + dqm_pathtime_resolution_( config.getUntrackedParameter( "dqmPathTimeResolution" ) ), // ms + dqm_moduletime_range_( config.getUntrackedParameter( "dqmModuleTimeRange" ) ), // ms + dqm_moduletime_resolution_( config.getUntrackedParameter( "dqmModuleTimeResolution" ) ), // ms + dqm_lumisections_range_( config.getUntrackedParameter( "dqmLumiSectionsRange" ) ), + dqm_path_( config.getUntrackedParameter("dqmPath" ) ), + // highlight configuration + highlight_module_psets_( config.getUntrackedParameter>("highlightModules") ), + highlight_modules_( highlight_module_psets_.size()) // filled in postBeginJob() +{ + registry.watchPreallocate( this, & FastTimerService::preallocate ); + registry.watchPreBeginJob( this, & FastTimerService::preBeginJob ); + registry.watchPostBeginJob( this, & FastTimerService::postBeginJob ); + registry.watchPostEndJob( this, & FastTimerService::postEndJob ); + registry.watchPreGlobalBeginRun( this, & FastTimerService::preGlobalBeginRun ); +//registry.watchPostGlobalBeginRun( this, & FastTimerService::postGlobalBeginRun ); +//registry.watchPreGlobalEndRun( this, & FastTimerService::preGlobalEndRun ); + registry.watchPostGlobalEndRun( this, & FastTimerService::postGlobalEndRun ); + registry.watchPreStreamBeginRun( this, & FastTimerService::preStreamBeginRun ); +//registry.watchPostStreamBeginRun( this, & FastTimerService::postStreamBeginRun ); +//registry.watchPreStreamEndRun( this, & FastTimerService::preStreamEndRun ); + registry.watchPostStreamEndRun( this, & FastTimerService::postStreamEndRun ); +//registry.watchPreGlobalBeginLumi( this, & FastTimerService::preGlobalBeginLumi ); +//registry.watchPostGlobalBeginLumi( this, & FastTimerService::postGlobalBeginLumi ); +//registry.watchPreGlobalEndLumi( this, & FastTimerService::preGlobalEndLumi ); +//registry.watchPostGlobalEndLumi( this, & FastTimerService::postGlobalEndLumi ); + registry.watchPreStreamBeginLumi( this, & FastTimerService::preStreamBeginLumi ); +//registry.watchPostStreamBeginLumi( this, & FastTimerService::postStreamBeginLumi ); +//registry.watchPreStreamEndLumi( this, & FastTimerService::preStreamEndLumi ); + registry.watchPostStreamEndLumi( this, & FastTimerService::postStreamEndLumi ); +//registry.watchPreEvent( this, & FastTimerService::preEvent ); + registry.watchPostEvent( this, & FastTimerService::postEvent ); + registry.watchPrePathEvent( this, & FastTimerService::prePathEvent ); + registry.watchPostPathEvent( this, & FastTimerService::postPathEvent ); + registry.watchPreSourceConstruction( this, & FastTimerService::preSourceConstruction); +//registry.watchPostSourceConstruction( this, & FastTimerService::postSourceConstruction); +//registry.watchPreSourceRun( this, & FastTimerService::preSourceRun ); +//registry.watchPostSourceRun( this, & FastTimerService::postSourceRun ); +//registry.watchPreSourceLumi( this, & FastTimerService::preSourceLumi ); +//registry.watchPostSourceLumi( this, & FastTimerService::postSourceLumi ); + registry.watchPreSourceEvent( this, & FastTimerService::preSourceEvent ); + registry.watchPostSourceEvent( this, & FastTimerService::postSourceEvent ); +//registry.watchPreModuleBeginJob( this, & FastTimerService::preModuleBeginJob ); +//registry.watchPostModuleBeginJob( this, & FastTimerService::postModuleBeginJob ); +//registry.watchPreModuleEndJob( this, & FastTimerService::preModuleEndJob ); +//registry.watchPostModuleEndJob( this, & FastTimerService::postModuleEndJob ); +//registry.watchPreModuleBeginStream( this, & FastTimerService::preModuleBeginStream ); +//registry.watchPostModuleBeginStream( this, & FastTimerService::postModuleBeginStream ); +//registry.watchPreModuleEndStream( this, & FastTimerService::preModuleEndStream ); +//registry.watchPostModuleEndStream( this, & FastTimerService::postModuleEndStream ); +//registry.watchPreModuleGlobalBeginRun( this, & FastTimerService::preModuleGlobalBeginRun ); +//registry.watchPostModuleGlobalBeginRun( this, & FastTimerService::postModuleGlobalBeginRun ); +//registry.watchPreModuleGlobalEndRun( this, & FastTimerService::preModuleGlobalEndRun ); +//registry.watchPostModuleGlobalEndRun( this, & FastTimerService::postModuleGlobalEndRun ); +//registry.watchPreModuleGlobalBeginLumi( this, & FastTimerService::preModuleGlobalBeginLumi ); +//registry.watchPostModuleGlobalBeginLumi( this, & FastTimerService::postModuleGlobalBeginLumi ); +//registry.watchPreModuleGlobalEndLumi( this, & FastTimerService::preModuleGlobalEndLumi ); +//registry.watchPostModuleGlobalEndLumi( this, & FastTimerService::postModuleGlobalEndLumi ); +//registry.watchPreModuleStreamBeginRun( this, & FastTimerService::preModuleStreamBeginRun ); +//registry.watchPostModuleStreamBeginRun( this, & FastTimerService::postModuleStreamBeginRun ); +//registry.watchPreModuleStreamEndRun( this, & FastTimerService::preModuleStreamEndRun ); +//registry.watchPostModuleStreamEndRun( this, & FastTimerService::postModuleStreamEndRun ); +//registry.watchPreModuleStreamBeginLumi( this, & FastTimerService::preModuleStreamBeginLumi ); +//registry.watchPostModuleStreamBeginLumi( this, & FastTimerService::postModuleStreamBeginLumi ); +//registry.watchPreModuleStreamEndLumi( this, & FastTimerService::preModuleStreamEndLumi ); +//registry.watchPostModuleStreamEndLumi( this, & FastTimerService::postModuleStreamEndLumi ); +//registry.watchPreModuleEventPrefetching( this, & FastTimerService::preModuleEventPrefetching ); +//registry.watchPostModuleEventPrefetching( this, & FastTimerService::postModuleEventPrefetching ); + registry.watchPreModuleEvent( this, & FastTimerService::preModuleEvent ); + registry.watchPostModuleEvent( this, & FastTimerService::postModuleEvent ); + registry.watchPreModuleEventDelayedGet( this, & FastTimerService::preModuleEventDelayedGet ); + registry.watchPostModuleEventDelayedGet( this, & FastTimerService::postModuleEventDelayedGet ); +//registry.watchPreEventReadFromSource( this, & FastTimerService::preEventReadFromSource ); +//registry.watchPostEventReadFromSource( this, & FastTimerService::postEventReadFromSource ); } -void FastTimerService::postEvent(edm::StreamContext const & sc) { - unsigned int pid = processID(sc.processContext()); - unsigned int sid = sc.streamID(); - unsigned int rid = sc.runIndex(); - auto & stream = m_stream[sid]; +FastTimerService::~FastTimerService() = default; + +double +FastTimerService::queryModuleTime_(edm::StreamID sid, unsigned int id) const +{ + // private version, assume "id" is valid + auto const& stream = streams_[sid]; + auto const& module = stream.modules[id]; + return ms(module.total.time_real); +} + +double +FastTimerService::querySourceTime(edm::StreamID sid) const +{ + return queryModuleTime_(sid, callgraph_.source().id()); +} + +double +FastTimerService::queryEventTime(edm::StreamID sid) const +{ + auto const& stream = streams_[sid]; + return ms(stream.total.time_real); +} + +double +FastTimerService::queryEventTime(edm::StreamID sid, std::string const& process) const +{ + unsigned int pid = callgraph_.processId(process); + auto const& stream = streams_[sid]; + return ms(stream.processes[pid].total.time_real); +} + +double +FastTimerService::queryModuleTime(edm::StreamID sid, const edm::ModuleDescription & md) const +{ + return queryModuleTime_(sid, md.id()); +} + +double +FastTimerService::queryModuleTime(edm::StreamID sid, unsigned int id) const +{ + if (id < callgraph_.size()) + return queryModuleTime_(sid, id); + + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} + +double +FastTimerService::queryModuleTimeByLabel(edm::StreamID sid, std::string const& label) const +{ + for (unsigned int id: boost::irange(0u, callgraph_.size())) + if (callgraph_.module(id).moduleLabel() == label) + return queryModuleTime_(sid, id); - // stop the per-event timer, and account event time - stream.timer_event.stop(); - stream.timer_last_transition = stream.timer_event.getStopTime(); - stream.timing_perprocess[pid].event = stream.timer_event.seconds(); + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} + +double +FastTimerService::queryModuleTimeByLabel(edm::StreamID sid, std::string const& process, const std::string & label) const +{ + for (unsigned int id: callgraph_.processDescription(process).modules_) + if (callgraph_.module(id).moduleLabel() == label) + return queryModuleTime_(sid, id); - // the last part of inter-path overhead is the time between the end of the last (end)path and the end of the event processing - double interpaths = delta(stream.timer_last_path, stream.timer_event.getStopTime()); - stream.timing_perprocess[pid].interpaths += interpaths; - stream.timing_perprocess[pid].paths_interpaths.back() = interpaths; + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} +double +FastTimerService::queryPathTime(edm::StreamID sid, std::string const& path) const +{ + auto const& stream = streams_[sid]; + for (unsigned int pid: boost::irange(0ul, callgraph_.processes().size())) { - // prevent different threads from updating the summary information at the same time - std::lock_guard lock_summary(m_summary_mutex); - - // keep track of the total number of events and add this event's time to the per-run and per-job summary - m_run_summary_perprocess[rid][pid] += stream.timing_perprocess[pid]; - m_job_summary_perprocess[pid] += stream.timing_perprocess[pid]; - - // account the whole event timing details - if (pid+1 == m_process.size()) { - stream.timing.count = 1; - stream.timing.preevent = stream.timing_perprocess[0].preevent; - stream.timing.event = stream.timing_perprocess[0].event; - for (unsigned int i = 1; i < m_process.size(); ++i) { - stream.timing.event += stream.timing_perprocess[i].preevent; - stream.timing.event += stream.timing_perprocess[i].event; - } - m_run_summary[rid] += stream.timing; - m_job_summary += stream.timing; - } + auto const& desc = callgraph_.processDescription(pid); + for (unsigned int id: boost::irange(0ul, desc.paths_.size())) + if (desc.paths_[id].name_ == path) + return ms(stream.processes[pid].paths[id].total.time_real); + for (unsigned int id: boost::irange(0ul, desc.endPaths_.size())) + if (desc.paths_[id].name_ == path) + return ms(stream.processes[pid].endpaths[id].total.time_real); } - // elaborate "exclusive" modules - if (m_enable_timing_exclusive) { - for (auto & keyval: stream.paths[pid]) { - PathInfo & pathinfo = keyval.second; - pathinfo.time_exclusive = pathinfo.time_overhead; - - for (uint32_t i = 0; i < pathinfo.last_run; ++i) { - ModuleInfo * module = pathinfo.modules[i]; - if (module == 0) - // this is a module occurring more than once in the same path, skip it after the first occurrence - continue; - if ((module->run_in_path == & pathinfo) and (module->counter == 1)) - pathinfo.time_exclusive += module->time_active; - } - } - } + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} - // fill the information per module type - // note: this is done here because during event processing two theads could try to update the same module type at the same time - // note: this is done only for the last subprocess, to avoid double conuting the modules' contributions - if ((m_enable_timing_modules) and (pid+1 == m_process.size())) { - for (unsigned int i = 0; i < stream.fast_modules.size(); ++i) - // check for null pointers - there is no guarantee that all module ids are valid and used - if (stream.fast_modules[i]) { - double active = stream.fast_modules[i]->time_active; - ModuleInfo & moduletype = * stream.fast_moduletypes[i]; - moduletype.time_active += active; - moduletype.summary_active += active; - } - } +double +FastTimerService::queryPathTime(edm::StreamID sid, std::string const& process, std::string const& path) const +{ + auto const& stream = streams_[sid]; + unsigned int pid = callgraph_.processId(process); + auto const& desc = callgraph_.processDescription(pid); + for (unsigned int id: boost::irange(0ul, desc.paths_.size())) + if (desc.paths_[id].name_ == path) + return ms(stream.processes[pid].paths[id].total.time_real); + for (unsigned int id: boost::irange(0ul, desc.endPaths_.size())) + if (desc.paths_[id].name_ == path) + return ms(stream.processes[pid].endpaths[id].total.time_real); + + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} - // fill the DQM plots from the internal buffers - if (not m_enable_dqm) - return; +double +FastTimerService::queryHighlightTime(edm::StreamID sid, std::string const& label) const +{ + auto const& stream = streams_[sid]; + for (unsigned int group: boost::irange(0ul, highlight_modules_.size())) + if (highlight_modules_[group].label == label) + return ms(stream.highlight[group].time_real); - // fill plots for per-event time by path - if (m_enable_timing_paths) { + // FIXME issue a LogWarning, raise an exception, or return NaN + return 0.; +} - for (auto & keyval: stream.paths[pid]) { - PathInfo & pathinfo = keyval.second; - stream.dqm_paths[pid].active_time->Fill(pathinfo.index, pathinfo.time_active * 1000.); - if (m_enable_dqm_bypath_active) - pathinfo.dqm_active->Fill(pathinfo.time_active * 1000.); +void +FastTimerService::ignoredSignal(std::string signal) const +{ + LogDebug("FastTimerService") << "The FastTimerService received is currently not monitoring the signal \"" << signal << "\".\n"; +} - stream.dqm_paths[pid].exclusive_time->Fill(pathinfo.index, pathinfo.time_exclusive * 1000.); - if (m_enable_dqm_bypath_exclusive) - pathinfo.dqm_exclusive->Fill(pathinfo.time_exclusive * 1000.); +void +FastTimerService::unsupportedSignal(std::string signal) const +{ + // warn about each signal only once per job + if (unsupported_signals_.insert(signal).second) + edm::LogWarning("FastTimerService") << "The FastTimerService received the unsupported signal \"" << signal << "\".\n" + << "Please report how to reproduce the issue to cms-hlt@cern.ch ."; +} - stream.dqm_paths[pid].total_time->Fill(pathinfo.index, pathinfo.time_total * 1000.); - if (m_enable_dqm_bypath_total) - pathinfo.dqm_total->Fill(pathinfo.time_total * 1000.); +void +FastTimerService::preGlobalBeginRun(edm::GlobalContext const& gc) +{ + ignoredSignal(__func__); - // fill path overhead histograms - if (m_enable_dqm_bypath_overhead) { - pathinfo.dqm_premodules ->Fill(pathinfo.time_premodules * 1000.); - pathinfo.dqm_intermodules->Fill(pathinfo.time_intermodules * 1000.); - pathinfo.dqm_postmodules ->Fill(pathinfo.time_postmodules * 1000.); - pathinfo.dqm_overhead ->Fill(pathinfo.time_overhead * 1000.); - } + // reset the run counters only during the main process being run + if (isFirstSubprocess(gc)) { + subprocess_global_run_check_[gc.runIndex()] = 0; + run_summary_[gc.runIndex()].reset(); + } +} - // fill detailed timing histograms - if (m_enable_dqm_bypath_details) { - for (uint32_t i = 0; i < pathinfo.last_run; ++i) { - ModuleInfo * module = pathinfo.modules[i]; - // skip duplicate modules - if (module == nullptr) - continue; - // fill the total time for all non-duplicate modules - pathinfo.dqm_module_total->Fill(i, module->time_active * 1000.); - // fill the active time only for module that have actually run in this path - if (module->run_in_path == & pathinfo) - pathinfo.dqm_module_active->Fill(i, module->time_active * 1000.); - } - } +void +FastTimerService::postGlobalBeginRun(edm::GlobalContext const&) +{ + ignoredSignal(__func__); +} - // fill path counter histograms - // - also for duplicate modules, to properly extract rejection information - // - fill the N+1th bin for paths accepting the event, so the FastTimerServiceClient can properly measure the last filter efficiency - if (m_enable_dqm_bypath_counters) { - for (uint32_t i = 0; i < pathinfo.last_run; ++i) - pathinfo.dqm_module_counter->Fill(i); - if (pathinfo.accept) - pathinfo.dqm_module_counter->Fill(pathinfo.modules.size()); - } +void +FastTimerService::preStreamBeginRun(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); - } - } + unsigned int sid = sc.streamID().value(); - // fill plots for per-event time by module - // note: this is done only for the last subprocess, to avoid filling the same plots multiple times - if ((m_enable_dqm_bymodule) and (pid+1 == m_process.size())) { - for (auto & keyval : stream.modules) { - ModuleInfo & module = keyval.second; - module.dqm_active->Fill(module.time_active * 1000.); + // reset counters and book the DQM plots during the main process being run + if (isFirstSubprocess(sc)) { + subprocess_run_check_[sid] = 0; + + // book the DQM plots + if (enable_dqm_) { + // define a callback to book the MonitorElements + auto bookTransactionCallback = [&, this] (DQMStore::IBooker & booker) + { + booker.setCurrentFolder(dqm_path_); + stream_plots_[sid].book(booker, callgraph_, + highlight_modules_, + dqm_eventtime_range_, + dqm_eventtime_resolution_, + dqm_pathtime_range_, + dqm_pathtime_resolution_, + dqm_moduletime_range_, + dqm_moduletime_resolution_, + dqm_lumisections_range_, + enable_dqm_bymodule_, + enable_dqm_byls_); + }; + + // book MonitorElements for this stream + edm::Service()->bookTransaction(bookTransactionCallback, sc.eventID().run(), sid, module_id_); } } +} + - // fill plots for per-event time by module type - // note: this is done only for the last subprocess, to avoid filling the same plots multiple times - if ((m_enable_dqm_bymoduletype) and (pid+1 == m_process.size())) { - for (auto & keyval : stream.moduletypes) { - ModuleInfo & module = keyval.second; - module.dqm_active->Fill(module.time_active * 1000.); +void +FastTimerService::preallocate(edm::service::SystemBounds const& bounds) +{ + concurrent_runs_ = bounds.maxNumberOfConcurrentRuns(); + concurrent_streams_ = bounds.maxNumberOfStreams(); + concurrent_threads_ = bounds.maxNumberOfThreads(); + + if (enable_dqm_bynproc_) + dqm_path_ += (boost::format("/Running %d processes") % concurrent_threads_).str(); + + // allocate atomic variables to keep track of the completion of each step, process by process + subprocess_event_check_ = std::make_unique[]>(concurrent_streams_); + for (unsigned int i = 0; i < concurrent_streams_; ++i) + subprocess_event_check_[i] = 0; + subprocess_lumisection_check_ = std::make_unique[]>(concurrent_streams_); + for (unsigned int i = 0; i < concurrent_streams_; ++i) + subprocess_lumisection_check_[i] = 0; + subprocess_run_check_ = std::make_unique[]>(concurrent_streams_); + for (unsigned int i = 0; i < concurrent_streams_; ++i) + subprocess_run_check_[i] = 0; + subprocess_global_run_check_ = std::make_unique[]>(concurrent_streams_); + for (unsigned int i = 0; i < concurrent_runs_; ++i) + subprocess_global_run_check_[i] = 0; + + // assign a pseudo module id to the FastTimerService + module_id_ = edm::ModuleDescription::getUniqueID(); +} + +void +FastTimerService::preSourceConstruction(edm::ModuleDescription const& module) { + callgraph_.preSourceConstruction(module); +} + +void +FastTimerService::preBeginJob(edm::PathsAndConsumesOfModulesBase const& pathsAndConsumes, edm::ProcessContext const & context) { + callgraph_.preBeginJob(pathsAndConsumes, context); +} + +void +FastTimerService::postBeginJob() { + unsigned int modules = callgraph_.size(); + + // module highlights + for (unsigned int group: boost::irange(0ul, highlight_module_psets_.size())) { + // copy and sort for faster search via std::binary_search + auto labels = highlight_module_psets_[group].getUntrackedParameter>("modules"); + std::sort(labels.begin(), labels.end()); + + highlight_modules_[group].label = highlight_module_psets_[group].getUntrackedParameter("label"); + highlight_modules_[group].modules.reserve(labels.size()); + // convert the module labels in module ids + for (unsigned int i = 0; i < modules; ++i) { + auto const & label = callgraph_.module(i).moduleLabel(); + if (std::binary_search(labels.begin(), labels.end(), label)) + highlight_modules_[group].modules.push_back(i); } } + highlight_module_psets_.clear(); - // fill the interpath overhead plot - if (m_enable_timing_paths) - for (unsigned int i = 0; i <= stream.paths[pid].size(); ++i) - stream.dqm_paths[pid].interpaths->Fill(i, stream.timing_perprocess[pid].paths_interpaths[i] * 1000.); + // allocate the resource counters for each stream, process, path and module + ResourcesPerJob temp(callgraph_, highlight_modules_); + streams_.resize(concurrent_streams_, temp); + run_summary_.resize(concurrent_runs_, temp); + job_summary_ = temp; - if (m_enable_dqm_summary) { - if (pid+1 == m_process.size()) - stream.dqm.fill(stream.timing); - stream.dqm_perprocess[pid].fill(stream.timing_perprocess[pid]); + // check that the DQMStore service is available + if (enable_dqm_ and not edm::Service().isAvailable()) { + // the DQMStore is not available, disable all DQM plots + enable_dqm_ = false; + // FIXME issue a LogWarning ? } - if (not m_dqm_luminosity.empty()) { - if (pid+1 == m_process.size()) - for (unsigned int i = 0; i < m_dqm_luminosity.size(); ++i) - stream.dqm_byluminosity[i].fill(stream.luminosity[i], stream.timing); - for (unsigned int i = 0; i < m_dqm_luminosity.size(); ++i) - stream.dqm_perprocess_byluminosity[pid][i].fill(stream.luminosity[i], stream.timing_perprocess[pid]); - } + // allocate the structures to hold pointers to the DQM plots + if (enable_dqm_) + stream_plots_.resize(concurrent_streams_, PlotsPerJob(callgraph_, highlight_modules_)); } -void FastTimerService::preSourceEvent(edm::StreamID sid) { - auto & stream = m_stream[sid]; +void +FastTimerService::postStreamBeginRun(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); +} - // clear the event counters - stream.timing.reset(); - stream.timer_source.start(); +void +FastTimerService::preStreamEndRun(edm::StreamContext const&) +{ + ignoredSignal(__func__); +} - // clear the event counters - // note: this is done here and not in preEvent to avoid clearing the counter before each subprocess - for (auto & keyval : stream.modules) { - keyval.second.timer.reset(); - keyval.second.time_active = 0.; - keyval.second.run_in_path = nullptr; - keyval.second.counter = 0; - } - for (auto & keyval : stream.moduletypes) { - keyval.second.timer.reset(); - keyval.second.time_active = 0.; - keyval.second.run_in_path = nullptr; - keyval.second.counter = 0; +void +FastTimerService::postStreamEndRun(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); + + unsigned int sid = sc.streamID().value(); + + // merge plots only after the last subprocess has run + bool last = isLastSubprocess(subprocess_run_check_[sid]); + if (enable_dqm_ and last) { + DQMStore & store = * edm::Service(); + store.mergeAndResetMEsRunSummaryCache(sc.eventID().run(), sid, module_id_); } +} - // account the time spent before the source - stream.timing.presource = delta(stream.timer_last_transition, stream.timer_source.getStartTime()); +void +FastTimerService::preGlobalBeginLumi(edm::GlobalContext const&) +{ + ignoredSignal(__func__); } -void FastTimerService::postSourceEvent(edm::StreamID sid) { - auto & stream = m_stream[sid]; - stream.timer_source.stop(); - stream.timer_last_transition = stream.timer_source.getStopTime(); +void +FastTimerService::postGlobalBeginLumi(edm::GlobalContext const&) +{ + ignoredSignal(__func__); +} - // account the time spent in the source - stream.timing.source = stream.timer_source.seconds(); +void +FastTimerService::preGlobalEndLumi(edm::GlobalContext const&) +{ + ignoredSignal(__func__); } +void +FastTimerService::postGlobalEndLumi(edm::GlobalContext const&) +{ + ignoredSignal(__func__); +} -void FastTimerService::prePathEvent(edm::StreamContext const & sc, edm::PathContext const & pc) { - std::string const & path = pc.pathName(); - unsigned int pid = processID(sc.processContext()); - unsigned int sid = sc.streamID(); - auto & stream = m_stream[sid]; - - auto keyval = stream.paths[pid].find(path); - if (keyval != stream.paths[pid].end()) { - stream.current_path = & keyval->second; - } else { - // should never get here - stream.current_path = nullptr; - edm::LogError("FastTimerService") << "FastTimerService::prePathEvent: unexpected path " << path; - return; +void +FastTimerService::preStreamBeginLumi(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); + + // reset counters only during the main process transition + if (isFirstSubprocess(sc)) { + unsigned int sid = sc.streamID().value(); + subprocess_lumisection_check_[sid] = 0; } +} - // prepare to measure the time spent between the beginning of the path and the execution of the first module - stream.current_path->first_module = nullptr; +void +FastTimerService::postStreamBeginLumi(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); +} - // time each (end)path - stream.current_path->timer.start(); +void +FastTimerService::preStreamEndLumi(edm::StreamContext const&) +{ + ignoredSignal(__func__); +} - if (path == m_process[pid].first_path) { - // this is the first path, start the "all paths" counter - stream.timer_paths.setStartTime(stream.current_path->timer.getStartTime()); - } else if (path == m_process[pid].first_endpath) { - // this is the first endpath, start the "all paths" counter - stream.timer_endpaths.setStartTime(stream.current_path->timer.getStartTime()); - } +void +FastTimerService::postStreamEndLumi(edm::StreamContext const& sc) { + ignoredSignal(__func__); - // measure the inter-path overhead as the time elapsed since the end of preiovus path - // (or the beginning of the event, if this is the first path - see preEvent) - double interpaths = delta(stream.timer_last_path, stream.current_path->timer.getStartTime()); - stream.timing_perprocess[pid].interpaths += interpaths; - stream.timing_perprocess[pid].paths_interpaths[stream.current_path->index] = interpaths; + unsigned int sid = sc.streamID().value(); + + // merge plots only after the last subprocess has run + bool last = isLastSubprocess(subprocess_lumisection_check_[sid]); + if (enable_dqm_ and last) { + DQMStore & store = * edm::Service(); + store.mergeAndResetMEsLuminositySummaryCache(sc.eventID().run(),sc.eventID().luminosityBlock(),sid, module_id_); + } } +void +FastTimerService::preGlobalEndRun(edm::GlobalContext const&) +{ + ignoredSignal(__func__); +} -void FastTimerService::postPathEvent(edm::StreamContext const & sc, edm::PathContext const & pc, edm::HLTPathStatus const & status) { - std::string const & path = pc.pathName(); - unsigned int pid = processID(sc.processContext()); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; +void +FastTimerService::postGlobalEndRun(edm::GlobalContext const& gc) +{ + ignoredSignal(__func__); - if (stream.current_path == nullptr) { - edm::LogError("FastTimerService") << "FastTimerService::postPathEvent: unexpected path " << path; - return; + // handle the summaries only after the last subprocess has run + bool last = isLastSubprocess(subprocess_global_run_check_[gc.runIndex()]); + if (print_run_summary_ and last) { + edm::LogVerbatim out("FastReport"); + printSummary(out, run_summary_[gc.runIndex()], "Run"); } +} - // time each (end)path - stream.current_path->timer.stop(); - stream.current_path->time_active = stream.current_path->timer.seconds(); - stream.timer_last_path = stream.current_path->timer.getStopTime(); - - double active = stream.current_path->time_active; - - // if enabled, account each (end)path - if (m_enable_timing_paths) { - - PathInfo & pathinfo = * stream.current_path; - pathinfo.summary_active += active; - - // measure the time spent between the execution of the last module and the end of the path - if (m_enable_timing_modules) { - double pre = 0.; // time spent before the first active module - double inter = 0.; // time spent between active modules - double post = 0.; // time spent after the last active module - double overhead = 0.; // time spent before, between, or after modules - double current = 0.; // time spent in modules active in the current path - double total = active; // total per-path time, including modules already run as part of other paths - - // implementation note: - // "active" has already measured all the time spent in this path - // "current" will be the sum of the time spent inside each module while running this path, so that - // "overhead" will be active - current - // "total" will be active + the sum of the time spent in non-active modules - - uint32_t last_run = 0; // index of the last module run in this path, plus one - if (status.wasrun() and not pathinfo.modules.empty()) - last_run = status.index() + 1; // index of the last module run in this path, plus one - for (uint32_t i = 0; i < last_run; ++i) { - ModuleInfo * module = pathinfo.modules[i]; - - if (module == 0) - // this is a module occurring more than once in the same path, skip it after the first occurrence - continue; - - ++module->counter; - if (module->run_in_path == & pathinfo) { - current += module->time_active; - } else { - total += module->time_active; - } +void +FastTimerService::preSourceRun() +{ + ignoredSignal(__func__); +} - } +void +FastTimerService::postSourceRun() +{ + ignoredSignal(__func__); +} - if (stream.current_path->first_module == nullptr) { - // no modules were active during this path, account all the time as overhead - pre = 0.; - inter = 0.; - post = active; - overhead = active; - } else { - // extract overhead information - pre = delta(stream.current_path->timer.getStartTime(), stream.current_path->first_module->timer.getStartTime()); - post = delta(stream.current_module->timer.getStopTime(), stream.current_path->timer.getStopTime()); - inter = active - pre - current - post; - // take care of numeric precision and rounding errors - the timer is less precise than nanosecond resolution - if (std::abs(inter) < 1e-9) - inter = 0.; - overhead = active - current; - // take care of numeric precision and rounding errors - the timer is less precise than nanosecond resolution - if (std::abs(overhead) < 1e-9) - overhead = 0.; - } +void +FastTimerService::preSourceLumi() +{ + ignoredSignal(__func__); +} - pathinfo.time_premodules = pre; - pathinfo.time_intermodules = inter; - pathinfo.time_postmodules = post; - pathinfo.time_overhead = overhead; - pathinfo.time_total = total; - pathinfo.summary_premodules += pre; - pathinfo.summary_intermodules += inter; - pathinfo.summary_postmodules += post; - pathinfo.summary_overhead += overhead; - pathinfo.summary_total += total; - pathinfo.last_run = last_run; - pathinfo.accept = status.accept(); +void +FastTimerService::postSourceLumi() +{ + ignoredSignal(__func__); +} + +void +FastTimerService::postEndJob() +{ + if (print_job_summary_) { + edm::LogVerbatim out("FastReport"); + printSummary(out, job_summary_, "Job"); + } +} + + + +template +void FastTimerService::printEvent(T& out, ResourcesPerJob const& data) const +{ + out << "FastReport --------------------------- Event Summary ---------------------------\n"; + out << "FastReport CPU time Real time Modules\n"; + auto const& source_d = callgraph_.source(); + auto const& source = data.modules[source_d.id()]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") % ms(source.total.time_thread) % ms(source.total.time_real) % source_d.moduleLabel(); + for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) { + auto const& proc_d = callgraph_.processDescription(i); + auto const& proc = data.processes[i]; + out << boost::format("FastReport %10.3f ms %10.3f ms process %s\n") % ms(proc.total.time_thread) % ms(proc.total.time_real) % proc_d.name_; + for (unsigned int m: proc_d.modules_) { + auto const& module_d = callgraph_.module(m); + auto const& module = data.modules[m]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") % ms(module.total.time_thread) % ms(module.total.time_real) % module_d.moduleLabel(); + } + } + out << boost::format("FastReport %10.3f ms %10.3f ms total\n") % ms(data.total.time_thread) % ms(data.total.time_real); + out << '\n'; + out << "FastReport CPU time Real time Processes and Paths\n"; + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") % ms(source.total.time_thread) % ms(source.total.time_real) % source_d.moduleLabel(); + for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) { + auto const& proc_d = callgraph_.processDescription(i); + auto const& proc = data.processes[i]; + out << boost::format("FastReport %10.3f ms %10.3f ms process %s\n") % ms(proc.total.time_thread) % ms(proc.total.time_real) % proc_d.name_; + for (unsigned int p = 0; p < proc.paths.size(); ++p) { + auto const& name = proc_d.paths_[p].name_; + auto const& path = proc.paths[p]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (only scheduled modules)\n") % ms(path.active.time_thread) % ms(path.active.time_real) % name; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (including dependencies)\n") % ms(path.total.time_thread) % ms(path.total.time_real) % name; + } + for (unsigned int p = 0; p < proc.endpaths.size(); ++p) { + auto const& name = proc_d.endPaths_[p].name_; + auto const& path = proc.endpaths[p]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (only scheduled modules)\n") % ms(path.active.time_thread) % ms(path.active.time_real) % name; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (including dependencies)\n") % ms(path.total.time_thread) % ms(path.total.time_real) % name; + } + } + out << boost::format("FastReport %10.3f ms %10.3f ms total\n") % ms(data.total.time_thread) % ms(data.total.time_real); + out << '\n'; + for (unsigned int group: boost::irange(0ul, highlight_modules_.size())) { + out << "FastReport CPU time Real time Highlighted modules\n"; + for (unsigned int m: highlight_modules_[group].modules) { + auto const& module_d = callgraph_.module(m); + auto const& module = data.modules[m]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") % ms(module.total.time_thread) % ms(module.total.time_real) % module_d.moduleLabel(); } + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") % ms(data.highlight[group].time_thread) % ms(data.highlight[group].time_real) % highlight_modules_[group].label; + out << '\n'; } +} - if (path == m_process[pid].last_path) { - // this is the last path, stop and account the "all paths" counter - stream.timer_paths.setStopTime(stream.current_path->timer.getStopTime()); - stream.timing_perprocess[pid].all_paths = stream.timer_paths.seconds(); - } else if (path == m_process[pid].last_endpath) { - // this is the last endpath, stop and account the "all endpaths" counter - stream.timer_endpaths.setStopTime(stream.current_path->timer.getStopTime()); - stream.timing_perprocess[pid].all_endpaths = stream.timer_endpaths.seconds(); +template +void FastTimerService::printSummary(T& out, ResourcesPerJob const& data, std::string const& label) const +{ + out << "FastReport "; + if (label.size() < 60) + for (unsigned int i = (60-label.size()) / 2; i > 0; --i) + out << '-'; + out << ' ' << label << " Summary "; + if (label.size() < 60) + for (unsigned int i = (59-label.size()) / 2; i > 0; --i) + out << '-'; + out << '\n'; + out << "FastReport CPU time avg. when run Real time avg. when run Modules\n"; + auto const& source_d = callgraph_.source(); + auto const& source = data.modules[source_d.id()]; + out << boost::format("FastReport %10.3f ms %10.3f ms %10.3f ms %10.3f ms %s\n") + % (ms(source.total.time_thread) / data.events) % (ms(source.total.time_thread) / source.events) + % (ms(source.total.time_real) / data.events) % (ms(source.total.time_real) / source.events) + % source_d.moduleLabel(); + for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) { + auto const& proc_d = callgraph_.processDescription(i); + auto const& proc = data.processes[i]; + out << boost::format("FastReport %10.3f ms %10.3f ms process %s\n") + % (ms(proc.total.time_thread) / data.events) + % (ms(proc.total.time_real) / data.events) + % proc_d.name_; + for (unsigned int m: proc_d.modules_) { + auto const& module_d = callgraph_.module(m); + auto const& module = data.modules[m]; + out << boost::format("FastReport %10.3f ms %10.3f ms %10.3f ms %10.3f ms %s\n") + % (ms(module.total.time_thread) / data.events) % (ms(module.total.time_thread) / module.events) + % (ms(module.total.time_real) / data.events) % (ms(module.total.time_real) / module.events) + % module_d.moduleLabel(); + } + } + out << boost::format("FastReport %10.3f ms %10.3f ms total\n") + % (ms(data.total.time_thread) / data.events) + % (ms(data.total.time_real) / data.events); + out << '\n'; + out << "FastReport CPU time Real time Processes and Paths\n"; + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") + % (ms(source.total.time_thread) / data.events) + % (ms(source.total.time_real) / data.events) + % source_d.moduleLabel(); + for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) { + auto const& proc_d = callgraph_.processDescription(i); + auto const& proc = data.processes[i]; + out << boost::format("FastReport %10.3f ms %10.3f ms process %s\n") + % (ms(proc.total.time_thread) / data.events) + % (ms(proc.total.time_real) / data.events) + % proc_d.name_; + for (unsigned int p = 0; p < proc.paths.size(); ++p) { + auto const& name = proc_d.paths_[p].name_; + auto const& path = proc.paths[p]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (only scheduled modules)\n") + % (ms(path.active.time_thread) / data.events) + % (ms(path.active.time_real) / data.events) + % name; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (including dependencies)\n") + % (ms(path.total.time_thread) / data.events) + % (ms(path.total.time_real) / data.events) + % name; + } + for (unsigned int p = 0; p < proc.endpaths.size(); ++p) { + auto const& name = proc_d.endPaths_[p].name_; + auto const& path = proc.endpaths[p]; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (only scheduled modules)\n") + % (ms(path.active.time_thread) / data.events) + % (ms(path.active.time_real) / data.events) + % name; + out << boost::format("FastReport %10.3f ms %10.3f ms %s (including dependencies)\n") + % (ms(path.total.time_thread) / data.events) + % (ms(path.total.time_real) / data.events) + % name; + } + } + out << boost::format("FastReport %10.3f ms %10.3f ms total\n") + % (ms(data.total.time_thread) / data.events) + % (ms(data.total.time_real) / data.events); + out << '\n'; + for (unsigned int group: boost::irange(0ul, highlight_modules_.size())) { + out << "FastReport CPU time avg. when run Real time avg. when run Highlighted modules\n"; + for (unsigned int m: highlight_modules_[group].modules) { + auto const& module_d = callgraph_.module(m); + auto const& module = data.modules[m]; + out << boost::format("FastReport %10.3f ms %10.3f ms %10.3f ms %10.3f ms %s\n") + % (ms(module.total.time_thread) / data.events) % (ms(module.total.time_thread) / module.events) + % (ms(module.total.time_real) / data.events) % (ms(module.total.time_real) / module.events) + % module_d.moduleLabel(); + } + out << boost::format("FastReport %10.3f ms %10.3f ms %s\n") + % (ms(data.highlight[group].time_thread) / data.events) + % (ms(data.highlight[group].time_real) / data.events) + % highlight_modules_[group].label; + out << '\n'; } +} +// check if this is the first process being signalled +bool +FastTimerService::isFirstSubprocess(edm::StreamContext const& sc) +{ + return (not sc.processContext()->isSubProcess()); } -void FastTimerService::preModuleEvent(edm::StreamContext const & sc, edm::ModuleCallingContext const & mcc) { - // this is ever called only if m_enable_timing_modules = true - assert(m_enable_timing_modules); +bool +FastTimerService::isFirstSubprocess(edm::GlobalContext const& gc) +{ + return (not gc.processContext()->isSubProcess()); +} - if (mcc.moduleDescription() == nullptr) { - edm::LogError("FastTimerService") << "FastTimerService::postModuleEventDelayedGet: invalid module"; - return; - } +// check if this is the last process being signalled +bool +FastTimerService::isLastSubprocess(std::atomic& check) +{ + // release-acquire semantic guarantees that all writes in this and other threads are visible + // after this operation; full sequentially-consistent ordering is (probably) not needed. + unsigned int old_value = check.fetch_add(1, std::memory_order_acq_rel); + return (old_value == callgraph_.processes().size() - 1); +} - edm::ModuleDescription const & md = * mcc.moduleDescription(); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; - - // time each module - if (md.id() < stream.fast_modules.size()) { - ModuleInfo & module = * stream.fast_modules[md.id()]; - module.run_in_path = stream.current_path; - module.timer.start(); - stream.current_module = & module; - // used to measure the time spent between the beginning of the path and the execution of the first module - if (stream.current_path->first_module == nullptr) - stream.current_path->first_module = & module; - } else { - // should never get here - edm::LogError("FastTimerService") << "FastTimerService::preModuleEvent: unexpected module " << md.moduleLabel(); - } +void +FastTimerService::preEvent(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); } -void FastTimerService::postModuleEvent(edm::StreamContext const & sc, edm::ModuleCallingContext const & mcc) { - // this is ever called only if m_enable_timing_modules = true - assert(m_enable_timing_modules); +void +FastTimerService::postEvent(edm::StreamContext const& sc) +{ + ignoredSignal(__func__); - if (mcc.moduleDescription() == nullptr) { - edm::LogError("FastTimerService") << "FastTimerService::postModuleEventDelayedGet: invalid module"; + unsigned int pid = callgraph_.processId(* sc.processContext()); + unsigned int sid = sc.streamID(); + auto & stream = streams_[sid]; + auto & process = callgraph_.processDescription(pid); + + // compute the event timing as the sum of all modules' timing + auto & data = stream.processes[pid].total; + for (unsigned int i: process.modules_) + data += stream.modules[i].total; + stream.total += data; + + // handle the summaries and fill the plots only after the last subprocess has run + bool last = isLastSubprocess(subprocess_event_check_[sid]); + if (not last) return; + + // highlighted modules + for (unsigned int group: boost::irange(0ul, highlight_modules_.size())) + for (unsigned int i: highlight_modules_[group].modules) + stream.highlight[group] += stream.modules[i].total; + + // avoid concurrent access to the summary objects + { + std::lock_guard guard(summary_mutex_); + job_summary_ += stream; + run_summary_[sc.runIndex()] += stream; } - edm::ModuleDescription const & md = * mcc.moduleDescription(); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; - - double active = 0.; - - // time and account each module - if (md.id() < stream.fast_modules.size()) { - ModuleInfo & module = * stream.fast_modules[md.id()]; - module.timer.stop(); - active = module.timer.seconds(); - module.time_active = active; - module.summary_active += active; - // plots are filled post event processing - } else { - // should never get here - edm::LogError("FastTimerService") << "FastTimerService::postModuleEvent: unexpected module " << md.moduleLabel(); + if (print_event_summary_) { + edm::LogVerbatim out("FastReport"); + printEvent(out, stream); } + + if (enable_dqm_) + stream_plots_[sid].fill(callgraph_, stream, sc.eventID().luminosityBlock()); } -void FastTimerService::preModuleEventDelayedGet(edm::StreamContext const & sc, edm::ModuleCallingContext const & mcc) { - // this is ever called only if m_enable_timing_modules = true - assert(m_enable_timing_modules); +void +FastTimerService::preSourceEvent(edm::StreamID sid) +{ + // clear the event counters + auto & stream = streams_[sid]; + stream.reset(); + ++stream.events; - if (mcc.moduleDescription() == nullptr) { - edm::LogError("FastTimerService") << "FastTimerService::postModuleEventDelayedGet: invalid module"; - return; - } + subprocess_event_check_[sid] = 0; - edm::ModuleDescription const & md = * mcc.moduleDescription(); - unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; + thread().measure(); +} - // if the ModuleCallingContext state is "Pefetching", the module is not running, - // and is asking for its dependencies due to a "consumes" declaration. - // we can ignore this signal. - // if the ModuleCallingContext state is "Running", the module was running: - // it declared its dependencies as "mayConsume", and is now calling getByToken/getByLabel. - // we pause the timer for this module, and resume it later in the postModuleEventDelayedGet signal. +void +FastTimerService::postSourceEvent(edm::StreamID sid) +{ + edm::ModuleDescription const& md = callgraph_.source(); + unsigned int id = md.id(); + auto & stream = streams_[sid]; - // if the ModuleCallingContext state is "Invalid", we ignore the signal. + thread().measure_and_store(stream.modules[id].total); + ++stream.modules[id].events; +} - if (mcc.state() == edm::ModuleCallingContext::State::kRunning) { - if (md.id() < stream.fast_modules.size()) { - ModuleInfo & module = * stream.fast_modules[md.id()]; - module.timer.pause(); - } else { - // should never get here - edm::LogError("FastTimerService") << "FastTimerService::preModuleEventDelayedGet: unexpected module " << md.moduleLabel(); - } - } +void +FastTimerService::prePathEvent(edm::StreamContext const& sc, edm::PathContext const & pc) +{ + unsigned int sid = sc.streamID().value(); + unsigned int pid = callgraph_.processId(* sc.processContext()); + unsigned int id = pc.pathID(); + auto & stream = streams_[sid]; + auto & data = pc.isEndPath() ? stream.processes[pid].endpaths[id] : stream.processes[pid].paths[id]; + data.status = false; + data.last = 0; } -void FastTimerService::postModuleEventDelayedGet(edm::StreamContext const & sc, edm::ModuleCallingContext const & mcc) { - // this is ever called only if m_enable_timing_modules = true - assert(m_enable_timing_modules); - if (mcc.moduleDescription() == nullptr) { - edm::LogError("FastTimerService") << "FastTimerService::postModuleEventDelayedGet: invalid module"; - return; +void +FastTimerService::postPathEvent(edm::StreamContext const& sc, edm::PathContext const & pc, edm::HLTPathStatus const & status) +{ + unsigned int sid = sc.streamID().value(); + unsigned int pid = callgraph_.processId(* sc.processContext()); + unsigned int id = pc.pathID(); + auto & stream = streams_[sid]; + auto & data = pc.isEndPath() ? stream.processes[pid].endpaths[id] : stream.processes[pid].paths[id]; + + auto const& path = pc.isEndPath() ? callgraph_.processDescription(pid).endPaths_[id] : callgraph_.processDescription(pid).paths_[id]; + unsigned int index = path.modules_on_path_.empty() ? 0 : status.index() + 1; + data.last = path.modules_on_path_.empty() ? 0 : path.last_dependency_of_module_[status.index()]; + + for (unsigned int i = 0; i < index; ++i) { + auto const& module = stream.modules[path.modules_on_path_[i]]; + data.active += module.total; } + for (unsigned int i = 0; i < data.last; ++i) { + auto const& module = stream.modules[path.modules_and_dependencies_[i]]; + data.total += module.total; + } +} - edm::ModuleDescription const & md = * mcc.moduleDescription(); +void +FastTimerService::preModuleEvent(edm::StreamContext const& sc, edm::ModuleCallingContext const & mcc) +{ + thread().measure(); +} + +void +FastTimerService::postModuleEvent(edm::StreamContext const& sc, edm::ModuleCallingContext const & mcc) +{ + edm::ModuleDescription const& md = * mcc.moduleDescription(); + unsigned int id = md.id(); unsigned int sid = sc.streamID().value(); - auto & stream = m_stream[sid]; - - // see the description of the possible ModuleCallingContext states in preModuleEventDelayedGet, above. - if (mcc.state() == edm::ModuleCallingContext::State::kRunning) { - if (md.id() < stream.fast_modules.size()) { - ModuleInfo & module = * stream.fast_modules[md.id()]; - module.timer.resume(); - } else { - // should never get here - edm::LogError("FastTimerService") << "FastTimerService::postModuleEventDelayedGet: unexpected module " << md.moduleLabel(); - } - } + auto & stream = streams_[sid]; + thread().measure_and_store(stream.modules[id].total); + ++stream.modules[id].events; } -// associate to a path all the modules it contains -void FastTimerService::fillPathMap(unsigned int pid, std::string const & name, std::vector const & modules) { - for (auto & stream: m_stream) { - - std::vector & pathmap = stream.paths[pid][name].modules; - pathmap.clear(); - pathmap.reserve( modules.size() ); - std::unordered_set pool; // keep track of inserted modules - for (auto const & module: modules) { - // fix the name of negated or ignored modules - std::string const & label = (module[0] == '!' or module[0] == '-') ? module.substr(1) : module; - - auto const & it = stream.modules.find(label); - if (it == stream.modules.end()) { - // no matching module was found - pathmap.push_back( 0 ); - } else if (pool.insert(& it->second).second) { - // new module - pathmap.push_back(& it->second); - } else { - // duplicate module - pathmap.push_back( 0 ); - } - } +void +FastTimerService::preModuleEventDelayedGet(edm::StreamContext const& sc, edm::ModuleCallingContext const & mcc) +{ + unsupportedSignal(__func__); +} - } +void +FastTimerService::postModuleEventDelayedGet(edm::StreamContext const& sc, edm::ModuleCallingContext const & mcc) +{ + unsupportedSignal(__func__); } -// find the first and last non-empty paths, optionally skipping the first one -std::pair FastTimerService::findFirstLast(unsigned int pid, std::vector const & paths, bool skip) { - std::vector p(paths.size(), nullptr); +void +FastTimerService::preModuleEventPrefetching(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); +} - // mark the empty paths - auto address_if_non_empty = [&](std::string const & name){ - return m_stream.front().paths[pid][name].modules.empty() ? nullptr : & name; - }; - std::transform(paths.begin(), paths.end(), p.begin(), address_if_non_empty); +void +FastTimerService::postModuleEventPrefetching(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); +} - // optionally, skip the first path - if (skip and not p.empty()) - p.erase(p.begin()); +void +FastTimerService::preEventReadFromSource(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); +} - // remove the empty paths - p.erase(std::remove(p.begin(), p.end(), nullptr), p.end()); +void +FastTimerService::postEventReadFromSource(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); +} - // return the first and last non-empty paths, if there are any - if (not p.empty()) - return std::make_pair(* p.front(), * p.back()); - else - return std::make_pair(std::string(), std::string()); +void +FastTimerService::preModuleGlobalBeginRun(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the current module/path/event -// Note: these functions incur in a "per-call timer overhead" (see above), currently of the order of 340ns +void +FastTimerService::postModuleGlobalBeginRun(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); +} -// return the time spent since the last preModuleEvent() event -double FastTimerService::currentModuleTime(edm::StreamID sid) const { - return m_stream[sid].current_module->timer.secondsUntilNow(); +void +FastTimerService::preModuleGlobalEndRun(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// return the time spent since the last prePathEvent() event -double FastTimerService::currentPathTime(edm::StreamID sid) const { - return m_stream[sid].current_path->timer.secondsUntilNow(); +void +FastTimerService::postModuleGlobalEndRun(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// return the time spent since the last preEvent() event -double FastTimerService::currentEventTime(edm::StreamID sid) const { - return m_stream[sid].timer_event.secondsUntilNow(); +void +FastTimerService::preModuleGlobalBeginLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in a module (available after the module has run) -double FastTimerService::queryModuleTime(edm::StreamID sid, const edm::ModuleDescription & module) const { - if (module.id() < m_stream[sid].fast_modules.size()) { - return m_stream[sid].fast_modules[module.id()]->time_active; - } else { - //edm::LogError("FastTimerService") << "FastTimerService::queryModuleTime: unexpected module " << module.moduleLabel(); - return 0.; - } +void +FastTimerService::postModuleGlobalBeginLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in a module (available after the module has run) -double FastTimerService::queryModuleTime(edm::StreamID sid, unsigned int id) const { - if (id < m_stream[sid].fast_modules.size()) { - return m_stream[sid].fast_modules[id]->time_active; - } else { - //edm::LogError("FastTimerService") << "FastTimerService::queryModuleTime: unexpected module id " << id; - return 0.; - } +void +FastTimerService::preModuleGlobalEndLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in a module (available after the module has run) -double FastTimerService::queryModuleTimeByLabel(edm::StreamID sid, const std::string & label) const { - auto const & keyval = m_stream[sid].modules.find(label); - if (keyval != m_stream[sid].modules.end()) { - return keyval->second.time_active; - } else { - // module not found - //edm::LogError("FastTimerService") << "FastTimerService::queryModuleTimeByLabel: unexpected module " << label; - return 0.; - } +void +FastTimerService::postModuleGlobalEndLumi(edm::GlobalContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in a type of module (available after the module has run) -double FastTimerService::queryModuleTimeByType(edm::StreamID sid, const std::string & type) const { - auto const & keyval = m_stream[sid].moduletypes.find(type); - if (keyval != m_stream[sid].moduletypes.end()) { - return keyval->second.time_active; - } else { - // module not found - //edm::LogError("FastTimerService") << "FastTimerService::queryModuleTimeByType: unexpected module type " << type; - return 0.; - } +void +FastTimerService::preModuleStreamBeginRun(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -/* FIXME re-implement taking into account subprocesses -// query the time spent in a path (available after the path has run) -double FastTimerService::queryPathActiveTime(edm::StreamID sid, const std::string & path) const { - PathMap::const_iterator keyval = m_stream[sid].paths.find(path); - if (keyval != m_stream[sid].paths.end()) { - return keyval->second.time_active; - } else { - edm::LogError("FastTimerService") << "FastTimerService::queryPathActiveTime: unexpected path " << path; - return 0.; - } +void +FastTimerService::postModuleStreamBeginRun(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in a path (available after the path has run) -double FastTimerService::queryPathExclusiveTime(edm::StreamID sid, const std::string & path) const { - PathMap::const_iterator keyval = m_stream[sid].paths.find(path); - if (keyval != m_stream[sid].paths.end()) { - return keyval->second.time_exclusive; - } else { - edm::LogError("FastTimerService") << "FastTimerService::queryPathExclusiveTime: unexpected path " << path; - return 0.; - } +void +FastTimerService::preModuleStreamEndRun(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the total time spent in a path (available after the path has run) -double FastTimerService::queryPathTotalTime(edm::StreamID sid, const std::string & path) const { - PathMap::const_iterator keyval = m_stream[sid].paths.find(path); - if (keyval != m_stream[sid].paths.end()) { - return keyval->second.time_total; - } else { - edm::LogError("FastTimerService") << "FastTimerService::queryPathTotalTime: unexpected path " << path; - return 0.; - } +void +FastTimerService::postModuleStreamEndRun(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -*/ -// query the time spent in the current event's source (available during event processing) -double FastTimerService::querySourceTime(edm::StreamID sid) const { - return m_stream[sid].timing.source; +void +FastTimerService::preModuleStreamBeginLumi(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent processing the current event (available after the event has been processed) -double FastTimerService::queryEventTime(edm::StreamID sid) const { - return m_stream[sid].timing.event; +void +FastTimerService::postModuleStreamBeginLumi(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -/* FIXME re-implement taking into account subprocesses -// query the time spent in the current event's paths (available during endpaths) -double FastTimerService::queryPathsTime(edm::StreamID sid) const { - return m_stream[sid].timing.all_paths; +void +FastTimerService::preModuleStreamEndLumi(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -// query the time spent in the current event's endpaths (available after all endpaths have run) -double FastTimerService::queryEndPathsTime(edm::StreamID sid) const { - return m_stream[sid].timing.all_endpaths; +void +FastTimerService::postModuleStreamEndLumi(edm::StreamContext const&, edm::ModuleCallingContext const&) +{ + ignoredSignal(__func__); } -*/ -// describe the module's configuration -void FastTimerService::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - edm::ParameterSetDescription desc; - desc.addUntracked( "useRealTimeClock", true); - desc.addUntracked( "enableTimingPaths", true); - desc.addUntracked( "enableTimingModules", true); - desc.addUntracked( "enableTimingExclusive", false); - desc.addUntracked( "enableTimingSummary", false); - desc.addUntracked( "skipFirstPath", false), - desc.addUntracked( "enableDQM", true); - desc.addUntracked( "enableDQMbyPathActive", false); - desc.addUntracked( "enableDQMbyPathTotal", true); - desc.addUntracked( "enableDQMbyPathOverhead", false); - desc.addUntracked( "enableDQMbyPathDetails", false); - desc.addUntracked( "enableDQMbyPathCounters", true); - desc.addUntracked( "enableDQMbyPathExclusive", false); - desc.addUntracked( "enableDQMbyModule", false); - desc.addUntracked( "enableDQMbyModuleType", false); - desc.addUntracked( "enableDQMSummary", false); - desc.addUntracked( "enableDQMbyLumiSection", false); - desc.addUntracked( "enableDQMbyProcesses", false); - desc.addUntracked( "dqmTimeRange", 1000. ); // ms - desc.addUntracked( "dqmTimeResolution", 5. ); // ms - desc.addUntracked( "dqmPathTimeRange", 100. ); // ms - desc.addUntracked( "dqmPathTimeResolution", 0.5); // ms - desc.addUntracked( "dqmModuleTimeRange", 40. ); // ms - desc.addUntracked( "dqmModuleTimeResolution", 0.2); // ms - desc.addUntracked( "dqmLumiSectionsRange", 2500 ); // ~ 16 hours - desc.addUntracked( "dqmPath", "HLT/TimerService"); - descriptions.add("FastTimerService", desc); + +FastTimerService::Measurement & +FastTimerService::thread() +{ + return threads_.local(); } -// assign a "process id" to a process, given its ProcessContext -unsigned int FastTimerService::processID(edm::ProcessContext const * context) + +// describe the module's configuration +void +FastTimerService::fillDescriptions(edm::ConfigurationDescriptions & descriptions) { - unsigned int pid = 0; + edm::ParameterSetDescription desc; + desc.addUntracked( "printEventSummary", false); + desc.addUntracked( "printRunSummary", true); + desc.addUntracked( "printJobSummary", true); + desc.addUntracked( "enableDQM", true); + desc.addUntracked( "enableDQMbyModule", false); + desc.addUntracked( "enableDQMbyLumiSection", false); + desc.addUntracked( "enableDQMbyProcesses", false); + desc.addUntracked( "dqmTimeRange", 1000. ); // ms + desc.addUntracked( "dqmTimeResolution", 5. ); // ms + desc.addUntracked( "dqmPathTimeRange", 100. ); // ms + desc.addUntracked( "dqmPathTimeResolution", 0.5); // ms + desc.addUntracked( "dqmModuleTimeRange", 40. ); // ms + desc.addUntracked( "dqmModuleTimeResolution", 0.2); // ms + desc.addUntracked( "dqmLumiSectionsRange", 2500 ); // ~ 16 hours + desc.addUntracked( "dqmPath", "HLT/TimerService"); + + edm::ParameterSetDescription highlightModulesDescription; + highlightModulesDescription.addUntracked>("modules", {}); + highlightModulesDescription.addUntracked("label", "producers"); + desc.addVPSetUntracked("highlightModules", highlightModulesDescription, {}); + + // # OBSOLETE - these parameters are ignored, they are left only not to break old configurations + // they will not be printed in the generated cfi.py file + desc.addOptionalNode(edm::ParameterDescription("useRealTimeClock", true, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableTimingPaths", true, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableTimingModules", true, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableTimingExclusive", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableTimingSummary", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("skipFirstPath", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathActive", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathTotal", true, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathOverhead", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathDetails", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathCounters", true, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyPathExclusive", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMbyModuleType", false, false), false)->setComment("This parameter is obsolete and will be ignored."); + desc.addOptionalNode(edm::ParameterDescription("enableDQMSummary", false, false), false)->setComment("This parameter is obsolete and will be ignored."); - // iterate through the chain of ProcessContext until we reach the topmost process - while (context->isSubProcess()) { - context = & context->parentProcessContext(); - ++pid; - } - return pid; + descriptions.add("FastTimerService", desc); } diff --git a/HLTrigger/Timer/src/ProcessCallGraph.cc b/HLTrigger/Timer/src/ProcessCallGraph.cc new file mode 100644 index 0000000000000..3a32cb3e886c9 --- /dev/null +++ b/HLTrigger/Timer/src/ProcessCallGraph.cc @@ -0,0 +1,346 @@ +/* + * + */ + +#include +#include +#include +#include +#include + +// boost optional (used by boost graph) results in some false positives with -Wmaybe-uninitialized +#pragma GCC diagnostic push +#pragma GCC diagnostic ignored "-Wmaybe-uninitialized" +#include +#pragma GCC diagnostic pop + +#include "DataFormats/Provenance/interface/ModuleDescription.h" +#include "FWCore/Framework/interface/TriggerNamesService.h" +#include "FWCore/MessageLogger/interface/MessageLogger.h" +#include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h" +#include "FWCore/ParameterSet/interface/ParameterSet.h" +#include "FWCore/ParameterSet/interface/ParameterSetDescription.h" +#include "FWCore/ParameterSet/interface/Registry.h" +#include "FWCore/ServiceRegistry/interface/ActivityRegistry.h" +#include "FWCore/ServiceRegistry/interface/ConsumesInfo.h" +#include "FWCore/ServiceRegistry/interface/PathsAndConsumesOfModulesBase.h" +#include "FWCore/ServiceRegistry/interface/ProcessContext.h" +#include "FWCore/ServiceRegistry/interface/Service.h" +#include "FWCore/Utilities/interface/EDMException.h" +#include "HLTrigger/Timer/interface/ProcessCallGraph.h" + + +ProcessCallGraph::ProcessCallGraph() +{ +} + + +// adaptor to use range-based for loops with boost::graph edges(...) and vertices(...) functions +template +struct iterator_pair_as_a_range : std::pair +{ +public: + using std::pair::pair; + + I begin() { return this->first; } + I end() { return this->second; } +}; + +template +iterator_pair_as_a_range make_range(std::pair p) +{ + return iterator_pair_as_a_range(p); +} + + +// FIXME +// - check that the Source has not already been added +void +ProcessCallGraph::preSourceConstruction(edm::ModuleDescription const & module) +{ + // keep track of the Source module id + source_ = module.id(); + + // create graph vertex for the source module + boost::add_vertex(graph_); + graph_.m_graph[module.id()] = { module, edm::EDMModuleType::kSource, true }; +} + + +// FIXME +// - check that the Source has already been added +// - check that all module ids are valid (e.g. subprocesses are not being added in +// the wrong order) +void +ProcessCallGraph::preBeginJob(edm::PathsAndConsumesOfModulesBase const & pathsAndConsumes, edm::ProcessContext const & context) +{ + unsigned int pid = registerProcess(context); + + // work on the full graph (for the main process) or a subgraph (for a subprocess) + GraphType & graph = context.isSubProcess() ? graph_.create_subgraph() : graph_.root(); + + // set the graph name property to the process name + boost::get_property(graph, boost::graph_name) = context.processName(); + + // create graph vertices associated to all modules in the process + auto size = pathsAndConsumes.allModules().size(); + for (size_t i = 0; i < size; ++i) + boost::add_vertex(graph); + + // set the vertices properties (use the module id as the global index into the graph) + std::vector modules; + modules.reserve(size); + for (edm::ModuleDescription const * module: pathsAndConsumes.allModules()) { + modules.push_back(module->id()); + graph_.m_graph[module->id()] = { *module, edmModuleTypeEnum(*module), false }; + } + + // add graph edges associated to module dependencies + for (edm::ModuleDescription const * consumer: pathsAndConsumes.allModules()) { + for (edm::ModuleDescription const * module: pathsAndConsumes.modulesWhoseProductsAreConsumedBy(consumer->id())) { + // module `consumer' depends on module `module' + boost::add_edge(consumer->id(), module->id(), graph_); + } + } + + // extract path names from the TriggerNamesService + edm::service::TriggerNamesService const & tns = * edm::Service(); + + // extract the details of the paths and endpaths: name, modules on the path, and their dependencies + size = pathsAndConsumes.paths().size(); + assert (tns.getTrigPaths().size() == size); + std::vector paths; + paths.reserve(size); + for (unsigned int i = 0; i < size; ++i) { + std::vector modules; + for (edm::ModuleDescription const * module: pathsAndConsumes.modulesOnPath(i)) { + modules.push_back(module->id()); + // mark the modules in the Paths as scheduled + graph_.m_graph[module->id()].scheduled_ = true; + } + auto deps = dependencies(modules); + paths.emplace_back(tns.getTrigPath(i), modules, deps.first, deps.second); + } + size = pathsAndConsumes.endPaths().size(); + std::vector endPaths; + endPaths.reserve(size); + for (unsigned int i = 0; i < size; ++i) { + std::vector modules; + for (edm::ModuleDescription const * module: pathsAndConsumes.modulesOnEndPath(i)) { + modules.push_back(module->id()); + // mark the modules in the EndPaths as scheduled + graph_.m_graph[module->id()].scheduled_ = true; + } + auto deps = dependencies(modules); + endPaths.emplace_back(tns.getEndPath(i), modules, deps.first, deps.second); + } + + // store the description of process, modules and paths + process_description_.emplace_back( + context.processName(), + graph, + modules, + paths, + endPaths); + assert(process_description_.size() == pid+1); + + // attach a subprocess to its parent + if (context.isSubProcess()) { + unsigned int parent_pid = processId(context.parentProcessContext()); + process_description_[parent_pid].subprocesses_.push_back(pid); + } +} + + +// number of modules stored in the call graph +unsigned int +ProcessCallGraph::size() const +{ + return boost::num_vertices(graph_); +} + + +// retrieve the ModuleDescriptio associated to the given id and vertex +edm::ModuleDescription const & +ProcessCallGraph::source() const +{ + return graph_.m_graph[source_].module_; +} + + +// retrieve the ModuleDescription associated to the given id and vertex +edm::ModuleDescription const & +ProcessCallGraph::module(unsigned int module) const +{ + return graph_.m_graph[module].module_; +} + + +// retrieve the full information for a given module +ProcessCallGraph::NodeType const & +ProcessCallGraph::operator[](unsigned int module) const +{ + return graph_.m_graph[module]; +} + + +// find the dependencies of the given module +std::vector +ProcessCallGraph::depends(unsigned int module) const +{ + std::vector colors(boost::num_vertices(graph_)); + auto colormap = boost::make_container_vertex_map(colors); + + // depht-first visit all vertices starting from the given module + boost::default_dfs_visitor visitor; + boost::depth_first_visit(graph_, module, visitor, colormap); + + // count the visited vertices (the `black' ones) in order to properly size the + // output vector; then fill the dependencies with the list of visited nodes + unsigned int size = 0; + for (unsigned int i = 0; i < colors.size(); ++i) + if (boost::black_color == colors[i]) + ++size; + std::vector dependencies(size); + unsigned j = 0; + for (unsigned int i = 0; i < colors.size(); ++i) + if (boost::black_color == colors[i]) + dependencies[j++] = i; + assert(size == j); + + return dependencies; +} + +// find the dependencies of all modules in the given path +// +// return two vector: +// - the first lists all the dependencies for the whole path +// - the second lists the one-after-the-last dependency index into the first vector for each module +std::pair, std::vector> +ProcessCallGraph::dependencies(std::vector const & path) +{ + std::vector colors(boost::num_vertices(graph_)); + auto colormap = boost::make_container_vertex_map(colors); + + // first, find and count all the path's modules' dependencies + boost::default_dfs_visitor visitor; + for (unsigned int module: path) + boost::depth_first_visit(graph_, module, visitor, colormap); + + unsigned int size = 0; + for (unsigned int i = 0; i < colors.size(); ++i) + if (colors[i] == 0) + ++size; + + // allocate the output vectors + std::vector dependencies(size); + dependencies.resize(0); + std::vector indices(path.size()); + indices.resize(0); + + // reset the color map + for (unsigned int i = 0; i < colors.size(); ++i) + colors[i] = 0; + + // find again all the dependencies, and record those associated to each module + struct record_vertices : boost::default_dfs_visitor { + record_vertices(std::vector & vertices) : + vertices_(vertices) { } + + void discover_vertex(unsigned int vertex, GraphType const& graph) { + vertices_.push_back(vertex); + } + + std::vector & vertices_; + }; + record_vertices recorder(dependencies); + + for (unsigned int module: path) { + // skip modules that have already been added as dependencies + if (colors[module] != boost::black_color) + boost::depth_first_visit(graph_, module, recorder, colormap); + indices.push_back(dependencies.size()); + } + + return std::make_pair(dependencies, indices); + +} + +// register a (sub)process and assigns it a "process id" +// if called with a duplicate process name, returns the original process id +unsigned int ProcessCallGraph::registerProcess(edm::ProcessContext const & context) +{ + static unsigned int s_id = 0; + + // registerProcess (called by preBeginJob) must be called for the parent process before its subprocess(es) + if (context.isSubProcess() and process_id_.find(context.parentProcessContext().processName()) == process_id_.end()) { + throw edm::Exception(edm::errors::LogicError) + << "ProcessCallGraph::preBeginJob(): called for subprocess \"" << context.processName() << "\"" + << " before being called for its parent process \"" << context.parentProcessContext().processName() << "\""; + } + + // registerProcess (called by preBeginJob) should be called once or each (sub)process + auto id = process_id_.find(context.processName()); + if (id != process_id_.end()) { + throw edm::Exception(edm::errors::LogicError) + << "ProcessCallGraph::preBeginJob(): called twice for the same " + << (context.isSubProcess() ? "subprocess" : "process") << " " << context.processName(); + } + + std::tie(id, std::ignore) = process_id_.insert(std::make_pair(context.processName(), s_id++)); + return id->second; +} + + +// retrieve the "process id" of a process, given its ProcessContex +// throws an exception if the (sub)process was not registered +unsigned int ProcessCallGraph::processId(edm::ProcessContext const & context) const +{ + auto id = process_id_.find(context.processName()); + if (id == process_id_.end()) + throw edm::Exception(edm::errors::LogicError) + << "ProcessCallGraph::processId(): unexpected " << (context.isSubProcess() ? "subprocess" : "process") << " " << context.processName(); + return id->second; +} + + +// retrieve the "process id" of a process, given its ProcessContex +// throws an exception if the (sub)process was not registered +unsigned int ProcessCallGraph::processId(std::string const & processName) const +{ + auto id = process_id_.find(processName); + if (id == process_id_.end()) + throw edm::Exception(edm::errors::LogicError) + << "ProcessCallGraph::processId(): unexpected (sub)process " << processName; + return id->second; +} + + +// retrieve the number of processes +std::vector const & ProcessCallGraph::processes() const +{ + return process_description_; +} + + +// retrieve information about a process, given its "process id" +ProcessCallGraph::ProcessType const & ProcessCallGraph::processDescription(unsigned int pid) const +{ + return process_description_.at(pid); +} + + +// retrieve information about a process, given its ProcessContex +ProcessCallGraph::ProcessType const & ProcessCallGraph::processDescription(edm::ProcessContext const & context) const +{ + unsigned int pid = processId(context); + return process_description_[pid]; +} + + +// retrieve information about a process, given its ProcessContex +ProcessCallGraph::ProcessType const & ProcessCallGraph::processDescription(std::string const & processName) const +{ + unsigned int pid = processId(processName); + return process_description_[pid]; +} diff --git a/HLTrigger/Timer/test/testFastTimerService.py b/HLTrigger/Timer/test/testFastTimerService.py index b83cb3ea5bc68..a78e14a807dce 100644 --- a/HLTrigger/Timer/test/testFastTimerService.py +++ b/HLTrigger/Timer/test/testFastTimerService.py @@ -23,21 +23,9 @@ del process.FastTimerService process.load('HLTrigger/Timer/FastTimerService_cff') -process.FastTimerService.useRealTimeClock = False -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True -process.FastTimerService.enableTimingSummary = True -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printRunSummary = True +process.FastTimerService.printJobSummary = True process.FastTimerService.enableDQM = True -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True process.FastTimerService.enableDQMbyModule = True -process.FastTimerService.enableDQMbyModuleType = True -process.FastTimerService.enableDQMSummary = True process.FastTimerService.enableDQMbyLumiSection = True process.FastTimerService.enableDQMbyProcesses = True diff --git a/RecoLocalCalo/EcalRecProducers/test/testMultipleEcalRecoLocal_cfg.py b/RecoLocalCalo/EcalRecProducers/test/testMultipleEcalRecoLocal_cfg.py index c49740a66b2d4..79abe347441ea 100644 --- a/RecoLocalCalo/EcalRecProducers/test/testMultipleEcalRecoLocal_cfg.py +++ b/RecoLocalCalo/EcalRecProducers/test/testMultipleEcalRecoLocal_cfg.py @@ -131,38 +131,15 @@ # instrument the menu with the FastTimerService process.load( "HLTrigger.Timer.FastTimerService_cfi" ) -# this is currently ignored in 7.x, and alway uses the real tim clock -process.FastTimerService.useRealTimeClock = True - -# enable specific features -process.FastTimerService.enableTimingPaths = True -process.FastTimerService.enableTimingModules = True -process.FastTimerService.enableTimingExclusive = True - # print a text summary at the end of the job -process.FastTimerService.enableTimingSummary = True - -# skip the first path (useful for HLT timing studies to disregard the time spent loading event and conditions data) -process.FastTimerService.skipFirstPath = False +process.FastTimerService.printJobSummary = True # enable per-event DQM plots process.FastTimerService.enableDQM = True -# enable per-path DQM plots -process.FastTimerService.enableDQMbyPathActive = True -process.FastTimerService.enableDQMbyPathTotal = True -process.FastTimerService.enableDQMbyPathOverhead = True -process.FastTimerService.enableDQMbyPathDetails = True -process.FastTimerService.enableDQMbyPathCounters = True -process.FastTimerService.enableDQMbyPathExclusive = True - # enable per-module DQM plots process.FastTimerService.enableDQMbyModule = True -process.FastTimerService.enableDQMbyModuleType = True -# enable per-event DQM sumary plots -process.FastTimerService.enableDQMSummary = True - # enable per-event DQM plots by lumisection process.FastTimerService.enableDQMbyLumiSection = True process.FastTimerService.dqmLumiSectionsRange = 2500 # lumisections (23.31 s)