diff --git a/FWCore/Services/plugins/tracer_setupFile.cc b/FWCore/Services/plugins/tracer_setupFile.cc index 96e464984c960..7fe9b1915eec6 100644 --- a/FWCore/Services/plugins/tracer_setupFile.cc +++ b/FWCore/Services/plugins/tracer_setupFile.cc @@ -85,7 +85,14 @@ namespace { esSyncEnqueue = 14, getNextTransition = 15, construction = 16, - startTracing = 17 + finalizeEDModules = 17, + finalizeEventSetupConfiguration = 18, + scheduleConsistencyCheck = 19, + createRunLumiEvents = 20, + finishSchedule = 21, + constructESModules = 22, + startServices = 23, + processPython = 24 }; std::ostream& operator<<(std::ostream& os, Step const s) { @@ -305,11 +312,28 @@ namespace { long long beginDestruction = 0; long long endDestruction = 0; }; + + struct StartupTimes { + using time_diff = + decltype(std::chrono::duration_cast(steady_clock::now() - steady_clock::now()).count()); + time_diff endServiceConstruction = 0; + time_diff beginFinalizeEDModules = 0; + time_diff endFinalizeEDModules = 0; + time_diff beginFinalizeEventSetupConfiguration = 0; + time_diff endFinalizeEventSetupConfiguration = 0; + time_diff beginScheduleConsistencyCheck = 0; + time_diff endScheduleConsistencyCheck = 0; + time_diff beginCreateRunLumiEvents = 0; + time_diff endCreateRunLumiEvents = 0; + time_diff beginFinishSchedule = 0; + time_diff endFinishSchedule = 0; + time_diff beginConstructESModules = 0; + time_diff endConstructESModules = 0; + }; } // namespace namespace edm::service::tracer { void setupFile(std::string const& iFileName, edm::ActivityRegistry& iRegistry) { - auto beginTracer = steady_clock::now(); using namespace std::chrono; if (iFileName.empty()) { @@ -318,7 +342,7 @@ namespace edm::service::tracer { auto logFile = std::make_shared(iFileName); - auto beginTime = TimingServiceBase::jobStartTime(); + const auto beginTime = TimingServiceBase::jobStartTime(); auto esModuleLabelsPtr = std::make_shared>(); auto& esModuleLabels = *esModuleLabelsPtr; @@ -399,13 +423,64 @@ namespace edm::service::tracer { logFile->write(oss.str()); }); + auto const pythonBegin = duration_cast(TimingServiceBase::pythonStartTime() - beginTime).count(); + auto const pythonEnd = duration_cast(TimingServiceBase::pythonEndTime() - beginTime).count(); + auto const servicesBegin = duration_cast(TimingServiceBase::servicesStartTime() - beginTime).count(); + + auto startupTimes = std::make_shared(); + auto ptrStartupTimes = startupTimes.get(); + iRegistry.watchPostServicesConstruction([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endServiceConstruction = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPreEventSetupModulesConstruction([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginConstructESModules = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostEventSetupModulesConstruction([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endConstructESModules = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPreModulesInitializationFinalized([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginFinalizeEDModules = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostModulesInitializationFinalized([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endFinalizeEDModules = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPreEventSetupConfigurationFinalized([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginFinalizeEventSetupConfiguration = + duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostEventSetupConfigurationFinalized([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endFinalizeEventSetupConfiguration = + duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPreScheduleConsistencyCheck([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginScheduleConsistencyCheck = + duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostScheduleConsistencyCheck([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endScheduleConsistencyCheck = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPrePrincipalsCreation([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginCreateRunLumiEvents = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostPrincipalsCreation([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endCreateRunLumiEvents = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPreFinishSchedule([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->beginFinishSchedule = duration_cast(steady_clock::now() - beginTime).count(); + }); + iRegistry.watchPostFinishSchedule([ptrStartupTimes, beginTime]() mutable { + ptrStartupTimes->endFinishSchedule = duration_cast(steady_clock::now() - beginTime).count(); + }); iRegistry.watchPreBeginJob([logFile, moduleLabelsPtr, esModuleLabelsPtr, moduleCtrDtrPtr, sourceCtrPtr, beginTime, - beginTracer](auto&) mutable { + pythonBegin, + pythonEnd, + servicesBegin, + startupTimes](auto&) mutable { { std::ostringstream oss; moduleIdToLabel(oss, *moduleLabelsPtr, 'M', "EDModule ID", "Module label"); @@ -419,11 +494,52 @@ namespace edm::service::tracer { esModuleLabelsPtr.reset(); } { - auto const tracerStart = duration_cast(beginTracer - beginTime).count(); auto msg = assembleMessage( - static_cast>(Phase::startTracing), 0, 0, 0, 0, tracerStart); + static_cast>(Phase::processPython), 0, 0, 0, 0, pythonBegin); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::processPython), 0, 0, 0, 0, pythonEnd); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::startServices), 0, 0, 0, 0, servicesBegin); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::startServices), + 0, + 0, + 0, + 0, + startupTimes->endServiceConstruction); + logFile->write(std::move(msg)); + } + + { + auto msg = assembleMessage( + static_cast>(Phase::constructESModules), + 0, + 0, + 0, + 0, + startupTimes->beginConstructESModules); logFile->write(std::move(msg)); } + { + auto msg = assembleMessage( + static_cast>(Phase::constructESModules), + 0, + 0, + 0, + 0, + startupTimes->endConstructESModules); + logFile->write(std::move(msg)); + } + //NOTE: the source construction can run concurently with module construction so we need to properly // interleave its timing in with the modules auto srcBeginConstruction = sourceCtrPtr->beginConstruction; @@ -482,6 +598,108 @@ namespace edm::service::tracer { } auto const t = duration_cast(steady_clock::now() - beginTime).count(); handleSource(t); + + { + auto msg = assembleMessage( + static_cast>(Phase::finishSchedule), + 0, + 0, + 0, + 0, + startupTimes->beginFinishSchedule); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::finishSchedule), + 0, + 0, + 0, + 0, + startupTimes->endFinishSchedule); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::createRunLumiEvents), + 0, + 0, + 0, + 0, + startupTimes->beginCreateRunLumiEvents); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::createRunLumiEvents), + 0, + 0, + 0, + 0, + startupTimes->endCreateRunLumiEvents); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::scheduleConsistencyCheck), + 0, + 0, + 0, + 0, + startupTimes->beginScheduleConsistencyCheck); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::scheduleConsistencyCheck), + 0, + 0, + 0, + 0, + startupTimes->endScheduleConsistencyCheck); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::finalizeEventSetupConfiguration), + 0, + 0, + 0, + 0, + startupTimes->beginFinalizeEventSetupConfiguration); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::finalizeEventSetupConfiguration), + 0, + 0, + 0, + 0, + startupTimes->endFinalizeEventSetupConfiguration); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::finalizeEDModules), + 0, + 0, + 0, + 0, + startupTimes->beginFinalizeEDModules); + logFile->write(std::move(msg)); + } + { + auto msg = assembleMessage( + static_cast>(Phase::finalizeEDModules), + 0, + 0, + 0, + 0, + startupTimes->endFinalizeEDModules); + logFile->write(std::move(msg)); + } + auto msg = assembleMessage( static_cast>(Phase::beginJob), 0, 0, 0, 0, t); logFile->write(std::move(msg)); @@ -830,35 +1048,42 @@ namespace edm::service::tracer { } std::ostringstream oss; - oss << "# Transition Symbol\n"; - oss << "#------------------------ ------\n"; - oss << "# startTracing " << Phase::startTracing << "\n" - << "# construction " << Phase::construction << "\n" - << "# getNextTransition " << Phase::getNextTransition << "\n" - << "# esSyncEnqueue " << Phase::esSyncEnqueue << "\n" - << "# esSync " << Phase::esSync << "\n" - << "# beginJob " << Phase::beginJob << "\n" - << "# beginStream " << Phase::beginStream << "\n" - << "# openFile " << Phase::openFile << "\n" - << "# beginProcessBlock " << Phase::beginProcessBlock << "\n" - << "# accessInputProcessBlock " << Phase::accessInputProcessBlock << "\n" - << "# globalBeginRun " << Phase::globalBeginRun << "\n" - << "# streamBeginRun " << Phase::streamBeginRun << "\n" - << "# globalBeginLumi " << Phase::globalBeginLumi << "\n" - << "# streamBeginLumi " << Phase::streamBeginLumi << "\n" - << "# Event " << Phase::Event << "\n" - << "# clearEvent " << Phase::clearEvent << "\n" - << "# streamEndLumi " << Phase::streamEndLumi << "\n" - << "# globalEndLumi " << Phase::globalEndLumi << "\n" - << "# globalWriteLumi " << Phase::globalWriteLumi << "\n" - << "# streamEndRun " << Phase::streamEndRun << "\n" - << "# globalEndRun " << Phase::globalEndRun << "\n" - << "# globalWriteRun " << Phase::globalWriteRun << "\n" - << "# endProcessBlock " << Phase::endProcessBlock << "\n" - << "# writeProcessBlock " << Phase::writeProcessBlock << "\n" - << "# endStream " << Phase::endStream << "\n" - << "# endJob " << Phase::endJob << "\n" - << "# destruction " << Phase::destruction << "\n\n"; + oss << "# Transition Symbol\n"; + oss << "#------------------------ ------\n"; + oss << "# processPython " << Phase::processPython << "\n" + << "# startServices " << Phase::startServices << "\n" + << "# constructionESModules " << Phase::constructESModules << "\n" + << "# finishSchedule " << Phase::finishSchedule << "\n" + << "# createRunLumiEvents " << Phase::createRunLumiEvents << "\n" + << "# scheduleConsistencyCheck " << Phase::scheduleConsistencyCheck << "\n" + << "# finish ES Configuration " << Phase::finalizeEventSetupConfiguration << "\n" + << "# finalize EDModules " << Phase::finalizeEDModules << "\n" + << "# construction " << Phase::construction << "\n" + << "# getNextTransition " << Phase::getNextTransition << "\n" + << "# esSyncEnqueue " << Phase::esSyncEnqueue << "\n" + << "# esSync " << Phase::esSync << "\n" + << "# beginJob " << Phase::beginJob << "\n" + << "# beginStream " << Phase::beginStream << "\n" + << "# openFile " << Phase::openFile << "\n" + << "# beginProcessBlock " << Phase::beginProcessBlock << "\n" + << "# accessInputProcessBlock " << Phase::accessInputProcessBlock << "\n" + << "# globalBeginRun " << Phase::globalBeginRun << "\n" + << "# streamBeginRun " << Phase::streamBeginRun << "\n" + << "# globalBeginLumi " << Phase::globalBeginLumi << "\n" + << "# streamBeginLumi " << Phase::streamBeginLumi << "\n" + << "# Event " << Phase::Event << "\n" + << "# clearEvent " << Phase::clearEvent << "\n" + << "# streamEndLumi " << Phase::streamEndLumi << "\n" + << "# globalEndLumi " << Phase::globalEndLumi << "\n" + << "# globalWriteLumi " << Phase::globalWriteLumi << "\n" + << "# streamEndRun " << Phase::streamEndRun << "\n" + << "# globalEndRun " << Phase::globalEndRun << "\n" + << "# globalWriteRun " << Phase::globalWriteRun << "\n" + << "# endProcessBlock " << Phase::endProcessBlock << "\n" + << "# writeProcessBlock " << Phase::writeProcessBlock << "\n" + << "# endStream " << Phase::endStream << "\n" + << "# endJob " << Phase::endJob << "\n" + << "# destruction " << Phase::destruction << "\n\n"; oss << "# Step Symbol Entries\n" << "# -------------------------- ------ ------------------------------------------\n" << "# preSourceTransition " << Step::preSourceTransition diff --git a/FWCore/Services/scripts/edmTracerCompactLogViewer.py b/FWCore/Services/scripts/edmTracerCompactLogViewer.py index 19ba998186734..05a348287651b 100755 --- a/FWCore/Services/scripts/edmTracerCompactLogViewer.py +++ b/FWCore/Services/scripts/edmTracerCompactLogViewer.py @@ -79,7 +79,14 @@ class Phase (object): esSyncEnqueue = 14 getNextTransition = 15 construction = 16 - startTracing = 17 + finalizeEDModules = 17 + finalizeEventSetupConfiguration = 18 + scheduleConsistencyCheck = 19 + createRunLumiEvents = 20 + finishSchedule = 21 + constructESModules = 22 + startServices = 23 + processPython = 24 #used for json output class Activity (object): @@ -90,8 +97,16 @@ class Activity (object): externalWork = 4 temporary = 100 + transitionToNames_ = { - Phase.startTracing: 'start tracing', + Phase.processPython: 'process python', + Phase.startServices: 'start Services', + Phase.constructESModules: 'construct ESModules', + Phase.finishSchedule: 'finish schedule', + Phase.createRunLumiEvents: 'create run/lumi/events', + Phase.scheduleConsistencyCheck: 'schedule consistency check', + Phase.finalizeEventSetupConfiguration : 'finalize EventSetup configuration', + Phase.finalizeEDModules: 'finalize EDModules', Phase.construction: 'construction', Phase.destruction: 'destruction', Phase.beginJob: 'begin job', @@ -123,7 +138,14 @@ def transitionName(transition): return transitionToNames_[transition] transitionToIndent_ = { - Phase.startTracing: 0, + Phase.processPython: 0, + Phase.startServices: 0, + Phase.constructESModules: 0, + Phase.finishSchedule: 0, + Phase.createRunLumiEvents: 0, + Phase.scheduleConsistencyCheck: 0, + Phase.finalizeEventSetupConfiguration : 0, + Phase.finalizeEDModules: 0, Phase.construction: 0, Phase.destruction: 0, Phase.endJob: 0, @@ -154,7 +176,14 @@ def transitionIndentLevel(transition): return transitionToIndent_[transition] globalTransitions_ = { - Phase.startTracing, + Phase.processPython, + Phase.startServices, + Phase.constructESModules, + Phase.finishSchedule, + Phase.createRunLumiEvents, + Phase.scheduleConsistencyCheck, + Phase.finalizeEventSetupConfiguration, + Phase.finalizeEDModules, Phase.construction, Phase.destruction, Phase.endJob, @@ -211,7 +240,7 @@ def syncText(self): return '' if self.transition == Phase.beginProcessBlock or self.transition == Phase.endProcessBlock or self.transition == Phase.writeProcessBlock or self.transition == Phase.accessInputProcessBlock: return '' - if self.transition == Phase.startTracing: + if self.transition in [Phase.finalizeEDModules, Phase.finalizeEventSetupConfiguration, Phase.scheduleConsistencyCheck, Phase.createRunLumiEvents, Phase.finishSchedule, Phase.constructESModules, Phase.startServices, Phase.processPython]: return '' if self.transition == Phase.construction or self.transition == Phase.destruction: return '' @@ -259,10 +288,7 @@ def textSpecial(self): def jsonInfo(self, counter, data): if transitionIsGlobal(self.transition): index = 0 - if self.transition == Phase.startTracing: - data.indexedGlobal(0).append(jsonTransition(type=self.transition, id=index, sync=list(self.sync),start=0, finish=self.time )) - return - elif self.transition == Phase.esSync: + if self.transition == Phase.esSync: if self.sync[1] == kLargestLumiNumber: #at end run transition index = findMatchingTransition(list(self.sync), data.allGlobals()) diff --git a/FWCore/Services/test/BuildFile.xml b/FWCore/Services/test/BuildFile.xml index 9d6e74b003c61..3cef16c6108bc 100644 --- a/FWCore/Services/test/BuildFile.xml +++ b/FWCore/Services/test/BuildFile.xml @@ -40,6 +40,8 @@ + + diff --git a/FWCore/Services/test/test_tracer_file.sh b/FWCore/Services/test/test_tracer_file.sh new file mode 100755 index 0000000000000..1fa89720d676b --- /dev/null +++ b/FWCore/Services/test/test_tracer_file.sh @@ -0,0 +1,41 @@ +#!/bin/bash + +function die { echo Failure $1: status $2 ; exit $2 ; } + +cmsRun -e ${SCRAM_TEST_PATH}/tracer_cfg.py &> test_Timing.log || die "cmsRun tracer_cfg.py" $? +edmTracerCompactLogViewer.py -j tracer.log &> tracer.json || die "edmTracerCompactLogViewer.py" $? +grep -q '"type": 24' tracer.json || die "Check for processPython transition in JSON" $? +grep -q '"type": 23' tracer.json || die "Check for startServices transition in JSON" $? +grep -q '"type": 22' tracer.json || die "Check for constructESModules transition in JSON" $? +grep -q '"type": 21' tracer.json || die "Check for finishSchedule transition in JSON" $? +grep -q '"type": 20' tracer.json || die "Check for createRunLumiEvents transition in JSON" $? +grep -q '"type": 19' tracer.json || die "Check for scheduleConsistencyCheck transition in JSON" $? +grep -q '"type": 18' tracer.json || die "Check for finalizeEventSetupConfiguration transition in JSON" $? +grep -q '"type": 17' tracer.json || die "Check for finalizeEDModules transition in JSON" $? +grep -q '"type": 16' tracer.json || die "Check for construction transition in JSON" $? +#grep -q '"type": -16' tracer.json || die "Check for destruction transition in JSON" $? #there are no destruction calls in the file +grep -q '"type": 12' tracer.json || die "Check for beginJob transition in JSON" $? +grep -q '"type": -12' tracer.json || die "Check for endJob transition in JSON" $? +grep -q '"type": 11' tracer.json || die "Check for beginStream transition in JSON" $? +grep -q '"type": -11' tracer.json || die "Check for endStream transition in JSON" $? +#grep -q '"type": 10' tracer.json || die "Check for open file transition in JSON" $? #no file in EmptySource +grep -q '"type": -10' tracer.json || die "Check for write file transition in JSON" $? +grep -q '"type": 9' tracer.json || die "Check for beginProcessBlock transition in JSON" $? +grep -q '"type": -9' tracer.json || die "Check for endProcessBlock transition in JSON" $? +#grep -q '"type": 8' tracer.json || die "Check for inputProcessBlock transition in JSON" $? #no file transition for inputProcessBlock in this test +grep -q '"type": -8' tracer.json && die "Check for missing -8 transition in JSON" $? +grep -q '"type": 7' tracer.json && die "Check for missing 7 transition in JSON" $? +grep -q '"type": -7' tracer.json || die "Check for globalWriteRun transition in JSON" $? +grep -q '"type": 6' tracer.json || die "Check for globalBeginRun transition in JSON" $? +grep -q '"type": -6' tracer.json || die "Check for globalEndRun transition in JSON" $? +grep -q '"type": 5' tracer.json || die "Check for streamBeginRun transition in JSON" $? +grep -q '"type": -5' tracer.json || die "Check for streamEndRun transition in JSON" $? +grep -q '"type": 4' tracer.json && die "Check for missing 4 transition in JSON" $? +grep -q '"type": -4' tracer.json || die "Check for globalWriteLumi transition in JSON" $? +grep -q '"type": 3' tracer.json || die "Check for globalBeginLumi transition in JSON" $? +grep -q '"type": -3' tracer.json || die "Check for globalEndLumi transition in JSON" $? +grep -q '"type": 2' tracer.json || die "Check for streamBeginLumi transition in JSON" $? +grep -q '"type": -2' tracer.json || die "Check for streamEndLumi transition in JSON" $? +grep -q '"type": 1' tracer.json && die "Check for missing 1 transition in JSON" $? +grep -q '"type": -1' tracer.json || die "Check for clearEvent transition in JSON" $? +grep -q '"type": 0' tracer.json || die "Check for event transition in JSON" $? \ No newline at end of file diff --git a/FWCore/Services/test/tracer_cfg.py b/FWCore/Services/test/tracer_cfg.py index 79debfe4d6532..87816f70132b5 100644 --- a/FWCore/Services/test/tracer_cfg.py +++ b/FWCore/Services/test/tracer_cfg.py @@ -6,7 +6,9 @@ process.load("FWCore.Framework.test.cmsExceptionsFatal_cff") -process.Tracer = cms.Service("Tracer") +process.Tracer = cms.Service("Tracer", + useMessageLogger=cms.untracked.bool(False), + fileName=cms.untracked.string("tracer.log")) process.maxEvents = cms.untracked.PSet( input = cms.untracked.int32(20) diff --git a/FWCore/Services/web/transitions.js b/FWCore/Services/web/transitions.js index 5c633c0ce3ed2..26a6ff15d09d7 100644 --- a/FWCore/Services/web/transitions.js +++ b/FWCore/Services/web/transitions.js @@ -37,7 +37,14 @@ const typeToColor = [ "#007777", //sync enqueue kSourceColor, // getNextTransition "#DD00DD", //construction - "#FF0000", //startup + "#FF0000", //finalizeEDModules + "#FF0000", //finalizeEventSetupConfiguration + "#FF0000", //scheduleConsistencyCheck + "#FF0000", //createRunLumiEvents + "#FF0000", //finishSchedule + "#DD00DD", //constructESModules + "#FF0000", //startServices + "#FF0000", //processPython ] const overlappingTransitions =[15] @@ -76,9 +83,17 @@ const typeToName = [ "EventSetup sych enqueue", //sync enqueue "find next transition", "construction", //construction - "startup", //startup + "finalize ED Modules", //finalizeEDModules + "finalize EventSetup configuration", //finalizeEventSetupConfiguration + "schedule consistency check", //scheduleConsistencyCheck + "create run/lumi/events", //createRunLumiEvents + "finish schedule", //finishSchedule + "construct ES Modules", //constructESModules + "start Services", //startServices + "process python", //processPython ] + const activityToName = [ "prefetch", "acquire", "process",