Framework/src/SystemTimeKeeper.cc

0001 // -*- C++ -*-
0002 //
0003 // Package:     FWCore/Framework
0004 // Class  :     SystemTimeKeeper
0005 //
0006 // Implementation:
0007 //     [Notes on implementation]
0008 //
0009 // Original Author:  Chris Jones
0010 //         Created:  Mon, 07 Jul 2014 14:37:32 GMT
0011 //
0012
0013 // system include files
0014 #include <algorithm>
0015
0016 // user include files
0017 #include "FWCore/Utilities/interface/StreamID.h"
0018 #include "FWCore/ServiceRegistry/interface/StreamContext.h"
0019 #include "FWCore/ServiceRegistry/interface/PathContext.h"
0020 #include "FWCore/ServiceRegistry/interface/PlaceInPathContext.h"
0021 #include "FWCore/ServiceRegistry/interface/ModuleCallingContext.h"
0022 #include "DataFormats/Provenance/interface/ModuleDescription.h"
0023 #include "DataFormats/Common/interface/HLTPathStatus.h"
0024 #include "FWCore/Framework/src/TriggerTimingReport.h"
0025 #include "FWCore/Framework/interface/TriggerNamesService.h"
0026 #include "FWCore/Utilities/interface/Algorithms.h"
0027 #include "FWCore/Framework/interface/SystemTimeKeeper.h"
0028
0029 using namespace edm;
0030
0031 namespace {
0032   bool lessModuleDescription(const ModuleDescription* iLHS, const ModuleDescription* iRHS) {
0033     return iLHS->id() < iRHS->id();
0034   }
0035 }  // namespace
0036 //
0037 // constants, enums and typedefs
0038 //
0039
0040 //
0041 // static data member definitions
0042 //
0043
0044 //
0045 // constructors and destructor
0046 //
0047 SystemTimeKeeper::SystemTimeKeeper(unsigned int iNumStreams,
0048                                    std::vector<const ModuleDescription*> const& iModules,
0049                                    service::TriggerNamesService const& iNamesService,
0050                                    ProcessContext const* iProcessContext)
0051     : m_streamEventTimer(iNumStreams),
0052       m_streamPathTiming(iNumStreams),
0053       m_modules(iModules),
0054       m_processContext(iProcessContext),
0055       m_minModuleID(0),
0056       m_numberOfEvents(0) {
0057   std::sort(m_modules.begin(), m_modules.end(), lessModuleDescription);
0058   if (not m_modules.empty()) {
0059     m_minModuleID = m_modules.front()->id();
0060     unsigned int numModuleSlots = m_modules.back()->id() - m_minModuleID + 1;
0061     m_streamModuleTiming.resize(iNumStreams);
0062     for (auto& stream : m_streamModuleTiming) {
0063       stream.resize(numModuleSlots);
0064     }
0065   }
0066
0067   std::vector<unsigned int> numModulesInPath;
0068   std::vector<unsigned int> numModulesInEndPath;
0069
0070   const unsigned int numPaths = iNamesService.getTrigPaths().size();
0071   const unsigned int numEndPaths = iNamesService.getEndPaths().size();
0072   m_pathNames.reserve(numPaths + numEndPaths);
0073   std::copy(iNamesService.getTrigPaths().begin(), iNamesService.getTrigPaths().end(), std::back_inserter(m_pathNames));
0074   std::copy(iNamesService.getEndPaths().begin(), iNamesService.getEndPaths().end(), std::back_inserter(m_pathNames));
0075
0076   numModulesInPath.reserve(numPaths);
0077   numModulesInEndPath.reserve(numEndPaths);
0078
0079   m_modulesOnPaths.reserve(numPaths + numEndPaths);
0080
0081   for (unsigned int i = 0; i < numPaths; ++i) {
0082     numModulesInPath.push_back(iNamesService.getTrigPathModules(i).size());
0083     m_modulesOnPaths.push_back(iNamesService.getTrigPathModules(i));
0084   }
0085   for (unsigned int i = 0; i < numEndPaths; ++i) {
0086     numModulesInEndPath.push_back(iNamesService.getEndPathModules(i).size());
0087     m_modulesOnPaths.push_back(iNamesService.getEndPathModules(i));
0088   }
0089
0090   m_endPathOffset = numModulesInPath.size();
0091
0092   for (auto& stream : m_streamPathTiming) {
0093     unsigned int index = 0;
0094     stream.resize(numModulesInPath.size() + numModulesInEndPath.size());
0095     for (unsigned int numMods : numModulesInPath) {
0096       stream[index].m_moduleTiming.resize(numMods);
0097       ++index;
0098     }
0099     for (unsigned int numMods : numModulesInEndPath) {
0100       stream[index].m_moduleTiming.resize(numMods);
0101       ++index;
0102     }
0103   }
0104 }
0105
0106 //
0107 // member functions
0108 //
0109 void SystemTimeKeeper::removeModuleIfExists(ModuleDescription const& module) {
0110   // The deletion of a module is signaled to all (Sub)Processes, even
0111   // though the module exists in only one of them.
0112   auto found = std::lower_bound(m_modules.begin(), m_modules.end(), &module, lessModuleDescription);
0113   if (*found == &module) {
0114     m_modules.erase(found);
0115   }
0116 }
0117
0118 SystemTimeKeeper::PathTiming& SystemTimeKeeper::pathTiming(StreamContext const& iStream, PathContext const& iPath) {
0119   unsigned int offset = 0;
0120   if (iPath.isEndPath()) {
0121     offset = m_endPathOffset;
0122   }
0123   assert(iPath.pathID() + offset < m_streamPathTiming[iStream.streamID().value()].size());
0124   return m_streamPathTiming[iStream.streamID().value()][iPath.pathID() + offset];
0125 }
0126
0127 //NOTE: Have to check bounds rather than ProcessContext on the
0128 // module callbacks because the ProcessContext could be for a
0129 // SubProcess which requested an usncheduled execution of a
0130 // module in a parent process. In that case the ProcessContext
0131 // is for the SubProcess but the module is is for the parent process.
0132 inline bool SystemTimeKeeper::checkBounds(unsigned int id) const {
0133   return id >= m_minModuleID and id < m_streamModuleTiming.front().size() + m_minModuleID;
0134 }
0135
0136 void SystemTimeKeeper::startEvent(StreamID iID) {
0137   m_numberOfEvents++;
0138   m_streamEventTimer[iID.value()].start();
0139 }
0140
0141 void SystemTimeKeeper::stopEvent(StreamContext const& iContext) {
0142   m_streamEventTimer[iContext.streamID().value()].stop();
0143 }
0144
0145 void SystemTimeKeeper::startPath(StreamContext const& iStream, PathContext const& iPath) {
0146   if (m_processContext == iStream.processContext()) {
0147     auto& timing = pathTiming(iStream, iPath);
0148     timing.m_timer.start();
0149   }
0150 }
0151
0152 void SystemTimeKeeper::stopPath(StreamContext const& iStream, PathContext const& iPath, HLTPathStatus const& iStatus) {
0153   if (m_processContext == iStream.processContext()) {
0154     auto& timing = pathTiming(iStream, iPath);
0155     timing.m_timer.stop();
0156
0157     //mark all modules up to and including the decision module as being visited
0158     auto& modsOnPath = timing.m_moduleTiming;
0159     for (unsigned int i = 0; i < iStatus.index() + 1; ++i) {
0160       ++modsOnPath[i].m_timesVisited;
0161     }
0162   }
0163 }
0164
0165 void SystemTimeKeeper::startModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0166   if (checkBounds(iModule.moduleDescription()->id())) {
0167     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0168     mod.m_timer.start();
0169     ++(mod.m_timesRun);
0170   }
0171 }
0172 void SystemTimeKeeper::stopModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0173   if (checkBounds(iModule.moduleDescription()->id())) {
0174     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0175     auto times = mod.m_timer.stop();
0176
0177     if (iModule.type() == ParentContext::Type::kPlaceInPath) {
0178       auto place = iModule.placeInPathContext();
0179
0180       auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
0181       modTiming.m_realTime += times;
0182     }
0183   }
0184 }
0185 void SystemTimeKeeper::pauseModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0186   if (checkBounds(iModule.moduleDescription()->id())) {
0187     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0188     auto times = mod.m_timer.stop();
0189
0190     if (iModule.type() == ParentContext::Type::kPlaceInPath) {
0191       auto place = iModule.placeInPathContext();
0192
0193       auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
0194       modTiming.m_realTime += times;
0195     }
0196   }
0197 }
0198 void SystemTimeKeeper::restartModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0199   if (checkBounds(iModule.moduleDescription()->id())) {
0200     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0201     mod.m_timer.start();
0202   }
0203 }
0204
0205 void SystemTimeKeeper::startProcessingLoop() {
0206   m_processingLoopTimer.start();
0207   m_processingLoopChildrenTimer.start();
0208 }
0209
0210 void SystemTimeKeeper::stopProcessingLoop() {
0211   m_processingLoopTimer.stop();
0212   m_processingLoopChildrenTimer.stop();
0213 }
0214
0215 static void fillPathSummary(unsigned int iStartIndex,
0216                             unsigned int iEndIndex,
0217                             std::vector<std::string> const& iPathNames,
0218                             std::vector<std::vector<std::string>> const& iModulesOnPaths,
0219                             std::vector<std::vector<SystemTimeKeeper::PathTiming>> const& iPathTimings,
0220                             std::vector<PathTimingSummary>& iSummary) {
0221   iSummary.resize(iEndIndex - iStartIndex);
0222
0223   for (auto const& stream : iPathTimings) {
0224     auto it = iSummary.begin();
0225     for (unsigned int index = iStartIndex; index < iEndIndex; ++index, ++it) {
0226       auto const& pathTiming = stream[index];
0227       it->name = iPathNames[index];
0228       it->bitPosition = index - iStartIndex;
0229       if (not pathTiming.m_moduleTiming.empty()) {
0230         it->timesRun += pathTiming.m_moduleTiming[0].m_timesVisited;
0231       }
0232       it->realTime += pathTiming.m_timer.realTime();
0233       if (it->moduleInPathSummaries.empty()) {
0234         it->moduleInPathSummaries.resize(pathTiming.m_moduleTiming.size());
0235       }
0236       for (unsigned int modIndex = 0; modIndex < pathTiming.m_moduleTiming.size(); ++modIndex) {
0237         auto const& modTiming = pathTiming.m_moduleTiming[modIndex];
0238         auto& modSummary = it->moduleInPathSummaries[modIndex];
0239         if (modSummary.moduleLabel.empty()) {
0240           modSummary.moduleLabel = iModulesOnPaths[index][modIndex];
0241         }
0242         modSummary.timesVisited += modTiming.m_timesVisited;
0243         modSummary.realTime += modTiming.m_realTime;
0244       }
0245     }
0246   }
0247 }
0248
0249 void SystemTimeKeeper::fillTriggerTimingReport(TriggerTimingReport& rep) const {
0250   {
0251     rep.eventSummary.totalEvents = m_numberOfEvents;
0252     double sumEventTime = 0.;
0253     for (auto const& stream : m_streamEventTimer) {
0254       sumEventTime += stream.realTime();
0255     }
0256     rep.eventSummary.realTime = m_processingLoopTimer.realTime();
0257     rep.eventSummary.cpuTime = m_processingLoopTimer.cpuTime() + m_processingLoopChildrenTimer.cpuTime();
0258     rep.eventSummary.sumStreamRealTime = sumEventTime;
0259   }
0260
0261   //Per module summary
0262   {
0263     auto& summary = rep.workerSummaries;
0264     summary.resize(m_modules.size());
0265     //Figure out how often a module was visited
0266     std::map<std::string, unsigned int> visited;
0267     for (auto const& stream : m_streamPathTiming) {
0268       unsigned int pathIndex = 0;
0269       for (auto const& path : stream) {
0270         unsigned int modIndex = 0;
0271         for (auto const& mod : path.m_moduleTiming) {
0272           visited[m_modulesOnPaths[pathIndex][modIndex]] += mod.m_timesVisited;
0273           ++modIndex;
0274         }
0275         ++pathIndex;
0276       }
0277     }
0278
0279     unsigned int modIndex = 0;
0280     for (auto const& mod : m_modules) {
0281       auto& outMod = summary[modIndex];
0282       outMod.moduleLabel = mod->moduleLabel();
0283       outMod.realTime = 0.;
0284
0285       auto moduleId = mod->id() - m_minModuleID;
0286       for (auto const& stream : m_streamModuleTiming) {
0287         auto const& timing = stream[moduleId];
0288         outMod.realTime += timing.m_timer.realTime();
0289         outMod.timesRun += timing.m_timesRun;
0290       }
0291       outMod.timesVisited = visited[mod->moduleLabel()];
0292       if (0 == outMod.timesVisited) {
0293         outMod.timesVisited = outMod.timesRun;
0294       }
0295       ++modIndex;
0296     }
0297   }
0298   sort_all(rep.workerSummaries);
0299
0300   //Per path summary
0301   {
0302     fillPathSummary(0, m_endPathOffset, m_pathNames, m_modulesOnPaths, m_streamPathTiming, rep.trigPathSummaries);
0303     fillPathSummary(m_endPathOffset,
0304                     m_streamPathTiming[0].size(),
0305                     m_pathNames,
0306                     m_modulesOnPaths,
0307                     m_streamPathTiming,
0308                     rep.endPathSummaries);
0309   }
0310 }
0311
0312 //
0313 // const member functions
0314 //
0315
0316 //
0317 // static member functions
0318 //