SystemTimeKeeper.cc

Go to the documentation of this file.

// -*- C++ -*-
//
// Package:     FWCore/Framework
// Class  :     SystemTimeKeeper
//
// Implementation:
//     [Notes on implementation]
//
// Original Author:  Chris Jones
//         Created:  Mon, 07 Jul 2014 14:37:32 GMT
//

// system include files
#include <algorithm>

// user include files
#include "FWCore/Utilities/interface/StreamID.h"
#include "FWCore/ServiceRegistry/interface/StreamContext.h"
#include "FWCore/ServiceRegistry/interface/PathContext.h"
#include "FWCore/ServiceRegistry/interface/PlaceInPathContext.h"
#include "FWCore/ServiceRegistry/interface/ModuleCallingContext.h"
#include "DataFormats/Provenance/interface/ModuleDescription.h"
#include "DataFormats/Common/interface/HLTPathStatus.h"
#include "FWCore/Framework/interface/TriggerTimingReport.h"
#include "FWCore/Framework/interface/TriggerNamesService.h"
#include "FWCore/Utilities/interface/Algorithms.h"
#include "SystemTimeKeeper.h"

using namespace edm;
//
// constants, enums and typedefs
//

//
// static data member definitions
//

//
// constructors and destructor
//
SystemTimeKeeper::SystemTimeKeeper(unsigned int iNumStreams,
                                   std::vector<const ModuleDescription*> const& iModules,
                                   service::TriggerNamesService const& iNamesService,
                                   ProcessContext const* iProcessContext)
    : m_streamEventTimer(iNumStreams),
      m_streamPathTiming(iNumStreams),
      m_modules(iModules),
      m_processContext(iProcessContext),
      m_minModuleID(0),
      m_numberOfEvents(0) {
  std::sort(
      m_modules.begin(), m_modules.end(), [](const ModuleDescription* iLHS, const ModuleDescription* iRHS) -> bool {
        return iLHS->id() < iRHS->id();
      });
  if (not m_modules.empty()) {
    m_minModuleID = m_modules.front()->id();
    unsigned int numModuleSlots = m_modules.back()->id() - m_minModuleID + 1;
    m_streamModuleTiming.resize(iNumStreams);
    for (auto& stream : m_streamModuleTiming) {
      stream.resize(numModuleSlots);
    }
  }

  std::vector<unsigned int> numModulesInPath;
  std::vector<unsigned int> numModulesInEndPath;

  const unsigned int numPaths = iNamesService.getTrigPaths().size();
  const unsigned int numEndPaths = iNamesService.getEndPaths().size();
  m_pathNames.reserve(numPaths + numEndPaths);
  std::copy(iNamesService.getTrigPaths().begin(), iNamesService.getTrigPaths().end(), std::back_inserter(m_pathNames));
  std::copy(iNamesService.getEndPaths().begin(), iNamesService.getEndPaths().end(), std::back_inserter(m_pathNames));

  numModulesInPath.reserve(numPaths);
  numModulesInEndPath.reserve(numEndPaths);

  m_modulesOnPaths.reserve(numPaths + numEndPaths);

  for (unsigned int i = 0; i < numPaths; ++i) {
    numModulesInPath.push_back(iNamesService.getTrigPathModules(i).size());
    m_modulesOnPaths.push_back(iNamesService.getTrigPathModules(i));
  }
  for (unsigned int i = 0; i < numEndPaths; ++i) {
    numModulesInEndPath.push_back(iNamesService.getEndPathModules(i).size());
    m_modulesOnPaths.push_back(iNamesService.getEndPathModules(i));
  }

  m_endPathOffset = numModulesInPath.size();

  for (auto& stream : m_streamPathTiming) {
    unsigned int index = 0;
    stream.resize(numModulesInPath.size() + numModulesInEndPath.size());
    for (unsigned int numMods : numModulesInPath) {
      stream[index].m_moduleTiming.resize(numMods);
      ++index;
    }
    for (unsigned int numMods : numModulesInEndPath) {
      stream[index].m_moduleTiming.resize(numMods);
      ++index;
    }
  }
}

