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.
0129 inline bool SystemTimeKeeper::checkBounds(unsigned int id) const {
0130   return id >= m_minModuleID and id < m_streamModuleTiming.front().size() + m_minModuleID;
0131 }
0132
0133 void SystemTimeKeeper::startEvent(StreamID iID) {
0134   m_numberOfEvents++;
0135   m_streamEventTimer[iID.value()].start();
0136 }
0137
0138 void SystemTimeKeeper::stopEvent(StreamContext const& iContext) {
0139   m_streamEventTimer[iContext.streamID().value()].stop();
0140 }
0141
0142 void SystemTimeKeeper::startPath(StreamContext const& iStream, PathContext const& iPath) {
0143   if (m_processContext == iStream.processContext()) {
0144     auto& timing = pathTiming(iStream, iPath);
0145     timing.m_timer.start();
0146   }
0147 }
0148
0149 void SystemTimeKeeper::stopPath(StreamContext const& iStream, PathContext const& iPath, HLTPathStatus const& iStatus) {
0150   if (m_processContext == iStream.processContext()) {
0151     auto& timing = pathTiming(iStream, iPath);
0152     timing.m_timer.stop();
0153
0154     //mark all modules up to and including the decision module as being visited
0155     auto& modsOnPath = timing.m_moduleTiming;
0156     for (unsigned int i = 0; i < iStatus.index() + 1; ++i) {
0157       ++modsOnPath[i].m_timesVisited;
0158     }
0159   }
0160 }
0161
0162 void SystemTimeKeeper::startModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0163   if (checkBounds(iModule.moduleDescription()->id())) {
0164     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0165     mod.m_timer.start();
0166     ++(mod.m_timesRun);
0167   }
0168 }
0169 void SystemTimeKeeper::stopModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0170   if (checkBounds(iModule.moduleDescription()->id())) {
0171     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0172     auto times = mod.m_timer.stop();
0173
0174     if (iModule.type() == ParentContext::Type::kPlaceInPath) {
0175       auto place = iModule.placeInPathContext();
0176
0177       auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
0178       modTiming.m_realTime += times;
0179     }
0180   }
0181 }
0182 void SystemTimeKeeper::pauseModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0183   if (checkBounds(iModule.moduleDescription()->id())) {
0184     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0185     auto times = mod.m_timer.stop();
0186
0187     if (iModule.type() == ParentContext::Type::kPlaceInPath) {
0188       auto place = iModule.placeInPathContext();
0189
0190       auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
0191       modTiming.m_realTime += times;
0192     }
0193   }
0194 }
0195 void SystemTimeKeeper::restartModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0196   if (checkBounds(iModule.moduleDescription()->id())) {
0197     auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
0198     mod.m_timer.start();
0199   }
0200 }
0201
0202 void SystemTimeKeeper::startProcessingLoop() {
0203   m_processingLoopTimer.start();
0204   m_processingLoopChildrenTimer.start();
0205 }
0206
0207 void SystemTimeKeeper::stopProcessingLoop() {
0208   m_processingLoopTimer.stop();
0209   m_processingLoopChildrenTimer.stop();
0210 }
0211
0212 static void fillPathSummary(unsigned int iStartIndex,
0213                             unsigned int iEndIndex,
0214                             std::vector<std::string> const& iPathNames,
0215                             std::vector<std::vector<std::string>> const& iModulesOnPaths,
0216                             std::vector<std::vector<SystemTimeKeeper::PathTiming>> const& iPathTimings,
0217                             std::vector<PathTimingSummary>& iSummary) {
0218   iSummary.resize(iEndIndex - iStartIndex);
0219
0220   for (auto const& stream : iPathTimings) {
0221     auto it = iSummary.begin();
0222     for (unsigned int index = iStartIndex; index < iEndIndex; ++index, ++it) {
0223       auto const& pathTiming = stream[index];
0224       it->name = iPathNames[index];
0225       it->bitPosition = index - iStartIndex;
0226       if (not pathTiming.m_moduleTiming.empty()) {
0227         it->timesRun += pathTiming.m_moduleTiming[0].m_timesVisited;
0228       }
0229       it->realTime += pathTiming.m_timer.realTime();
0230       if (it->moduleInPathSummaries.empty()) {
0231         it->moduleInPathSummaries.resize(pathTiming.m_moduleTiming.size());
0232       }
0233       for (unsigned int modIndex = 0; modIndex < pathTiming.m_moduleTiming.size(); ++modIndex) {
0234         auto const& modTiming = pathTiming.m_moduleTiming[modIndex];
0235         auto& modSummary = it->moduleInPathSummaries[modIndex];
0236         if (modSummary.moduleLabel.empty()) {
0237           modSummary.moduleLabel = iModulesOnPaths[index][modIndex];
0238         }
0239         modSummary.timesVisited += modTiming.m_timesVisited;
0240         modSummary.realTime += modTiming.m_realTime;
0241       }
0242     }
0243   }
0244 }
0245
0246 void SystemTimeKeeper::fillTriggerTimingReport(TriggerTimingReport& rep) const {
0247   {
0248     rep.eventSummary.totalEvents = m_numberOfEvents;
0249     double sumEventTime = 0.;
0250     for (auto const& stream : m_streamEventTimer) {
0251       sumEventTime += stream.realTime();
0252     }
0253     rep.eventSummary.realTime = m_processingLoopTimer.realTime();
0254     rep.eventSummary.cpuTime = m_processingLoopTimer.cpuTime() + m_processingLoopChildrenTimer.cpuTime();
0255     rep.eventSummary.sumStreamRealTime = sumEventTime;
0256   }
0257
0258   //Per module summary
0259   {
0260     auto& summary = rep.workerSummaries;
0261     summary.resize(m_modules.size());
0262     //Figure out how often a module was visited
0263     std::map<std::string, unsigned int> visited;
0264     for (auto const& stream : m_streamPathTiming) {
0265       unsigned int pathIndex = 0;
0266       for (auto const& path : stream) {
0267         unsigned int modIndex = 0;
0268         for (auto const& mod : path.m_moduleTiming) {
0269           visited[m_modulesOnPaths[pathIndex][modIndex]] += mod.m_timesVisited;
0270           ++modIndex;
0271         }
0272         ++pathIndex;
0273       }
0274     }
0275
0276     unsigned int modIndex = 0;
0277     for (auto const& mod : m_modules) {
0278       auto& outMod = summary[modIndex];
0279       outMod.moduleLabel = mod->moduleLabel();
0280       outMod.realTime = 0.;
0281
0282       auto moduleId = mod->id() - m_minModuleID;
0283       for (auto const& stream : m_streamModuleTiming) {
0284         auto const& timing = stream[moduleId];
0285         outMod.realTime += timing.m_timer.realTime();
0286         outMod.timesRun += timing.m_timesRun;
0287       }
0288       outMod.timesVisited = visited[mod->moduleLabel()];
0289       if (0 == outMod.timesVisited) {
0290         outMod.timesVisited = outMod.timesRun;
0291       }
0292       ++modIndex;
0293     }
0294   }
0295   sort_all(rep.workerSummaries);
0296
0297   //Per path summary
0298   {
0299     fillPathSummary(0, m_endPathOffset, m_pathNames, m_modulesOnPaths, m_streamPathTiming, rep.trigPathSummaries);
0300     fillPathSummary(m_endPathOffset,
0301                     m_streamPathTiming[0].size(),
0302                     m_pathNames,
0303                     m_modulesOnPaths,
0304                     m_streamPathTiming,
0305                     rep.endPathSummaries);
0306   }
0307 }
0308
0309 //
0310 // const member functions
0311 //
0312
0313 //
0314 // static member functions
0315 //