28 #include "tbb/concurrent_unordered_map.h"
38 using duration_t = std::chrono::microseconds;
39 using clock_t = std::chrono::steady_clock;
47 class StallStatistics {
52 StallStatistics() =
default;
55 unsigned numberOfStalls()
const {
return stallCounter_; }
59 duration_t totalStalledTime()
const {
return duration_t{totalTime_.load()}; }
60 duration_t maxStalledTime()
const {
return duration_t{maxTime_.load()}; }
65 void update(duration_t
const ms) {
67 auto const thisTime = ms.count();
68 totalTime_ += thisTime;
70 while (thisTime >
max && !maxTime_.compare_exchange_strong(
max, thisTime))
76 std::atomic<unsigned> stallCounter_{};
77 std::atomic<rep_t> totalTime_{};
78 std::atomic<rep_t> maxTime_{};
88 template <
typename H,
typename...
T>
91 concatenate(os,
t...);
96 postSourceEvent =
's',
98 postModuleEventPrefetching =
'p',
99 preModuleEventAcquire =
'A',
100 postModuleEventAcquire =
'a',
101 preModuleEvent =
'M',
102 preEventReadFromSource =
'R',
103 postEventReadFromSource =
'r',
104 postModuleEvent =
'm',
121 os << static_cast<std::underlying_type_t<step>>(
s);
126 os << static_cast<std::underlying_type_t<Phase>>(
s);
130 template <
step S,
typename... ARGS>
132 std::ostringstream oss;
134 concatenate(oss,
args...);
142 case StreamContext::Transition::kBeginRun:
143 return Phase::streamBeginRun;
144 case StreamContext::Transition::kBeginLuminosityBlock:
145 return Phase::streamBeginLumi;
146 case StreamContext::Transition::kEvent:
148 case StreamContext::Transition::kEndLuminosityBlock:
149 return Phase::streamEndLumi;
150 case StreamContext::Transition::kEndRun:
151 return Phase::streamEndRun;
159 auto toTransition(
edm::StreamContext const& iContext) -> std::underlying_type_t<Phase> {
160 return static_cast<std::underlying_type_t<Phase>
>(toTransitionImpl(iContext));
166 case GlobalContext::Transition::kBeginRun:
167 return Phase::globalBeginRun;
168 case GlobalContext::Transition::kBeginLuminosityBlock:
169 return Phase::globalBeginLumi;
170 case GlobalContext::Transition::kEndLuminosityBlock:
171 return Phase::globalEndLumi;
172 case GlobalContext::Transition::kWriteLuminosityBlock:
173 return Phase::globalEndLumi;
174 case GlobalContext::Transition::kEndRun:
175 return Phase::globalEndRun;
176 case GlobalContext::Transition::kWriteRun:
177 return Phase::globalEndRun;
184 auto toTransition(
edm::GlobalContext const& iContext) -> std::underlying_type_t<Phase> {
185 return static_cast<std::underlying_type_t<Phase>
>(toTransitionImpl(iContext));
222 decltype(
now()) beginTime_{};
229 using ModuleID = decltype(std::declval<ModuleDescription>().
id());
230 tbb::concurrent_unordered_map<std::pair<StreamID_value, ModuleID>, std::pair<decltype(beginTime_),
bool>>
233 std::vector<std::string> moduleLabels_{};
234 std::vector<StallStatistics> moduleStats_{};
243 constexpr
char const* filename_default{
""};
244 constexpr
double threshold_default{0.1};
249 using namespace std::chrono;
255 std::chrono::round<duration_t>(duration<double>(iPS.getUntrackedParameter<
double>(
"stallThreshold")))} {
299 iRegistry.preallocateSignal_.connect(
300 [
this](service::SystemBounds
const& iBounds) { numStreams_ = iBounds.maxNumberOfStreams(); });
302 std::ostringstream oss;
303 oss <<
"# Transition Symbol\n";
304 oss <<
"#----------------- ------\n";
305 oss <<
"# globalBeginRun " << Phase::globalBeginRun <<
"\n"
306 <<
"# streamBeginRun " << Phase::streamBeginRun <<
"\n"
307 <<
"# globalBeginLumi " << Phase::globalBeginLumi <<
"\n"
308 <<
"# streamBeginLumi " << Phase::streamBeginLumi <<
"\n"
310 <<
"# streamEndLumi " << Phase::streamEndLumi <<
"\n"
311 <<
"# globalEndLumi " << Phase::globalEndLumi <<
"\n"
312 <<
"# streamEndRun " << Phase::streamEndRun <<
"\n"
313 <<
"# globalEndRun " << Phase::globalEndRun <<
"\n";
314 oss <<
"# Step Symbol Entries\n"
315 <<
"# -------------------------- ------ ------------------------------------------\n"
316 <<
"# preSourceEvent " << step::preSourceEvent <<
" <Stream ID> <Time since beginJob (ms)>\n"
317 <<
"# postSourceEvent " << step::postSourceEvent <<
" <Stream ID> <Time since beginJob (ms)>\n"
318 <<
"# preEvent " << step::preEvent
319 <<
" <Stream ID> <Run#> <LumiBlock#> <Event#> <Time since beginJob (ms)>\n"
320 <<
"# postModuleEventPrefetching " << step::postModuleEventPrefetching
321 <<
" <Stream ID> <Module ID> <Time since beginJob (ms)>\n"
322 <<
"# preModuleEventAcquire " << step::preModuleEventAcquire
323 <<
" <Stream ID> <Module ID> <Time since beginJob (ms)>\n"
324 <<
"# postModuleEventAcquire " << step::postModuleEventAcquire
325 <<
" <Stream ID> <Module ID> <Time since beginJob (ms)>\n"
326 <<
"# preModuleTransition " << step::preModuleEvent
327 <<
" <Stream ID> <Module ID> <Transition type> <Time since beginJob (ms)>\n"
328 <<
"# preEventReadFromSource " << step::preEventReadFromSource
329 <<
" <Stream ID> <Module ID> <Time since beginJob (ms)>\n"
330 <<
"# postEventReadFromSource " << step::postEventReadFromSource
331 <<
" <Stream ID> <Module ID> <Time since beginJob (ms)>\n"
332 <<
"# postModuleTransition " << step::postModuleEvent
333 <<
" <Stream ID> <Module ID> <Transition type> <Time since beginJob (ms)>\n"
334 <<
"# postEvent " << step::postEvent
335 <<
" <Stream ID> <Run#> <LumiBlock#> <Event#> <Time since beginJob (ms)>\n";
336 file_.
write(oss.str());
344 "Name of file to which detailed timing information should be written.\n"
345 "An empty filename argument (the default) indicates that no extra\n"
346 "information will be written to a dedicated file, but only the summary\n"
347 "including stalling-modules information will be logged.");
348 desc.addUntracked<
double>(
"stallThreshold", threshold_default)
350 "Threshold (in seconds) used to classify modules as stalled.\n"
351 "Microsecond granularity allowed.");
352 descriptions.
add(
"StallMonitor",
desc);
354 "This service keeps track of various times in event-processing to determine which modules are stalling.");
369 auto const mid = md.
id();
400 std::ostringstream oss;
401 oss <<
"\n# " << col0 << space << lastCol <<
'\n';
402 oss <<
"# " <<
std::string(col0.width() + space.size() + lastCol.size(),
'-') <<
'\n';
408 oss <<
"#M " << std::setw(
width) << std::left << col0(
i) << space << std::left <<
moduleLabels_[
i] <<
'\n';
421 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
422 auto msg = assembleMessage<step::preSourceEvent>(sid.
value(),
t);
427 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
428 auto msg = assembleMessage<step::postSourceEvent>(sid.
value(),
t);
433 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
435 auto msg = assembleMessage<step::preEvent>(stream_id(sc),
eid.run(),
eid.luminosityBlock(),
eid.event(),
t);
440 auto const sid = stream_id(sc);
441 auto const mid = module_id(mcc);
446 auto msg = assembleMessage<step::postModuleEventPrefetching>(sid, mid,
t);
452 auto const preModEventAcquire =
now();
453 auto const sid = stream_id(sc);
454 auto const mid = module_id(mcc);
456 auto startT =
start.first.time_since_epoch();
459 auto t = duration_cast<duration_t>(preModEventAcquire -
beginTime_).count();
460 auto msg = assembleMessage<step::preModuleEventAcquire>(sid, mid,
t);
465 auto const preFetch_to_preModEventAcquire = duration_cast<duration_t>(preModEventAcquire -
start.first);
468 moduleStats_[mid].update(preFetch_to_preModEventAcquire);
473 auto const postModEventAcquire = duration_cast<duration_t>(
now() -
beginTime_).count();
474 auto msg = assembleMessage<step::postModuleEventAcquire>(stream_id(sc), module_id(mcc), postModEventAcquire);
479 auto const preModEvent =
now();
480 auto const sid = stream_id(sc);
481 auto const mid = module_id(mcc);
483 auto startT =
start.first.time_since_epoch();
485 auto t = duration_cast<duration_t>(preModEvent -
beginTime_).count();
487 assembleMessage<step::preModuleEvent>(sid, mid,
static_cast<std::underlying_type_t<Phase>
>(
Phase::Event),
t);
492 auto const preFetch_to_preModEvent = duration_cast<duration_t>(preModEvent -
start.first);
500 auto const tNow =
now();
501 auto const sid = stream_id(sc);
502 auto const mid = module_id(mcc);
503 auto t = duration_cast<duration_t>(tNow -
beginTime_).count();
504 auto msg = assembleMessage<step::preModuleEvent>(sid, mid, toTransition(sc),
t);
509 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
510 auto msg = assembleMessage<step::postModuleEvent>(stream_id(sc), module_id(mcc), toTransition(sc),
t);
516 auto msg = assembleMessage<step::preModuleEvent>(
numStreams_, module_id(mcc), toTransition(gc),
t);
521 auto const postModTime = duration_cast<duration_t>(
now() -
beginTime_).count();
522 auto msg = assembleMessage<step::postModuleEvent>(
numStreams_, module_id(mcc), toTransition(gc), postModTime);
527 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
528 auto msg = assembleMessage<step::preEventReadFromSource>(stream_id(sc), module_id(mcc),
t);
533 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
534 auto msg = assembleMessage<step::postEventReadFromSource>(stream_id(sc), module_id(mcc),
t);
539 auto const postModEvent = duration_cast<duration_t>(
now() -
beginTime_).count();
540 auto msg = assembleMessage<step::postModuleEvent>(
541 stream_id(sc), module_id(mcc),
static_cast<std::underlying_type_t<Phase>
>(
Phase::Event), postModEvent);
546 auto const t = duration_cast<duration_t>(
now() -
beginTime_).count();
548 auto msg = assembleMessage<step::postEvent>(stream_id(sc),
eid.run(),
eid.luminosityBlock(),
eid.event(),
t);
556 if (
stats.numberOfStalls() == 0u)
569 out <<
tag << space << col1 << space << col2 << space << col3 << space << col4 <<
'\n';
574 using seconds_d = duration<double>;
576 auto to_seconds_str = [](
auto const& duration) {
577 std::ostringstream oss;
578 auto const time = duration_cast<seconds_d>(duration).count();
583 out << std::setfill(
' ');
585 if (
stats.label().empty() ||
586 stats.numberOfStalls() == 0u)
588 out << std::left <<
tag << space << col1(
stats.label()) << space << std::right << col2(
stats.numberOfStalls())
589 << space << col3(to_seconds_str(
stats.totalStalledTime())) << space
590 << col4(to_seconds_str(
stats.maxStalledTime())) <<
'\n';