Skip to content

Commit 857f9fc

Browse files
Dr15JonesDr15Jones
committed
Pass new signals to Tracer file
- handle new startup related signals in Tracer file - Update edmTracerCompactLogViewer to handle new file entries - Update web view of timing for new signals.
1 parent 4b8e6bc commit 857f9fc

File tree

6 files changed

+358
-47
lines changed

6 files changed

+358
-47
lines changed

‎FWCore/Services/plugins/tracer_setupFile.cc‎

Lines changed: 260 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -85,7 +85,14 @@ namespace {
8585
esSyncEnqueue = 14,
8686
getNextTransition = 15,
8787
construction = 16,
88-
startTracing = 17
88+
finalizeEDModules = 17,
89+
finalizeEventSetupConfiguration = 18,
90+
scheduleConsistencyCheck = 19,
91+
createRunLumiEvents = 20,
92+
finishSchedule = 21,
93+
constructESModules = 22,
94+
startServices = 23,
95+
processPython = 24
8996
};
9097

9198
std::ostream& operator<<(std::ostream& os, Step const s) {
@@ -305,11 +312,28 @@ namespace {
305312
long long beginDestruction = 0;
306313
long long endDestruction = 0;
307314
};
315+
316+
struct StartupTimes {
317+
using time_diff =
318+
decltype(std::chrono::duration_cast<duration_t>(steady_clock::now() - steady_clock::now()).count());
319+
time_diff endServiceConstruction = 0;
320+
time_diff beginFinalizeEDModules = 0;
321+
time_diff endFinalizeEDModules = 0;
322+
time_diff beginFinalizeEventSetupConfiguration = 0;
323+
time_diff endFinalizeEventSetupConfiguration = 0;
324+
time_diff beginScheduleConsistencyCheck = 0;
325+
time_diff endScheduleConsistencyCheck = 0;
326+
time_diff beginCreateRunLumiEvents = 0;
327+
time_diff endCreateRunLumiEvents = 0;
328+
time_diff beginFinishSchedule = 0;
329+
time_diff endFinishSchedule = 0;
330+
time_diff beginConstructESModules = 0;
331+
time_diff endConstructESModules = 0;
332+
};
308333
} // namespace
309334