//
// member functions
//
SystemTimeKeeper::PathTiming& SystemTimeKeeper::pathTiming(StreamContext const& iStream, PathContext const& iPath) {
  unsigned int offset = 0;
  if (iPath.isEndPath()) {
    offset = m_endPathOffset;
  }
  assert(iPath.pathID() + offset < m_streamPathTiming[iStream.streamID().value()].size());
  return m_streamPathTiming[iStream.streamID().value()][iPath.pathID() + offset];
}

//NOTE: Have to check bounds rather than ProcessContext on the
// module callbacks because the ProcessContext could be for a
// SubProcess which requested an usncheduled execution of a
// module in a parent process. In that case the ProcessContext
// is for the SubProcess but the module is is for the parent process.
inline bool SystemTimeKeeper::checkBounds(unsigned int id) const {
  return id >= m_minModuleID and id < m_streamModuleTiming.front().size() + m_minModuleID;
}

void SystemTimeKeeper::startEvent(StreamID iID) {
  m_numberOfEvents++;
  m_streamEventTimer[iID.value()].start();
}

void SystemTimeKeeper::stopEvent(StreamContext const& iContext) {
  m_streamEventTimer[iContext.streamID().value()].stop();
}

void SystemTimeKeeper::startPath(StreamContext const& iStream, PathContext const& iPath) {
  if (m_processContext == iStream.processContext()) {
    auto& timing = pathTiming(iStream, iPath);
    timing.m_timer.start();
  }
}

void SystemTimeKeeper::stopPath(StreamContext const& iStream, PathContext const& iPath, HLTPathStatus const& iStatus) {
  if (m_processContext == iStream.processContext()) {
    auto& timing = pathTiming(iStream, iPath);
    timing.m_timer.stop();

    //mark all modules up to and including the decision module as being visited
    auto& modsOnPath = timing.m_moduleTiming;
    for (unsigned int i = 0; i < iStatus.index() + 1; ++i) {
      ++modsOnPath[i].m_timesVisited;
    }
  }
}

void SystemTimeKeeper::startModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
  if (checkBounds(iModule.moduleDescription()->id())) {
    auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
    mod.m_timer.start();
    ++(mod.m_timesRun);
  }
}
void SystemTimeKeeper::stopModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
  if (checkBounds(iModule.moduleDescription()->id())) {
    auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
    auto times = mod.m_timer.stop();

    if (iModule.type() == ParentContext::Type::kPlaceInPath) {
      auto place = iModule.placeInPathContext();

      auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
      modTiming.m_realTime += times;
    }
  }
}
void SystemTimeKeeper::pauseModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
  if (checkBounds(iModule.moduleDescription()->id())) {
    auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
    auto times = mod.m_timer.stop();

    if (iModule.type() == ParentContext::Type::kPlaceInPath) {
      auto place = iModule.placeInPathContext();

      auto& modTiming = pathTiming(iStream, *(place->pathContext())).m_moduleTiming[place->placeInPath()];
      modTiming.m_realTime += times;
    }
  }
}
void SystemTimeKeeper::restartModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
  if (checkBounds(iModule.moduleDescription()->id())) {
    auto& mod = m_streamModuleTiming[iStream.streamID().value()][iModule.moduleDescription()->id() - m_minModuleID];
    mod.m_timer.start();
  }
}

void SystemTimeKeeper::startProcessingLoop() { m_processingLoopTimer.start(); }

void SystemTimeKeeper::stopProcessingLoop() { m_processingLoopTimer.stop(); }