310335
namespace edm::service::tracer {
311336
void setupFile(std::string const& iFileName, edm::ActivityRegistry& iRegistry) {
312-
auto beginTracer = steady_clock::now();
313337
using namespace std::chrono;
314338

315339
if (iFileName.empty()) {
@@ -318,7 +342,7 @@ namespace edm::service::tracer {
318342

319343
auto logFile = std::make_shared<edm::ThreadSafeOutputFileStream>(iFileName);
320344

321-
auto beginTime = TimingServiceBase::jobStartTime();
345+
const auto beginTime = TimingServiceBase::jobStartTime();
322346

323347
auto esModuleLabelsPtr = std::make_shared<std::vector<std::string>>();
324348
auto& esModuleLabels = *esModuleLabelsPtr;
@@ -399,13 +423,64 @@ namespace edm::service::tracer {
399423
logFile->write(oss.str());
400424
});
401425

426+
auto const pythonBegin = duration_cast<duration_t>(TimingServiceBase::pythonStartTime() - beginTime).count();
427+
auto const pythonEnd = duration_cast<duration_t>(TimingServiceBase::pythonEndTime() - beginTime).count();
428+
auto const servicesBegin = duration_cast<duration_t>(TimingServiceBase::servicesStartTime() - beginTime).count();
429+
430+
auto startupTimes = std::make_shared<StartupTimes>();
431+
auto ptrStartupTimes = startupTimes.get();
432+
iRegistry.watchPostServicesConstruction([ptrStartupTimes, beginTime]() mutable {
433+
ptrStartupTimes->endServiceConstruction = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
434+
});
435+
iRegistry.watchPreEventSetupModulesConstruction([ptrStartupTimes, beginTime]() mutable {
436+
ptrStartupTimes->beginConstructESModules = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
437+
});
438+
iRegistry.watchPostEventSetupModulesConstruction([ptrStartupTimes, beginTime]() mutable {
439+
ptrStartupTimes->endConstructESModules = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
440+
});
441+
iRegistry.watchPreModulesInitializationFinalized([ptrStartupTimes, beginTime]() mutable {
442+
ptrStartupTimes->beginFinalizeEDModules = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
443+
});
444+
iRegistry.watchPostModulesInitializationFinalized([ptrStartupTimes, beginTime]() mutable {
445+
ptrStartupTimes->endFinalizeEDModules = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
446+
});
447+
iRegistry.watchPreEventSetupConfigurationFinalized([ptrStartupTimes, beginTime]() mutable {
448+
ptrStartupTimes->beginFinalizeEventSetupConfiguration =
449+
duration_cast<duration_t>(steady_clock::now() - beginTime).count();
450+
});
451+
iRegistry.watchPostEventSetupConfigurationFinalized([ptrStartupTimes, beginTime]() mutable {
452+
ptrStartupTimes->endFinalizeEventSetupConfiguration =
453+
duration_cast<duration_t>(steady_clock::now() - beginTime).count();
454+
});
455+
iRegistry.watchPreScheduleConsistencyCheck([ptrStartupTimes, beginTime]() mutable {
456+
ptrStartupTimes->beginScheduleConsistencyCheck =
457+
duration_cast<duration_t>(steady_clock::now() - beginTime).count();
458+
});
459+
iRegistry.watchPostScheduleConsistencyCheck([ptrStartupTimes, beginTime]() mutable {
460+
ptrStartupTimes->endScheduleConsistencyCheck = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
461+
});
462+
iRegistry.watchPrePrincipalsCreation([ptrStartupTimes, beginTime]() mutable {
463+
ptrStartupTimes->beginCreateRunLumiEvents = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
464+
});
465+
iRegistry.watchPostPrincipalsCreation([ptrStartupTimes, beginTime]() mutable {
466+
ptrStartupTimes->endCreateRunLumiEvents = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
467+
});
468+
iRegistry.watchPreFinishSchedule([ptrStartupTimes, beginTime]() mutable {
469+
ptrStartupTimes->beginFinishSchedule = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
470+
});
471+
iRegistry.watchPostFinishSchedule([ptrStartupTimes, beginTime]() mutable {
472+
ptrStartupTimes->endFinishSchedule = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
473+
});
402474
iRegistry.watchPreBeginJob([logFile,
403475
moduleLabelsPtr,
404476
esModuleLabelsPtr,
405477
moduleCtrDtrPtr,
406478
sourceCtrPtr,
407479
beginTime,
408-
beginTracer](auto&) mutable {
480+
pythonBegin,
481+
pythonEnd,
482+
servicesBegin,
483+
startupTimes](auto&) mutable {
409484
{
410485
std::ostringstream oss;
411486
moduleIdToLabel(oss, *moduleLabelsPtr, 'M', "EDModule ID", "Module label");
@@ -419,11 +494,52 @@ namespace edm::service::tracer {
419494
esModuleLabelsPtr.reset();
420495
}
421496
{
422-
auto const tracerStart = duration_cast<duration_t>(beginTracer - beginTime).count();
423497
auto msg = assembleMessage<Step::preFrameworkTransition>(
424-
static_cast<std::underlying_type_t<Phase>>(Phase::startTracing), 0, 0, 0, 0, tracerStart);
498+
static_cast<std::underlying_type_t<Phase>>(Phase::processPython), 0, 0, 0, 0, pythonBegin);
499+
logFile->write(std::move(msg));
500+
}
501+
{
502+
auto msg = assembleMessage<Step::postFrameworkTransition>(
503+
static_cast<std::underlying_type_t<Phase>>(Phase::processPython), 0, 0, 0, 0, pythonEnd);
504+
logFile->write(std::move(msg));
505+
}
506+
{
507+
auto msg = assembleMessage<Step::preFrameworkTransition>(
508+
static_cast<std::underlying_type_t<Phase>>(Phase::startServices), 0, 0, 0, 0, servicesBegin);
509+
logFile->write(std::move(msg));
510+
}
511+
{
512+
auto msg = assembleMessage<Step::postFrameworkTransition>(
513+
static_cast<std::underlying_type_t<Phase>>(Phase::startServices),
514+
0,
515+
0,
516+
0,
517+
0,
518+
startupTimes->endServiceConstruction);
519+
logFile->write(std::move(msg));
520+
}
521+
522+
{
523+
auto msg = assembleMessage<Step::preFrameworkTransition>(
524+
static_cast<std::underlying_type_t<Phase>>(Phase::constructESModules),
525+
0,
526+
0,
527+
0,
528+
0,
529+
startupTimes->beginConstructESModules);
425530
logFile->write(std::move(msg));
426531
}
532+
{
533+
auto msg = assembleMessage<Step::postFrameworkTransition>(
534+
static_cast<std::underlying_type_t<Phase>>(Phase::constructESModules),
535+
0,
536+
0,
537+
0,
538+
0,
539+
startupTimes->endConstructESModules);
540+
logFile->write(std::move(msg));
541+
}
542+
427543
//NOTE: the source construction can run concurently with module construction so we need to properly
428544
// interleave its timing in with the modules
429545
auto srcBeginConstruction = sourceCtrPtr->beginConstruction;
@@ -482,6 +598,108 @@ namespace edm::service::tracer {
482598
}
483599
auto const t = duration_cast<duration_t>(steady_clock::now() - beginTime).count();
484600
handleSource(t);
601+
602+
{
603+
auto msg = assembleMessage<Step::preFrameworkTransition>(
604+
static_cast<std::underlying_type_t<Phase>>(Phase::finishSchedule),
605+
0,
606+
0,
607+
0,
608+
0,
609+
startupTimes->beginFinishSchedule);
610+
logFile->write(std::move(msg));
611+
}
612+
{
613+
auto msg = assembleMessage<Step::postFrameworkTransition>(
614+
static_cast<std::underlying_type_t<Phase>>(Phase::finishSchedule),
615+
0,
616+
0,
617+
0,
618+
0,
619+
startupTimes->endFinishSchedule);
620+
logFile->write(std::move(msg));
621+
}
622+
{
623+
auto msg = assembleMessage<Step::preFrameworkTransition>(
624+
static_cast<std::underlying_type_t<Phase>>(Phase::createRunLumiEvents),
625+
0,
626+
0,
627+
0,
628+
0,
629+
startupTimes->beginCreateRunLumiEvents);
630+
logFile->write(std::move(msg));
631+
}
632+
{
633+
auto msg = assembleMessage<Step::postFrameworkTransition>(
634+
static_cast<std::underlying_type_t<Phase>>(Phase::createRunLumiEvents),
635+
0,
636+
0,
637+
0,
638+
0,
639+
startupTimes->endCreateRunLumiEvents);
640+
logFile->write(std::move(msg));
641+
}
642+
{
643+
auto msg = assembleMessage<Step::preFrameworkTransition>(
644+
static_cast<std::underlying_type_t<Phase>>(Phase::scheduleConsistencyCheck),
645+
0,
646+
0,
647+
0,
648+
0,
649+
startupTimes->beginScheduleConsistencyCheck);
650+
logFile->write(std::move(msg));
651+
}
652+
{
653+
auto msg = assembleMessage<Step::postFrameworkTransition>(
654+
static_cast<std::underlying_type_t<Phase>>(Phase::scheduleConsistencyCheck),
655+
0,
656+
0,
657+
0,
658+
0,
659+
startupTimes->endScheduleConsistencyCheck);
660+
logFile->write(std::move(msg));
661+
}
662+
{
663+
auto msg = assembleMessage<Step::preFrameworkTransition>(
664+
static_cast<std::underlying_type_t<Phase>>(Phase::finalizeEventSetupConfiguration),
665+
0,
666+
0,
667+
0,
668+
0,
669+
startupTimes->beginFinalizeEventSetupConfiguration);
670+
logFile->write(std::move(msg));
671+
}
672+
{
673+
auto msg = assembleMessage<Step::postFrameworkTransition>(
674+
static_cast<std::underlying_type_t<Phase>>(Phase::finalizeEventSetupConfiguration),
675+
0,
676+
0,
677+
0,
678+
0,
679+
startupTimes->endFinalizeEventSetupConfiguration);
680+
logFile->write(std::move(msg));
681+
}
682+
{
683+
auto msg = assembleMessage<Step::preFrameworkTransition>(
684+
static_cast<std::underlying_type_t<Phase>>(Phase::finalizeEDModules),
685+
0,
686+
0,
687+
0,
688+
0,
689+
startupTimes->beginFinalizeEDModules);
690+
logFile->write(std::move(msg));
691+
}
692+
{
693+
auto msg = assembleMessage<Step::postFrameworkTransition>(
694+
static_cast<std::underlying_type_t<Phase>>(Phase::finalizeEDModules),
695+
0,
696+
0,
697+
0,
698+
0,
699+
startupTimes->endFinalizeEDModules);
700+
logFile->write(std::move(msg));
701+
}
702+
485703
auto msg = assembleMessage<Step::preFrameworkTransition>(
486704
static_cast<std::underlying_type_t<Phase>>(Phase::beginJob), 0, 0, 0, 0, t);
487705
logFile->write(std::move(msg));
@@ -830,35 +1048,42 @@ namespace edm::service::tracer {
8301048
}
8311049

8321050
std::ostringstream oss;
833-
oss << "# Transition Symbol\n";
834-
oss << "#------------------------ ------\n";
835-
oss << "# startTracing " << Phase::startTracing << "\n"
836-
<< "# construction " << Phase::construction << "\n"
837-
<< "# getNextTransition " << Phase::getNextTransition << "\n"
838-
<< "# esSyncEnqueue " << Phase::esSyncEnqueue << "\n"
839-
<< "# esSync " << Phase::esSync << "\n"
840-
<< "# beginJob " << Phase::beginJob << "\n"
841-
<< "# beginStream " << Phase::beginStream << "\n"
842-
<< "# openFile " << Phase::openFile << "\n"
843-
<< "# beginProcessBlock " << Phase::beginProcessBlock << "\n"
844-
<< "# accessInputProcessBlock " << Phase::accessInputProcessBlock << "\n"
845-
<< "# globalBeginRun " << Phase::globalBeginRun << "\n"
846-
<< "# streamBeginRun " << Phase::streamBeginRun << "\n"
847-
<< "# globalBeginLumi " << Phase::globalBeginLumi << "\n"
848-
<< "# streamBeginLumi " << Phase::streamBeginLumi << "\n"
849-
<< "# Event " << Phase::Event << "\n"
850-
<< "# clearEvent " << Phase::clearEvent << "\n"
851-
<< "# streamEndLumi " << Phase::streamEndLumi << "\n"
852-
<< "# globalEndLumi " << Phase::globalEndLumi << "\n"
853-
<< "# globalWriteLumi " << Phase::globalWriteLumi << "\n"
854-
<< "# streamEndRun " << Phase::streamEndRun << "\n"
855-
<< "# globalEndRun " << Phase::globalEndRun << "\n"
856-
<< "# globalWriteRun " << Phase::globalWriteRun << "\n"
857-
<< "# endProcessBlock " << Phase::endProcessBlock << "\n"
858-
<< "# writeProcessBlock " << Phase::writeProcessBlock << "\n"
859-
<< "# endStream " << Phase::endStream << "\n"
860-
<< "# endJob " << Phase::endJob << "\n"
861-
<< "# destruction " << Phase::destruction << "\n\n";
1051+
oss << "# Transition Symbol\n";
1052+
oss << "#------------------------ ------\n";
1053+
oss << "# processPython " << Phase::processPython << "\n"
1054+
<< "# startServices " << Phase::startServices << "\n"
1055+
<< "# constructionESModules " << Phase::constructESModules << "\n"
1056+
<< "# finishSchedule " << Phase::finishSchedule << "\n"
1057+
<< "# createRunLumiEvents " << Phase::createRunLumiEvents << "\n"
1058+
<< "# scheduleConsistencyCheck " << Phase::scheduleConsistencyCheck << "\n"
1059+
<< "# finish ES Configuration " << Phase::finalizeEventSetupConfiguration << "\n"
1060+
<< "# finalize EDModules " << Phase::finalizeEDModules << "\n"
1061+
<< "# construction " << Phase::construction << "\n"
1062+
<< "# getNextTransition " << Phase::getNextTransition << "\n"
1063+
<< "# esSyncEnqueue " << Phase::esSyncEnqueue << "\n"
1064+
<< "# esSync " << Phase::esSync << "\n"
1065+
<< "# beginJob " << Phase::beginJob << "\n"
1066+
<< "# beginStream " << Phase::beginStream << "\n"
1067+
<< "# openFile " << Phase::openFile << "\n"
1068+
<< "# beginProcessBlock " << Phase::beginProcessBlock << "\n"
1069+
<< "# accessInputProcessBlock " << Phase::accessInputProcessBlock << "\n"
1070+
<< "# globalBeginRun " << Phase::globalBeginRun << "\n"
1071+
<< "# streamBeginRun " << Phase::streamBeginRun << "\n"
1072+
<< "# globalBeginLumi " << Phase::globalBeginLumi << "\n"
1073+
<< "# streamBeginLumi " << Phase::streamBeginLumi << "\n"
1074+
<< "# Event " << Phase::Event << "\n"
1075+
<< "# clearEvent " << Phase::clearEvent << "\n"
1076+
<< "# streamEndLumi " << Phase::streamEndLumi << "\n"
1077+
<< "# globalEndLumi " << Phase::globalEndLumi << "\n"
1078+
<< "# globalWriteLumi " << Phase::globalWriteLumi << "\n"
1079+
<< "# streamEndRun " << Phase::streamEndRun << "\n"
1080+
<< "# globalEndRun " << Phase::globalEndRun << "\n"
1081+
<< "# globalWriteRun " << Phase::globalWriteRun << "\n"
1082+
<< "# endProcessBlock " << Phase::endProcessBlock << "\n"
1083+
<< "# writeProcessBlock " << Phase::writeProcessBlock << "\n"
1084+
<< "# endStream " << Phase::endStream << "\n"
1085+
<< "# endJob " << Phase::endJob << "\n"
1086+
<< "# destruction " << Phase::destruction << "\n\n";
8621087
oss << "# Step Symbol Entries\n"
8631088
<< "# -------------------------- ------ ------------------------------------------\n"
8641089
<< "# preSourceTransition " << Step::preSourceTransition

0 commit comments

Comments
 (0)