static void fillPathSummary(unsigned int iStartIndex,
                            unsigned int iEndIndex,
                            std::vector<std::string> const& iPathNames,
                            std::vector<std::vector<std::string>> const& iModulesOnPaths,
                            std::vector<std::vector<SystemTimeKeeper::PathTiming>> const& iPathTimings,
                            std::vector<PathTimingSummary>& iSummary) {
  iSummary.resize(iEndIndex - iStartIndex);

  for (auto const& stream : iPathTimings) {
    auto it = iSummary.begin();
    for (unsigned int index = iStartIndex; index < iEndIndex; ++index, ++it) {
      auto const& pathTiming = stream[index];
      it->name = iPathNames[index];
      it->bitPosition = index - iStartIndex;
      if (not pathTiming.m_moduleTiming.empty()) {
        it->timesRun += pathTiming.m_moduleTiming[0].m_timesVisited;
      }
      it->realTime += pathTiming.m_timer.realTime();
      if (it->moduleInPathSummaries.empty()) {
        it->moduleInPathSummaries.resize(pathTiming.m_moduleTiming.size());
      }
      for (unsigned int modIndex = 0; modIndex < pathTiming.m_moduleTiming.size(); ++modIndex) {
        auto const& modTiming = pathTiming.m_moduleTiming[modIndex];
        auto& modSummary = it->moduleInPathSummaries[modIndex];
        if (modSummary.moduleLabel.empty()) {
          modSummary.moduleLabel = iModulesOnPaths[index][modIndex];
        }
        modSummary.timesVisited += modTiming.m_timesVisited;
        modSummary.realTime += modTiming.m_realTime;
      }
    }
  }
}

void SystemTimeKeeper::fillTriggerTimingReport(TriggerTimingReport& rep) const {
  {
    rep.eventSummary.totalEvents = m_numberOfEvents;
    double sumEventTime = 0.;
    for (auto const& stream : m_streamEventTimer) {
      sumEventTime += stream.realTime();
    }
    rep.eventSummary.realTime = m_processingLoopTimer.realTime();
    rep.eventSummary.cpuTime = m_processingLoopTimer.cpuTime();
    rep.eventSummary.sumStreamRealTime = sumEventTime;
  }

  //Per module summary
  {
    auto& summary = rep.workerSummaries;
    summary.resize(m_modules.size());
    //Figure out how often a module was visited
    std::map<std::string, unsigned int> visited;
    for (auto const& stream : m_streamPathTiming) {
      unsigned int pathIndex = 0;
      for (auto const& path : stream) {
        unsigned int modIndex = 0;
        for (auto const& mod : path.m_moduleTiming) {
          visited[m_modulesOnPaths[pathIndex][modIndex]] += mod.m_timesVisited;
          ++modIndex;
        }
        ++pathIndex;
      }
    }

    unsigned int modIndex = 0;
    for (auto const& mod : m_modules) {
      auto& outMod = summary[modIndex];
      outMod.moduleLabel = mod->moduleLabel();
      outMod.realTime = 0.;

      auto moduleId = mod->id() - m_minModuleID;
      for (auto const& stream : m_streamModuleTiming) {
        auto const& timing = stream[moduleId];
        outMod.realTime += timing.m_timer.realTime();
        outMod.timesRun += timing.m_timesRun;
      }
      outMod.timesVisited = visited[mod->moduleLabel()];
      if (0 == outMod.timesVisited) {
        outMod.timesVisited = outMod.timesRun;
      }
      ++modIndex;
    }
  }
  sort_all(rep.workerSummaries);

  //Per path summary
  {
    fillPathSummary(0, m_endPathOffset, m_pathNames, m_modulesOnPaths, m_streamPathTiming, rep.trigPathSummaries);
    fillPathSummary(m_endPathOffset,
                    m_streamPathTiming[0].size(),
                    m_pathNames,
                    m_modulesOnPaths,
                    m_streamPathTiming,
                    rep.endPathSummaries);
  }
}

//
// const member functions
//

//
// static member functions
//