CMS 3D CMS Logo

FastTimerService.cc
Go to the documentation of this file.
1 // C++ headers
2 #include <cmath>
3 #include <fstream>
4 #include <iomanip>
5 #include <iostream>
6 #include <limits>
7 #include <mutex>
8 #include <sstream>
9 #include <string>
10 #include <unordered_map>
11 #include <unordered_set>
12 
13 // boost headers
14 #include <boost/range/irange.hpp>
15 
16 // {fmt} headers
17 #include <fmt/printf.h>
18 
19 // JSON headers
20 #include <nlohmann/json.hpp>
22 
23 // CMSSW headers
42 #include "FastTimerService.h"
43 
44 using namespace std::literals;
45 
47 
48 namespace {
49 
50  // convert any std::chrono::duration to milliseconds
51  template <class Rep, class Period>
52  double ms(std::chrono::duration<Rep, Period> duration) {
53  return std::chrono::duration_cast<std::chrono::duration<double, std::milli>>(duration).count();
54  }
55 
56  // convert any boost::chrono::duration to milliseconds
57  template <class Rep, class Period>
58  double ms(boost::chrono::duration<Rep, Period> duration) {
59  return boost::chrono::duration_cast<boost::chrono::duration<double, boost::milli>>(duration).count();
60  }
61 
62  // convert a std::atomic<boost::chrono::nanoseconds::rep> to milliseconds
63  double ms(std::atomic<boost::chrono::nanoseconds::rep> const& duration) {
64  return boost::chrono::duration_cast<boost::chrono::duration<double, boost::milli>>(
65  boost::chrono::nanoseconds(duration.load()))
66  .count();
67  }
68 
69  // convert from bytes to kilobytes, rounding down
70  uint64_t kB(uint64_t bytes) { return bytes / 1024; }
71 
72  // convert from bytes to kilobytes, rounding down
73  uint64_t kB(std::atomic<uint64_t> const& bytes) { return bytes.load() / 1024; }
74 
75 } // namespace
76 
78 
79 // resources being monitored by the service
80 
81 // Resources
82 
84  : time_thread(boost::chrono::nanoseconds::zero()),
85  time_real(boost::chrono::nanoseconds::zero()),
86  allocated(0ul),
87  deallocated(0ul) {}
88 
90  time_thread = boost::chrono::nanoseconds::zero();
92  allocated = 0ul;
93  deallocated = 0ul;
94 }
95 
97  time_thread += other.time_thread;
98  time_real += other.time_real;
99  allocated += other.allocated;
100  deallocated += other.deallocated;
101  return *this;
102 }
103 
105  time_thread += boost::chrono::nanoseconds(other.time_thread.load());
106  time_real += boost::chrono::nanoseconds(other.time_real.load());
107  allocated += other.allocated.load();
108  deallocated += other.deallocated.load();
109  return *this;
110 }
111 
113  Resources result(*this);
114  result += other;
115  return result;
116 }
117 
119  Resources result(*this);
120  result += other;
121  return result;
122 }
123 
124 // AtomicResources
125 // operation on the whole object are not atomic, as the operations
126 // on the individual fields could be interleaved; however, accumulation
127 // of results should yield the correct result.
128 
130  : time_thread(0ul), time_real(0ul), allocated(0ul), deallocated(0ul) {}
131 
133  : time_thread(other.time_thread.load()),
134  time_real(other.time_real.load()),
135  allocated(other.allocated.load()),
136  deallocated(other.deallocated.load()) {}
137 
139  time_thread = 0ul;
140  time_real = 0ul;
141  allocated = 0ul;
142  deallocated = 0ul;
143 }
144 
146  time_thread = other.time_thread.load();
147  time_real = other.time_real.load();
148  allocated = other.allocated.load();
149  deallocated = other.deallocated.load();
150  return *this;
151 }
152 
154  time_thread += other.time_thread.load();
155  time_real += other.time_real.load();
156  allocated += other.allocated.load();
157  deallocated += other.deallocated.load();
158  return *this;
159 }
160 
162  time_thread += other.time_thread.count();
163  time_real += other.time_real.count();
164  allocated += other.allocated;
165  deallocated += other.deallocated;
166  return *this;
167 }
168 
170  AtomicResources result(*this);
171  result += other;
172  return result;
173 }
174 
176  return other + *this;
177 }
178 
179 // ResourcesPerModule
180 
182 
184  total.reset();
185  events = 0;
186  has_acquire = false;
187 }
188 
190  total += other.total;
191  events += other.events;
192  has_acquire = has_acquire or other.has_acquire;
193  return *this;
194 }
195 
197  ResourcesPerModule const& other) const {
198  ResourcesPerModule result(*this);
199  result += other;
200  return result;
201 }
202 
203 // ResourcesPerPath
204 
206  active.reset();
207  total.reset();
208  last = 0;
209  status = false;
210 }
211 
213  active += other.active;
214  total += other.total;
215  last = 0; // summing these makes no sense, reset them instead
216  status = false;
217  return *this;
218 }
219 
221  ResourcesPerPath result(*this);
222  result += other;
223  return result;
224 }
225 
226 // ResourcesPerProcess
227 
229  : total(), paths(process.paths_.size()), endpaths(process.endPaths_.size()) {}
230 
232  total.reset();
233  for (auto& path : paths)
234  path.reset();
235  for (auto& path : endpaths)
236  path.reset();
237 }
238 
240  ResourcesPerProcess const& other) {
241  total += other.total;
242  assert(paths.size() == other.paths.size());
243  for (unsigned int i : boost::irange(0ul, paths.size()))
244  paths[i] += other.paths[i];
245  assert(endpaths.size() == other.endpaths.size());
246  for (unsigned int i : boost::irange(0ul, endpaths.size()))
247  endpaths[i] += other.endpaths[i];
248  return *this;
249 }
250 
252  ResourcesPerProcess const& other) const {
254  result += other;
255  return result;
256 }
257 
258 // ResourcesPerJob
259 
261  std::vector<GroupOfModules> const& groups)
262  : total(), overhead(), eventsetup(), event(), highlight(groups.size()), modules(job.size()), processes(), events(0) {
263  processes.reserve(job.processes().size());
264  for (auto const& process : job.processes())
265  processes.emplace_back(process);
266 }
267 
269  total.reset();
270  overhead.reset();
271  eventsetup.reset();
272  event.reset();
273  for (auto& module : highlight)
274  module.reset();
275  for (auto& module : modules)
276  module.reset();
277  for (auto& process : processes)
278  process.reset();
279  events = 0;
280 }
281 
283  total += other.total;
284  overhead += other.overhead;
285  eventsetup += other.eventsetup;
286  event += other.event;
287  assert(highlight.size() == other.highlight.size());
288  for (unsigned int i : boost::irange(0ul, highlight.size()))
289  highlight[i] += other.highlight[i];
290  assert(modules.size() == other.modules.size());
291  for (unsigned int i : boost::irange(0ul, modules.size()))
292  modules[i] += other.modules[i];
293  assert(processes.size() == other.processes.size());
294  for (unsigned int i : boost::irange(0ul, processes.size()))
295  processes[i] += other.processes[i];
296  events += other.events;
297  return *this;
298 }
299 
301  ResourcesPerJob result(*this);
302  result += other;
303  return result;
304 }
305 
306 // per-thread measurements
307 
308 // Measurement
309 
311 
313 #ifdef DEBUG_THREAD_CONCURRENCY
314  id = std::this_thread::get_id();
315 #endif // DEBUG_THREAD_CONCURRENCY
316  time_thread = boost::chrono::thread_clock::now();
318  allocated = memory_usage::allocated();
319  deallocated = memory_usage::deallocated();
320 }
321 
323 #ifdef DEBUG_THREAD_CONCURRENCY
324  assert(std::this_thread::get_id() == id);
325 #endif // DEBUG_THREAD_CONCURRENCY
326  auto new_time_thread = boost::chrono::thread_clock::now();
327  auto new_time_real = boost::chrono::high_resolution_clock::now();
328  auto new_allocated = memory_usage::allocated();
329  auto new_deallocated = memory_usage::deallocated();
330  store.time_thread = new_time_thread - time_thread;
331  store.time_real = new_time_real - time_real;
332  store.allocated = new_allocated - allocated;
333  store.deallocated = new_deallocated - deallocated;
334  time_thread = new_time_thread;
335  time_real = new_time_real;
336  allocated = new_allocated;
337  deallocated = new_deallocated;
338 }
339 
341 #ifdef DEBUG_THREAD_CONCURRENCY
342  assert(std::this_thread::get_id() == id);
343 #endif // DEBUG_THREAD_CONCURRENCY
344  auto new_time_thread = boost::chrono::thread_clock::now();
345  auto new_time_real = boost::chrono::high_resolution_clock::now();
346  auto new_allocated = memory_usage::allocated();
347  auto new_deallocated = memory_usage::deallocated();
348  store.time_thread += new_time_thread - time_thread;
349  store.time_real += new_time_real - time_real;
350  store.allocated += new_allocated - allocated;
351  store.deallocated += new_deallocated - deallocated;
352  time_thread = new_time_thread;
353  time_real = new_time_real;
354  allocated = new_allocated;
355  deallocated = new_deallocated;
356 }
357 
359 #ifdef DEBUG_THREAD_CONCURRENCY
360  assert(std::this_thread::get_id() == id);
361 #endif // DEBUG_THREAD_CONCURRENCY
362  auto new_time_thread = boost::chrono::thread_clock::now();
363  auto new_time_real = boost::chrono::high_resolution_clock::now();
364  auto new_allocated = memory_usage::allocated();
365  auto new_deallocated = memory_usage::deallocated();
366  store.time_thread += boost::chrono::duration_cast<boost::chrono::nanoseconds>(new_time_thread - time_thread).count();
367  store.time_real += boost::chrono::duration_cast<boost::chrono::nanoseconds>(new_time_real - time_real).count();
368  store.allocated += new_allocated - allocated;
369  store.deallocated += new_deallocated - deallocated;
370  time_thread = new_time_thread;
371  time_real = new_time_real;
372  allocated = new_allocated;
373  deallocated = new_deallocated;
374 }
375 
377 
379  std::string const& name,
380  std::string const& title,
381  PlotRanges const& ranges,
382  unsigned int lumisections,
383  bool byls) {
384  int time_bins = (int)std::ceil(ranges.time_range / ranges.time_resolution);
385  int mem_bins = (int)std::ceil(ranges.memory_range / ranges.memory_resolution);
386  std::string y_title_ms = fmt::sprintf("events / %.1f ms", ranges.time_resolution);
387  std::string y_title_kB = fmt::sprintf("events / %.1f kB", ranges.memory_resolution);
388 
389  // MonitorElement::setStatOverflows(kTRUE) includes underflows and overflows in the computation of mean and RMS
390  time_thread_ =
391  booker.book1D(name + " time_thread", title + " processing time (cpu)", time_bins, 0., ranges.time_range);
392  time_thread_->setXTitle("processing time [ms]");
393  time_thread_->setYTitle(y_title_ms);
394  time_thread_->setStatOverflows(kTRUE);
395 
396  time_real_ = booker.book1D(name + " time_real", title + " processing time (real)", time_bins, 0., ranges.time_range);
397  time_real_->setXTitle("processing time [ms]");
398  time_real_->setYTitle(y_title_ms);
399  time_real_->setStatOverflows(kTRUE);
400 
402  allocated_ = booker.book1D(name + " allocated", title + " allocated memory", mem_bins, 0., ranges.memory_range);
403  allocated_->setXTitle("memory [kB]");
404  allocated_->setYTitle(y_title_kB);
405  allocated_->setStatOverflows(kTRUE);
406 
407  deallocated_ =
408  booker.book1D(name + " deallocated", title + " deallocated memory", mem_bins, 0., ranges.memory_range);
409  deallocated_->setXTitle("memory [kB]");
410  deallocated_->setYTitle(y_title_kB);
411  deallocated_->setStatOverflows(kTRUE);
412  }
413 
414  if (not byls)
415  return;
416 
417  time_thread_byls_ = booker.bookProfile(name + " time_thread_byls",
418  title + " processing time (cpu) vs. lumisection",
419  lumisections,
420  0.5,
421  lumisections + 0.5,
422  time_bins,
423  0.,
425  " ");
426  time_thread_byls_->setXTitle("lumisection");
427  time_thread_byls_->setYTitle("processing time [ms]");
428  time_thread_byls_->setStatOverflows(kTRUE);
429 
430  time_real_byls_ = booker.bookProfile(name + " time_real_byls",
431  title + " processing time (real) vs. lumisection",
432  lumisections,
433  0.5,
434  lumisections + 0.5,
435  time_bins,
436  0.,
438  " ");
439  time_real_byls_->setXTitle("lumisection");
440  time_real_byls_->setYTitle("processing time [ms]");
441  time_real_byls_->setStatOverflows(kTRUE);
442 
444  allocated_byls_ = booker.bookProfile(name + " allocated_byls",
445  title + " allocated memory vs. lumisection",
446  lumisections,
447  0.5,
448  lumisections + 0.5,
449  mem_bins,
450  0.,
452  " ");
453  allocated_byls_->setXTitle("lumisection");
454  allocated_byls_->setYTitle("memory [kB]");
455  allocated_byls_->setStatOverflows(kTRUE);
456 
457  deallocated_byls_ = booker.bookProfile(name + " deallocated_byls",
458  title + " deallocated memory vs. lumisection",
459  lumisections,
460  0.5,
461  lumisections + 0.5,
462  mem_bins,
463  0.,
465  " ");
466  deallocated_byls_->setXTitle("lumisection");
467  deallocated_byls_->setYTitle("memory [kB]");
468  deallocated_byls_->setStatOverflows(kTRUE);
469  }
470 }
471 
472 void FastTimerService::PlotsPerElement::fill(Resources const& data, unsigned int lumisection) {
473  if (time_thread_)
474  time_thread_->Fill(ms(data.time_thread));
475 
476  if (time_thread_byls_)
477  time_thread_byls_->Fill(lumisection, ms(data.time_thread));
478 
479  if (time_real_)
480  time_real_->Fill(ms(data.time_real));
481 
482  if (time_real_byls_)
483  time_real_byls_->Fill(lumisection, ms(data.time_real));
484 
485  if (allocated_)
486  allocated_->Fill(kB(data.allocated));
487 
488  if (allocated_byls_)
489  allocated_byls_->Fill(lumisection, kB(data.allocated));
490 
491  if (deallocated_)
492  deallocated_->Fill(kB(data.deallocated));
493 
494  if (deallocated_byls_)
495  deallocated_byls_->Fill(lumisection, kB(data.deallocated));
496 }
497 
498 void FastTimerService::PlotsPerElement::fill(AtomicResources const& data, unsigned int lumisection) {
499  if (time_thread_)
500  time_thread_->Fill(ms(boost::chrono::nanoseconds(data.time_thread.load())));
501 
502  if (time_thread_byls_)
503  time_thread_byls_->Fill(lumisection, ms(boost::chrono::nanoseconds(data.time_thread.load())));
504 
505  if (time_real_)
506  time_real_->Fill(ms(boost::chrono::nanoseconds(data.time_real.load())));
507 
508  if (time_real_byls_)
509  time_real_byls_->Fill(lumisection, ms(boost::chrono::nanoseconds(data.time_real.load())));
510 
511  if (allocated_)
512  allocated_->Fill(kB(data.allocated));
513 
514  if (allocated_byls_)
515  allocated_byls_->Fill(lumisection, kB(data.allocated));
516 
517  if (deallocated_)
518  deallocated_->Fill(kB(data.deallocated));
519 
520  if (deallocated_byls_)
521  deallocated_byls_->Fill(lumisection, kB(data.deallocated));
522 }
523 
525  Resources const& part,
526  unsigned int lumisection) {
527  float total;
528  float fraction;
529 
530  total = ms(data.time_thread);
531  fraction = (total > 0.) ? (ms(part.time_thread) / total) : 0.;
532  if (time_thread_)
533  time_thread_->Fill(total, fraction);
534 
535  if (time_thread_byls_)
536  time_thread_byls_->Fill(lumisection, total, fraction);
537 
538  total = ms(data.time_real);
539  fraction = (total > 0.) ? (ms(part.time_real) / total) : 0.;
540  if (time_real_)
541  time_real_->Fill(total, fraction);
542 
543  if (time_real_byls_)
544  time_real_byls_->Fill(lumisection, total, fraction);
545 
546  total = kB(data.allocated);
547  fraction = (total > 0.) ? (kB(part.allocated) / total) : 0.;
548  if (allocated_)
549  allocated_->Fill(total, fraction);
550 
551  if (allocated_byls_)
552  allocated_byls_->Fill(lumisection, total, fraction);
553 
554  total = kB(data.deallocated);
555  fraction = (total > 0.) ? (kB(part.deallocated) / total) : 0.;
556  if (deallocated_)
557  deallocated_->Fill(total, fraction);
558 
559  if (deallocated_byls_)
560  deallocated_byls_->Fill(lumisection, total, fraction);
561 }
562 
564  std::string const& prefixDir,
565  ProcessCallGraph const& job,
567  PlotRanges const& ranges,
568  unsigned int lumisections,
569  bool byls) {
570  const std::string basedir = booker.pwd();
571  std::string folderName = basedir + "/" + prefixDir + path.name_;
574 
575  total_.book(booker, "path", path.name_, ranges, lumisections, byls);
576 
577  // MonitorElement::setStatOverflows(kTRUE) includes underflows and overflows in the computation of mean and RMS
578  unsigned int bins = path.modules_and_dependencies_.size();
579  module_counter_ = booker.book1DD("module_counter", "module counter", bins + 1, -0.5, bins + 0.5);
580  module_counter_->setYTitle("events");
581  module_counter_->setStatOverflows(kTRUE);
582  module_time_thread_total_ =
583  booker.book1DD("module_time_thread_total", "total module time (cpu)", bins, -0.5, bins - 0.5);
584  module_time_thread_total_->setYTitle("processing time [ms]");
585  module_time_thread_total_->setStatOverflows(kTRUE);
586  module_time_real_total_ =
587  booker.book1DD("module_time_real_total", "total module time (real)", bins, -0.5, bins - 0.5);
588  module_time_real_total_->setYTitle("processing time [ms]");
589  module_time_real_total_->setStatOverflows(kTRUE);
591  module_allocated_total_ =
592  booker.book1DD("module_allocated_total", "total allocated memory", bins, -0.5, bins - 0.5);
593  module_allocated_total_->setYTitle("memory [kB]");
594  module_allocated_total_->setStatOverflows(kTRUE);
595  module_deallocated_total_ =
596  booker.book1DD("module_deallocated_total", "total deallocated memory", bins, -0.5, bins - 0.5);
597  module_deallocated_total_->setYTitle("memory [kB]");
598  module_deallocated_total_->setStatOverflows(kTRUE);
599  }
600  for (unsigned int bin : boost::irange(0u, bins)) {
601  auto const& module = job[path.modules_and_dependencies_[bin]];
602  std::string const& label =
603  module.scheduled_ ? module.module_.moduleLabel() : module.module_.moduleLabel() + " (unscheduled)";
604  module_counter_->setBinLabel(bin + 1, label);
605  module_time_thread_total_->setBinLabel(bin + 1, label);
606  module_time_real_total_->setBinLabel(bin + 1, label);
608  module_allocated_total_->setBinLabel(bin + 1, label);
609  module_deallocated_total_->setBinLabel(bin + 1, label);
610  }
611  }
612  module_counter_->setBinLabel(bins + 1, "");
613 
614  booker.setCurrentFolder(basedir);
615 }
616 
618  ResourcesPerJob const& data,
619  ResourcesPerPath const& path,
620  unsigned int ls) {
621  // fill the total path time
622  total_.fill(path.total, ls);
623 
624  // fill the modules that actually ran and the total time spent in each od them
625  for (unsigned int i = 0; i < path.last; ++i) {
626  auto const& module = data.modules[description.modules_and_dependencies_[i]];
627  if (module_counter_)
628  module_counter_->Fill(i);
629 
630  if (module_time_thread_total_)
631  module_time_thread_total_->Fill(i, ms(module.total.time_thread));
632 
633  if (module_time_real_total_)
634  module_time_real_total_->Fill(i, ms(module.total.time_real));
635 
636  if (module_allocated_total_)
637  module_allocated_total_->Fill(i, kB(module.total.allocated));
638 
639  if (module_deallocated_total_)
640  module_deallocated_total_->Fill(i, kB(module.total.deallocated));
641  }
642  if (module_counter_ and path.status)
643  module_counter_->Fill(path.last);
644 }
645 
647  : event_(), paths_(process.paths_.size()), endpaths_(process.endPaths_.size()) {}
648 
650  ProcessCallGraph const& job,
652  PlotRanges const& event_ranges,
653  PlotRanges const& path_ranges,
654  unsigned int lumisections,
655  bool bypath,
656  bool byls) {
657  const std::string basedir = booker.pwd();
658  event_.book(booker, "process " + process.name_, "process " + process.name_, event_ranges, lumisections, byls);
659  if (bypath) {
660  booker.setCurrentFolder(basedir + "/process " + process.name_ + " paths");
661  for (unsigned int id : boost::irange(0ul, paths_.size())) {
662  paths_[id].book(booker, "path ", job, process.paths_[id], path_ranges, lumisections, byls);
663  }
664  for (unsigned int id : boost::irange(0ul, endpaths_.size())) {
665  endpaths_[id].book(booker, "endpath ", job, process.endPaths_[id], path_ranges, lumisections, byls);
666  }
667  booker.setCurrentFolder(basedir);
668  }
669 }
670 
672  ResourcesPerJob const& data,
674  unsigned int ls) {
675  // fill process event plots
676  event_.fill(process.total, ls);
677 
678  // fill all paths plots
679  for (unsigned int id : boost::irange(0ul, paths_.size()))
680  paths_[id].fill(description.paths_[id], data, process.paths[id], ls);
681 
682  // fill all endpaths plots
683  for (unsigned int id : boost::irange(0ul, endpaths_.size()))
684  endpaths_[id].fill(description.endPaths_[id], data, process.endpaths[id], ls);
685 }
686 
687 FastTimerService::PlotsPerJob::PlotsPerJob(ProcessCallGraph const& job, std::vector<GroupOfModules> const& groups)
688  : event_(), event_ex_(), overhead_(), highlight_(groups.size()), modules_(job.size()), processes_() {
689  processes_.reserve(job.processes().size());
690  for (auto const& process : job.processes())
691  processes_.emplace_back(process);
692 }
693 
695  ProcessCallGraph const& job,
696  std::vector<GroupOfModules> const& groups,
697  PlotRanges const& event_ranges,
698  PlotRanges const& path_ranges,
699  PlotRanges const& module_ranges,
700  unsigned int lumisections,
701  bool bymodule,
702  bool bypath,
703  bool byls,
704  bool transitions) {
705  const std::string basedir = booker.pwd();
706 
707  // event summary plots
708  event_.book(booker, "event", "Event", event_ranges, lumisections, byls);
709 
710  event_ex_.book(booker, "explicit", "Event (explicit)", event_ranges, lumisections, byls);
711 
712  overhead_.book(booker, "overhead", "Overhead", event_ranges, lumisections, byls);
713 
714  modules_[job.source().id()].book(booker, "source", "Source", module_ranges, lumisections, byls);
715 
716  if (transitions) {
717  lumi_.book(booker, "lumi", "LumiSection transitions", event_ranges, lumisections, byls);
718 
719  run_.book(booker, "run", "Run transtions", event_ranges, lumisections, false);
720  }
721 
722  // plot the time spent in few given groups of modules
723  for (unsigned int group : boost::irange(0ul, groups.size())) {
724  auto const& label = groups[group].label;
725  highlight_[group].book(booker, "highlight " + label, "Highlight " + label, event_ranges, lumisections, byls);
726  }
727 
728  // plots per subprocess (event, modules, paths and endpaths)
729  for (unsigned int pid : boost::irange(0ul, job.processes().size())) {
730  auto const& process = job.processDescription(pid);
731  processes_[pid].book(booker, job, process, event_ranges, path_ranges, lumisections, bypath, byls);
732 
733  if (bymodule) {
734  booker.setCurrentFolder(basedir + "/process " + process.name_ + " modules");
735  for (unsigned int id : process.modules_) {
736  std::string const& module_label = job.module(id).moduleLabel();
737  std::string safe_label = module_label;
738  fixForDQM(safe_label);
739  modules_[id].book(booker, safe_label, module_label, module_ranges, lumisections, byls);
740  }
741  booker.setCurrentFolder(basedir);
742  }
743  }
744 }
745 
747  // fill total event plots
748  event_.fill(data.total, ls);
749  event_ex_.fill(data.event, ls);
750  overhead_.fill(data.overhead, ls);
751 
752  // fill highltight plots
753  for (unsigned int group : boost::irange(0ul, highlight_.size()))
754  highlight_[group].fill_fraction(data.total, data.highlight[group], ls);
755 
756  // fill modules plots
757  for (unsigned int id : boost::irange(0ul, modules_.size()))
758  modules_[id].fill(data.modules[id].total, ls);
759 
760  for (unsigned int pid : boost::irange(0ul, processes_.size()))
761  processes_[pid].fill(job.processDescription(pid), data, data.processes[pid], ls);
762 }
763 
765  // fill run transition plots
766  run_.fill(data, 0);
767 }
768 
770  // fill lumisection transition plots
771  lumi_.fill(data, ls);
772 }
773 
775 
777  : // configuration
778  callgraph_(),
779  // job configuration
781  concurrent_runs_(0),
784  print_event_summary_(config.getUntrackedParameter<bool>("printEventSummary")),
785  print_run_summary_(config.getUntrackedParameter<bool>("printRunSummary")),
786  print_job_summary_(config.getUntrackedParameter<bool>("printJobSummary")),
787  // JSON configuration
788  //write_json_per_event_(config.getUntrackedParameter<bool>("writeJSONByEvent")),
789  //write_json_per_ls_(config.getUntrackedParameter<bool>("writeJSONByLumiSection")),
790  //write_json_per_run_(config.getUntrackedParameter<bool>("writeJSONByRun")),
791  write_json_summary_(config.getUntrackedParameter<bool>("writeJSONSummary")),
792  json_filename_(config.getUntrackedParameter<std::string>("jsonFileName")),
793  // DQM configuration
794  enable_dqm_(config.getUntrackedParameter<bool>("enableDQM")),
795  enable_dqm_bymodule_(config.getUntrackedParameter<bool>("enableDQMbyModule")),
796  enable_dqm_bypath_(config.getUntrackedParameter<bool>("enableDQMbyPath")),
797  enable_dqm_byls_(config.getUntrackedParameter<bool>("enableDQMbyLumiSection")),
798  enable_dqm_bynproc_(config.getUntrackedParameter<bool>("enableDQMbyProcesses")),
799  enable_dqm_transitions_(config.getUntrackedParameter<bool>("enableDQMTransitions")),
800  dqm_event_ranges_({config.getUntrackedParameter<double>("dqmTimeRange"), // ms
801  config.getUntrackedParameter<double>("dqmTimeResolution"), // ms
802  config.getUntrackedParameter<double>("dqmMemoryRange"), // kB
803  config.getUntrackedParameter<double>("dqmMemoryResolution")}), // kB
804  dqm_path_ranges_({config.getUntrackedParameter<double>("dqmPathTimeRange"), // ms
805  config.getUntrackedParameter<double>("dqmPathTimeResolution"), // ms
806  config.getUntrackedParameter<double>("dqmPathMemoryRange"), // kB
807  config.getUntrackedParameter<double>("dqmPathMemoryResolution")}), // kB
808  dqm_module_ranges_({config.getUntrackedParameter<double>("dqmModuleTimeRange"), // ms
809  config.getUntrackedParameter<double>("dqmModuleTimeResolution"), // ms
810  config.getUntrackedParameter<double>("dqmModuleMemoryRange"), // kB
811  config.getUntrackedParameter<double>("dqmModuleMemoryResolution")}), // kB
812  dqm_lumisections_range_(config.getUntrackedParameter<unsigned int>("dqmLumiSectionsRange")),
813  dqm_path_(config.getUntrackedParameter<std::string>("dqmPath")),
814  // highlight configuration
815  highlight_module_psets_(config.getUntrackedParameter<std::vector<edm::ParameterSet>>("highlightModules")),
816  highlight_modules_(highlight_module_psets_.size()) // filled in postBeginJob()
817 {
818  // start observing when a thread enters or leaves the TBB global thread arena
819  tbb::task_scheduler_observer::observe();
820 
821  // register EDM call backs
822  registry.watchPreallocate(this, &FastTimerService::preallocate);
823  registry.watchPreBeginJob(this, &FastTimerService::preBeginJob);
824  registry.watchPostBeginJob(this, &FastTimerService::postBeginJob);
825  registry.watchPostEndJob(this, &FastTimerService::postEndJob);
826  registry.watchPreGlobalBeginRun(this, &FastTimerService::preGlobalBeginRun);
827  //registry.watchPostGlobalBeginRun( this, & FastTimerService::postGlobalBeginRun );
828  //registry.watchPreGlobalEndRun( this, & FastTimerService::preGlobalEndRun );
829  registry.watchPostGlobalEndRun(this, &FastTimerService::postGlobalEndRun);
830  registry.watchPreStreamBeginRun(this, &FastTimerService::preStreamBeginRun);
831  //registry.watchPostStreamBeginRun( this, & FastTimerService::postStreamBeginRun );
832  //registry.watchPreStreamEndRun( this, & FastTimerService::preStreamEndRun );
833  registry.watchPostStreamEndRun(this, &FastTimerService::postStreamEndRun);
834  registry.watchPreGlobalBeginLumi(this, &FastTimerService::preGlobalBeginLumi);
835  //registry.watchPostGlobalBeginLumi( this, & FastTimerService::postGlobalBeginLumi );
836  //registry.watchPreGlobalEndLumi( this, & FastTimerService::preGlobalEndLumi );
837  registry.watchPostGlobalEndLumi(this, &FastTimerService::postGlobalEndLumi);
838  registry.watchPreStreamBeginLumi(this, &FastTimerService::preStreamBeginLumi);
839  //registry.watchPostStreamBeginLumi( this, & FastTimerService::postStreamBeginLumi );
840  //registry.watchPreStreamEndLumi( this, & FastTimerService::preStreamEndLumi );
841  registry.watchPostStreamEndLumi(this, &FastTimerService::postStreamEndLumi);
842  registry.watchPreEvent(this, &FastTimerService::preEvent);
843  registry.watchPostEvent(this, &FastTimerService::postEvent);
844  registry.watchPrePathEvent(this, &FastTimerService::prePathEvent);
845  registry.watchPostPathEvent(this, &FastTimerService::postPathEvent);
846  registry.watchPreSourceConstruction(this, &FastTimerService::preSourceConstruction);
847  //registry.watchPostSourceConstruction( this, & FastTimerService::postSourceConstruction);
848  registry.watchPreSourceRun(this, &FastTimerService::preSourceRun);
849  registry.watchPostSourceRun(this, &FastTimerService::postSourceRun);
850  registry.watchPreSourceLumi(this, &FastTimerService::preSourceLumi);
851  registry.watchPostSourceLumi(this, &FastTimerService::postSourceLumi);
852  registry.watchPreSourceEvent(this, &FastTimerService::preSourceEvent);
853  registry.watchPostSourceEvent(this, &FastTimerService::postSourceEvent);
854  //registry.watchPreModuleConstruction( this, & FastTimerService::preModuleConstruction);
855  //registry.watchPostModuleConstruction( this, & FastTimerService::postModuleConstruction);
856  //registry.watchPreModuleBeginJob( this, & FastTimerService::preModuleBeginJob );
857  //registry.watchPostModuleBeginJob( this, & FastTimerService::postModuleBeginJob );
858  //registry.watchPreModuleEndJob( this, & FastTimerService::preModuleEndJob );
859  //registry.watchPostModuleEndJob( this, & FastTimerService::postModuleEndJob );
860  //registry.watchPreModuleBeginStream( this, & FastTimerService::preModuleBeginStream );
861  //registry.watchPostModuleBeginStream( this, & FastTimerService::postModuleBeginStream );
862  //registry.watchPreModuleEndStream( this, & FastTimerService::preModuleEndStream );
863  //registry.watchPostModuleEndStream( this, & FastTimerService::postModuleEndStream );
864  registry.watchPreModuleGlobalBeginRun(this, &FastTimerService::preModuleGlobalBeginRun);
865  registry.watchPostModuleGlobalBeginRun(this, &FastTimerService::postModuleGlobalBeginRun);
866  registry.watchPreModuleGlobalEndRun(this, &FastTimerService::preModuleGlobalEndRun);
867  registry.watchPostModuleGlobalEndRun(this, &FastTimerService::postModuleGlobalEndRun);
868  registry.watchPreModuleGlobalBeginLumi(this, &FastTimerService::preModuleGlobalBeginLumi);
869  registry.watchPostModuleGlobalBeginLumi(this, &FastTimerService::postModuleGlobalBeginLumi);
870  registry.watchPreModuleGlobalEndLumi(this, &FastTimerService::preModuleGlobalEndLumi);
871  registry.watchPostModuleGlobalEndLumi(this, &FastTimerService::postModuleGlobalEndLumi);
872  registry.watchPreModuleStreamBeginRun(this, &FastTimerService::preModuleStreamBeginRun);
873  registry.watchPostModuleStreamBeginRun(this, &FastTimerService::postModuleStreamBeginRun);
874  registry.watchPreModuleStreamEndRun(this, &FastTimerService::preModuleStreamEndRun);
875  registry.watchPostModuleStreamEndRun(this, &FastTimerService::postModuleStreamEndRun);
876  registry.watchPreModuleStreamBeginLumi(this, &FastTimerService::preModuleStreamBeginLumi);
877  registry.watchPostModuleStreamBeginLumi(this, &FastTimerService::postModuleStreamBeginLumi);
878  registry.watchPreModuleStreamEndLumi(this, &FastTimerService::preModuleStreamEndLumi);
879  registry.watchPostModuleStreamEndLumi(this, &FastTimerService::postModuleStreamEndLumi);
880  //registry.watchPreModuleEventPrefetching( this, & FastTimerService::preModuleEventPrefetching );
881  //registry.watchPostModuleEventPrefetching( this, & FastTimerService::postModuleEventPrefetching );
882  registry.watchPreModuleEventAcquire(this, &FastTimerService::preModuleEventAcquire);
883  registry.watchPostModuleEventAcquire(this, &FastTimerService::postModuleEventAcquire);
884  registry.watchPreModuleEvent(this, &FastTimerService::preModuleEvent);
885  registry.watchPostModuleEvent(this, &FastTimerService::postModuleEvent);
886  registry.watchPreModuleEventDelayedGet(this, &FastTimerService::preModuleEventDelayedGet);
887  registry.watchPostModuleEventDelayedGet(this, &FastTimerService::postModuleEventDelayedGet);
888  registry.watchPreEventReadFromSource(this, &FastTimerService::preEventReadFromSource);
889  registry.watchPostEventReadFromSource(this, &FastTimerService::postEventReadFromSource);
890  registry.watchPreESModule(this, &FastTimerService::preESModule);
891  registry.watchPostESModule(this, &FastTimerService::postESModule);
892 }
893 
894 void FastTimerService::ignoredSignal(const std::string& signal) const {
895  LogDebug("FastTimerService") << "The FastTimerService received is currently not monitoring the signal \"" << signal
896  << "\".\n";
897 }
898 
900  // warn about each signal only once per job
901  if (unsupported_signals_.insert(signal).second)
902  edm::LogWarning("FastTimerService") << "The FastTimerService received the unsupported signal \"" << signal
903  << "\".\n"
904  << "Please report how to reproduce the issue to cms-hlt@cern.ch .";
905 }
906 
908  ignoredSignal(__func__);
909 
910  // reset the run counters only during the main process being run
911  if (isFirstSubprocess(gc)) {
912  auto index = gc.runIndex();
913  subprocess_global_run_check_[index] = 0;
914  run_transition_[index].reset();
915  run_summary_[index].reset();
916 
917  // book the DQM plots
918  if (enable_dqm_) {
919  // define a callback to book the MonitorElements
920  auto bookTransactionCallback = [&, this](dqm::reco::DQMStore::IBooker& booker, dqm::reco::DQMStore::IGetter&) {
921  auto scope = dqm::reco::DQMStore::IBooker::UseRunScope(booker);
922  // we should really do this, but only DQMStore is allowed to touch it
923  // We could move to postGlobalBeginRun, then the DQMStore has sure set it up.
924  //booker.setRunLumi(gc.luminosityBlockID());
925  booker.setCurrentFolder(dqm_path_);
926  plots_->book(booker,
927  callgraph_,
928  highlight_modules_,
929  dqm_event_ranges_,
930  dqm_path_ranges_,
931  dqm_module_ranges_,
932  dqm_lumisections_range_,
933  enable_dqm_bymodule_,
934  enable_dqm_bypath_,
935  enable_dqm_byls_,
936  enable_dqm_transitions_);
937  };
938 
939  // book MonitorElements for this stream
940  edm::Service<dqm::legacy::DQMStore>()->meBookerGetter(bookTransactionCallback);
941  }
942  }
943 }
944 
945 void FastTimerService::postGlobalBeginRun(edm::GlobalContext const& gc) { ignoredSignal(__func__); }
946 
947 void FastTimerService::preStreamBeginRun(edm::StreamContext const& sc) { ignoredSignal(__func__); }
948 
950  // clean characters that are deemed unsafe for DQM
951  // see the definition of `s_safe` in DQMServices/Core/src/DQMStore.cc
952  static const auto safe_for_dqm = "/ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789-+=_()# "s;
953  for (auto& c : label)
954  if (safe_for_dqm.find(c) == std::string::npos)
955  c = '_';
956 }
957 
959  concurrent_lumis_ = bounds.maxNumberOfConcurrentLuminosityBlocks();
960  concurrent_runs_ = bounds.maxNumberOfConcurrentRuns();
961  concurrent_streams_ = bounds.maxNumberOfStreams();
962  concurrent_threads_ = bounds.maxNumberOfThreads();
963 
964  if (enable_dqm_bynproc_)
965  dqm_path_ += fmt::sprintf(
966  "/Running on %s with %d streams on %d threads", processor_model, concurrent_streams_, concurrent_threads_);
967 
968  // fix the DQM path to avoid invalid characters
969  fixForDQM(dqm_path_);
970 
971  // allocate atomic variables to keep track of the completion of each step, process by process
972  subprocess_event_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_streams_);
973  for (unsigned int i = 0; i < concurrent_streams_; ++i)
974  subprocess_event_check_[i] = 0;
975  subprocess_global_run_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_runs_);
976  for (unsigned int i = 0; i < concurrent_runs_; ++i)
977  subprocess_global_run_check_[i] = 0;
978  subprocess_global_lumi_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_lumis_);
979  for (unsigned int i = 0; i < concurrent_lumis_; ++i)
980  subprocess_global_lumi_check_[i] = 0;
981 
982  // allocate buffers to keep track of the resources spent in the lumi and run transitions
983  lumi_transition_.resize(concurrent_lumis_);
984  run_transition_.resize(concurrent_runs_);
985 }
986 
988  callgraph_.preSourceConstruction(module);
989 }
990 
992  edm::ProcessContext const& context) {
993  callgraph_.preBeginJob(pathsAndConsumes, context);
994 }
995 
997  unsigned int modules = callgraph_.size();
998 
999  // module highlights
1000  for (unsigned int group : boost::irange(0ul, highlight_module_psets_.size())) {
1001  // copy and sort for faster search via std::binary_search
1002  auto labels = highlight_module_psets_[group].getUntrackedParameter<std::vector<std::string>>("modules");
1003  std::sort(labels.begin(), labels.end());
1004 
1005  highlight_modules_[group].label = highlight_module_psets_[group].getUntrackedParameter<std::string>("label");
1006  highlight_modules_[group].modules.reserve(labels.size());
1007  // convert the module labels in module ids
1008  for (unsigned int i = 0; i < modules; ++i) {
1009  auto const& label = callgraph_.module(i).moduleLabel();
1010  if (std::binary_search(labels.begin(), labels.end(), label))
1011  highlight_modules_[group].modules.push_back(i);
1012  }
1013  }
1014  highlight_module_psets_.clear();
1015 
1016  // allocate the resource counters for each stream, process, path and module
1017  ResourcesPerJob temp(callgraph_, highlight_modules_);
1018  streams_.resize(concurrent_streams_, temp);
1019  run_summary_.resize(concurrent_runs_, temp);
1020  job_summary_ = temp;
1021 
1022  // check that the DQMStore service is available
1023  if (enable_dqm_ and not edm::Service<dqm::legacy::DQMStore>().isAvailable()) {
1024  // the DQMStore is not available, disable all DQM plots
1025  enable_dqm_ = false;
1026  edm::LogWarning("FastTimerService") << "The DQMStore is not avalable, the DQM plots will not be generated";
1027  }
1028 
1029  // allocate the structures to hold pointers to the DQM plots
1030  if (enable_dqm_) {
1031  plots_ = std::make_unique<PlotsPerJob>(callgraph_, highlight_modules_);
1032  }
1033 }
1034 
1035 void FastTimerService::postStreamBeginRun(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1036 
1037 void FastTimerService::preStreamEndRun(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1038 
1039 void FastTimerService::postStreamEndRun(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1040 
1042  ignoredSignal(__func__);
1043 
1044  // reset the lumi counters only during the main process being run
1045  if (isFirstSubprocess(gc)) {
1046  auto index = gc.luminosityBlockIndex();
1047  subprocess_global_lumi_check_[index] = 0;
1048  lumi_transition_[index].reset();
1049  }
1050 }
1051 
1052 void FastTimerService::postGlobalBeginLumi(edm::GlobalContext const& gc) { ignoredSignal(__func__); }
1053 
1054 void FastTimerService::preGlobalEndLumi(edm::GlobalContext const& gc) { ignoredSignal(__func__); }
1055 
1057  ignoredSignal(__func__);
1058 
1059  // handle the summaries only after the last subprocess has run
1060  auto index = gc.luminosityBlockIndex();
1061  bool last = isLastSubprocess(subprocess_global_lumi_check_[index]);
1062  if (not last)
1063  return;
1064 
1065  edm::LogVerbatim out("FastReport");
1066  auto const& label =
1067  fmt::sprintf("run %d, lumisection %d", gc.luminosityBlockID().run(), gc.luminosityBlockID().luminosityBlock());
1068  printTransition(out, lumi_transition_[index], label);
1069 
1070  if (enable_dqm_ and enable_dqm_transitions_) {
1071  plots_->fill_lumi(lumi_transition_[index], gc.luminosityBlockID().luminosityBlock());
1072  }
1073 }
1074 
1075 void FastTimerService::preStreamBeginLumi(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1076 
1077 void FastTimerService::postStreamBeginLumi(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1078 
1079 void FastTimerService::preStreamEndLumi(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1080 
1081 void FastTimerService::postStreamEndLumi(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1082 
1083 void FastTimerService::preGlobalEndRun(edm::GlobalContext const& gc) { ignoredSignal(__func__); }
1084 
1086  ignoredSignal(__func__);
1087 
1088  // handle the summaries only after the last subprocess has run
1089  auto index = gc.runIndex();
1090  bool last = isLastSubprocess(subprocess_global_run_check_[index]);
1091  if (not last)
1092  return;
1093 
1094  edm::LogVerbatim out("FastReport");
1095  auto const& label = fmt::sprintf("Run %d", gc.luminosityBlockID().run());
1096  if (print_run_summary_) {
1097  printSummary(out, run_summary_[index], label);
1098  }
1099  printTransition(out, run_transition_[index], label);
1100 
1101  if (enable_dqm_ and enable_dqm_transitions_) {
1102  plots_->fill_run(run_transition_[index]);
1103  }
1104 }
1105 
1106 void FastTimerService::preSourceRun(edm::RunIndex index) { thread().measure_and_accumulate(overhead_); }
1107 
1108 void FastTimerService::postSourceRun(edm::RunIndex index) { thread().measure_and_accumulate(run_transition_[index]); }
1109 
1110 void FastTimerService::preSourceLumi(edm::LuminosityBlockIndex index) { thread().measure_and_accumulate(overhead_); }
1111 
1113  thread().measure_and_accumulate(lumi_transition_[index]);
1114 }
1115 
1117  // stop observing to avoid potential race conditions at exit
1118  tbb::task_scheduler_observer::observe(false);
1119  guard_.finalize();
1120  if (print_job_summary_) {
1121  edm::LogVerbatim out("FastReport");
1122  printSummary(out, job_summary_, "Job");
1123  }
1124  if (write_json_summary_) {
1125  writeSummaryJSON(job_summary_, json_filename_);
1126  }
1127 }
1128 
1129 template <typename T>
1131  out << "FastReport ";
1132  if (label.size() < 60)
1133  for (unsigned int i = (60 - label.size()) / 2; i > 0; --i)
1134  out << '-';
1135  out << ' ' << label << " Summary ";
1136  if (label.size() < 60)
1137  for (unsigned int i = (59 - label.size()) / 2; i > 0; --i)
1138  out << '-';
1139  out << '\n';
1140 }
1141 
1142 template <typename T>
1144  out << "FastReport CPU time Real time Allocated Deallocated " << label << "\n";
1145  // FastReport ########.# ms ########.# ms +######### kB -######### kB ...
1146 }
1147 
1148 template <typename T>
1150  out << fmt::sprintf("FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1151  ms(data.time_thread),
1152  ms(data.time_real),
1153  +static_cast<int64_t>(kB(data.allocated)),
1154  -static_cast<int64_t>(kB(data.deallocated)),
1155  label);
1156 }
1157 
1158 template <typename T>
1160  out << fmt::sprintf("FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1161  ms(boost::chrono::nanoseconds(data.time_thread.load())),
1162  ms(boost::chrono::nanoseconds(data.time_real.load())),
1163  +static_cast<int64_t>(kB(data.allocated)),
1164  -static_cast<int64_t>(kB(data.deallocated)),
1165  label);
1166 }
1167 
1168 template <typename T>
1170  printHeader(out, "Event");
1171  printEventHeader(out, "Modules");
1172  auto const& source_d = callgraph_.source();
1173  auto const& source = data.modules[source_d.id()];
1174  printEventLine(out, source.total, source_d.moduleLabel());
1175  for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) {
1176  auto const& proc_d = callgraph_.processDescription(i);
1177  auto const& proc = data.processes[i];
1178  printEventLine(out, proc.total, "process " + proc_d.name_);
1179  for (unsigned int m : proc_d.modules_) {
1180  auto const& module_d = callgraph_.module(m);
1181  auto const& module = data.modules[m];
1182  printEventLine(out, module.total, " " + module_d.moduleLabel());
1183  }
1184  }
1185  printEventLine(out, data.total, "total");
1186  out << '\n';
1187  printEventHeader(out, "Processes and Paths");
1188  printEventLine(out, source.total, source_d.moduleLabel());
1189  for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) {
1190  auto const& proc_d = callgraph_.processDescription(i);
1191  auto const& proc = data.processes[i];
1192  printEventLine(out, proc.total, "process " + proc_d.name_);
1193  for (unsigned int p = 0; p < proc.paths.size(); ++p) {
1194  auto const& name = proc_d.paths_[p].name_;
1195  auto const& path = proc.paths[p];
1196  printEventLine(out, path.active, name + " (only scheduled modules)");
1197  printEventLine(out, path.total, name + " (including dependencies)");
1198  }
1199  for (unsigned int p = 0; p < proc.endpaths.size(); ++p) {
1200  auto const& name = proc_d.endPaths_[p].name_;
1201  auto const& path = proc.endpaths[p];
1202  printEventLine(out, path.active, name + " (only scheduled modules)");
1203  printEventLine(out, path.total, name + " (including dependencies)");
1204  }
1205  }
1206  printEventLine(out, data.total, "total");
1207  out << '\n';
1208  for (unsigned int group : boost::irange(0ul, highlight_modules_.size())) {
1209  printEventHeader(out, "Highlighted modules");
1210  for (unsigned int m : highlight_modules_[group].modules) {
1211  auto const& module_d = callgraph_.module(m);
1212  auto const& module = data.modules[m];
1213  printEventLine(out, module.total, " " + module_d.moduleLabel());
1214  }
1215  printEventLine(out, data.highlight[group], highlight_modules_[group].label);
1216  out << '\n';
1217  }
1218 }
1219 
1220 template <typename T>
1221 void FastTimerService::printSummaryHeader(T& out, std::string const& label, bool detailed) const {
1222  // clang-format off
1223  if (detailed)
1224  out << "FastReport CPU time avg. when run Real time avg. when run Alloc. avg. when run Dealloc. avg. when run ";
1225  // FastReport ########.# ms ########.# ms ########.# ms ########.# ms +######### kB +######### kB -######### kB -######### kB ...
1226  else
1227  out << "FastReport CPU time avg. Real time avg. Alloc. avg. Dealloc. avg. ";
1228  // FastReport ########.# ms ########.# ms +######### kB -######### kB ...
1229  out << label << '\n';
1230  // clang-format on
1231 }
1232 
1233 template <typename T>
1235  // clang-format off
1236  out << "FastReport CPU time sched. / depend. Real time sched. / depend. Alloc. sched. / depend. Dealloc. sched. / depend. ";
1237  // FastReport ########.# ms ########.# ms ########.# ms ########.# ms +######### kB +######### kB -######### kB -######### kB ...
1238  out << label << '\n';
1239  // clang-format on
1240 }
1241 
1242 template <typename T>
1244  out << fmt::sprintf(
1245  // clang-format off
1246  "FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1247  // clang-format on
1248  (events ? ms(data.time_thread) / events : 0),
1249  (events ? ms(data.time_real) / events : 0),
1250  (events ? +static_cast<int64_t>(kB(data.allocated) / events) : 0),
1251  (events ? -static_cast<int64_t>(kB(data.deallocated) / events) : 0),
1252  label);
1253 }
1254 
1255 template <typename T>
1257  T& out, AtomicResources const& data, uint64_t events, uint64_t active, std::string const& label) const {
1258  out << fmt::sprintf(
1259  // clang-format off
1260  "FastReport %10.1f ms %10.1f ms %10.1f ms %10.1f ms %+10d kB %+10d kB %+10d kB %+10d kB %s\n",
1261  // clang-format on
1262  (events ? ms(data.time_thread) / events : 0),
1263  (active ? ms(data.time_thread) / active : 0),
1264  (events ? ms(data.time_real) / events : 0),
1265  (active ? ms(data.time_real) / active : 0),
1266  (events ? +static_cast<int64_t>(kB(data.allocated) / events) : 0),
1267  (active ? +static_cast<int64_t>(kB(data.allocated) / active) : 0),
1268  (events ? -static_cast<int64_t>(kB(data.deallocated) / events) : 0),
1269  (active ? -static_cast<int64_t>(kB(data.deallocated) / active) : 0),
1270  label);
1271 }
1272 
1273 template <typename T>
1275  AtomicResources const& data,
1276  uint64_t events,
1277  std::string const& label) const {
1278  out << fmt::sprintf(
1279  // clang-format off
1280  "FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1281  // clang-format on
1282  (events ? ms(data.time_thread) / events : 0),
1283  (events ? ms(data.time_real) / events : 0),
1284  (events ? +static_cast<int64_t>(kB(data.allocated) / events) : 0),
1285  (events ? -static_cast<int64_t>(kB(data.deallocated) / events) : 0),
1286  label);
1287 }
1288 
1289 template <typename T>
1291  T& out, Resources const& data, uint64_t events, uint64_t active, std::string const& label) const {
1292  out << fmt::sprintf(
1293  "FastReport %10.1f ms %10.1f ms %10.1f ms %10.1f ms %+10d kB %+10d kB %+10d kB %+10d kB %s\n",
1294  (events ? ms(data.time_thread) / events : 0),
1295  (active ? ms(data.time_thread) / active : 0),
1296  (events ? ms(data.time_real) / events : 0),
1297  (active ? ms(data.time_real) / active : 0),
1298  (events ? +static_cast<int64_t>(kB(data.allocated) / events) : 0),
1299  (active ? +static_cast<int64_t>(kB(data.allocated) / active) : 0),
1300  (events ? -static_cast<int64_t>(kB(data.deallocated) / events) : 0),
1301  (active ? -static_cast<int64_t>(kB(data.deallocated) / active) : 0),
1302  label);
1303 }
1304 
1305 template <typename T>
1307  T& out, Resources const& data, Resources const& total, uint64_t events, std::string const& label) const {
1308  out << fmt::sprintf(
1309  "FastReport %10.1f ms %10.1f ms %10.1f ms %10.1f ms %+10d kB %+10d kB %+10d kB %+10d kB %s\n",
1310  (events ? ms(data.time_thread) / events : 0),
1311  (events ? ms(total.time_thread) / events : 0),
1312  (events ? ms(data.time_real) / events : 0),
1313  (events ? ms(total.time_real) / events : 0),
1314  (events ? +static_cast<int64_t>(kB(data.allocated) / events) : 0),
1315  (events ? +static_cast<int64_t>(kB(total.allocated) / events) : 0),
1316  (events ? -static_cast<int64_t>(kB(data.deallocated) / events) : 0),
1317  (events ? -static_cast<int64_t>(kB(total.deallocated) / events) : 0),
1318  label);
1319 }
1320 
1321 template <typename T>
1323  printHeader(out, label);
1324  printSummaryHeader(out, "Modules", true);
1325  auto const& source_d = callgraph_.source();
1326  auto const& source = data.modules[source_d.id()];
1327  printSummaryLine(out, source.total, data.events, source.events, source_d.moduleLabel());
1328  for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) {
1329  auto const& proc_d = callgraph_.processDescription(i);
1330  auto const& proc = data.processes[i];
1331  printSummaryLine(out, proc.total, data.events, "process " + proc_d.name_);
1332  for (unsigned int m : proc_d.modules_) {
1333  auto const& module_d = callgraph_.module(m);
1334  auto const& module = data.modules[m];
1335  printSummaryLine(out, module.total, data.events, module.events, " " + module_d.moduleLabel());
1336  }
1337  }
1338  printSummaryLine(out, data.total, data.events, "total");
1339  printSummaryLine(out, data.overhead, data.events, "other");
1340  printSummaryLine(out, data.eventsetup, data.events, "eventsetup");
1341  out << '\n';
1342  printPathSummaryHeader(out, "Processes and Paths");
1343  printSummaryLine(out, source.total, data.events, source_d.moduleLabel());
1344  for (unsigned int i = 0; i < callgraph_.processes().size(); ++i) {
1345  auto const& proc_d = callgraph_.processDescription(i);
1346  auto const& proc = data.processes[i];
1347  printSummaryLine(out, proc.total, data.events, "process " + proc_d.name_);
1348  for (unsigned int p = 0; p < proc.paths.size(); ++p) {
1349  auto const& name = proc_d.paths_[p].name_;
1350  auto const& path = proc.paths[p];
1351  printPathSummaryLine(out, path.active, path.total, data.events, " " + name);
1352  }
1353  for (unsigned int p = 0; p < proc.endpaths.size(); ++p) {
1354  auto const& name = proc_d.endPaths_[p].name_;
1355  auto const& path = proc.endpaths[p];
1356  printPathSummaryLine(out, path.active, path.total, data.events, " " + name);
1357  }
1358  }
1359  printSummaryLine(out, data.total, data.events, "total");
1360  printSummaryLine(out, data.overhead, data.events, "other");
1361  printSummaryLine(out, data.eventsetup, data.events, "eventsetup");
1362  out << '\n';
1363  for (unsigned int group : boost::irange(0ul, highlight_modules_.size())) {
1364  printSummaryHeader(out, "Highlighted modules", true);
1365  for (unsigned int m : highlight_modules_[group].modules) {
1366  auto const& module_d = callgraph_.module(m);
1367  auto const& module = data.modules[m];
1368  printSummaryLine(out, module.total, data.events, module.events, module_d.moduleLabel());
1369  }
1370  printSummaryLine(out, data.highlight[group], data.events, highlight_modules_[group].label);
1371  out << '\n';
1372  }
1373 }
1374 
1375 template <typename T>
1377  printEventHeader(out, "Transition");
1378  printEventLine(out, data, label);
1379 }
1380 
1381 template <typename T>
1383  std::string const& label,
1384  unsigned int events,
1385  T const& data) const {
1386  return json{{"type", type},
1387  {"label", label},
1388  {"events", events},
1389  {"time_thread", ms(data.time_thread)},
1390  {"time_real", ms(data.time_real)},
1391  {"mem_alloc", kB(data.allocated)},
1392  {"mem_free", kB(data.deallocated)}};
1393 }
1394 
1396  return encodeToJSON(module.moduleName(), module.moduleLabel(), data.events, data.total);
1397 }
1398 
1400  json j;
1401 
1402  // write a description of the resources
1403  j["resources"] = json::array({json{{"time_real", "real time"}},
1404  json{{"time_thread", "cpu time"}},
1405  json{{"mem_alloc", "allocated memory"}},
1406  json{{"mem_free", "deallocated memory"}}});
1407 
1408  // write the resources used by the job
1409  j["total"] = encodeToJSON(
1410  "Job", callgraph_.processDescription(0).name_, data.events, data.total + data.overhead + data.eventsetup);
1411 
1412  // write the resources used by every module
1413  j["modules"] = json::array();
1414  for (unsigned int i = 0; i < callgraph_.size(); ++i) {
1415  auto const& module = callgraph_.module(i);
1416  auto const& data_m = data.modules[i];
1417  j["modules"].push_back(encodeToJSON(module, data_m));
1418  }
1419 
1420  // add an entry for the "overhead"
1421  j["modules"].push_back(encodeToJSON("other", "other", data.events, data.overhead));
1422  j["modules"].push_back(encodeToJSON("eventsetup", "eventsetup", data.events, data.eventsetup));
1423 
1424  std::ofstream out(filename);
1425  out << std::setw(2) << j << std::flush;
1426 }
1427 
1428 // check if this is the first process being signalled
1430  return (not sc.processContext()->isSubProcess());
1431 }
1432 
1434  return (not gc.processContext()->isSubProcess());
1435 }
1436 
1437 // check if this is the last process being signalled
1438 bool FastTimerService::isLastSubprocess(std::atomic<unsigned int>& check) {
1439  // release-acquire semantic guarantees that all writes in this and other threads are visible
1440  // after this operation; full sequentially-consistent ordering is (probably) not needed.
1441  unsigned int old_value = check.fetch_add(1, std::memory_order_acq_rel);
1442  return (old_value == callgraph_.processes().size() - 1);
1443 }
1444 
1445 void FastTimerService::preEvent(edm::StreamContext const& sc) { ignoredSignal(__func__); }
1446 
1448  ignoredSignal(__func__);
1449 
1450  unsigned int pid = callgraph_.processId(*sc.processContext());
1451  unsigned int sid = sc.streamID();
1452  auto& stream = streams_[sid];
1453  auto& process = callgraph_.processDescription(pid);
1454 
1455  // measure the event resources as the sum of all modules' resources
1456  auto& data = stream.processes[pid].total;
1457  for (unsigned int id : process.modules_)
1458  data += stream.modules[id].total;
1459  stream.total += data;
1460 
1461  // handle the summaries and fill the plots only after the last subprocess has run
1462  bool last = isLastSubprocess(subprocess_event_check_[sid]);
1463  if (not last)
1464  return;
1465 
1466  // measure the event resources explicitly
1467  stream.event_measurement.measure_and_store(stream.event);
1468 
1469  // add to the event resources those used by source (which is not part of any process)
1470  unsigned int id = 0;
1471  stream.total += stream.modules[id].total;
1472 
1473  // highlighted modules
1474  for (unsigned int group : boost::irange(0ul, highlight_modules_.size()))
1475  for (unsigned int i : highlight_modules_[group].modules)
1476  stream.highlight[group] += stream.modules[i].total;
1477 
1478  // avoid concurrent access to the summary objects
1479  {
1480  std::lock_guard<std::mutex> guard(summary_mutex_);
1481  job_summary_ += stream;
1482  run_summary_[sc.runIndex()] += stream;
1483  }
1484 
1485  if (print_event_summary_) {
1486  edm::LogVerbatim out("FastReport");
1487  printEvent(out, stream);
1488  }
1489 
1490  if (enable_dqm_) {
1491  plots_->fill(callgraph_, stream, sc.eventID().luminosityBlock());
1492  }
1493 }
1494 
1496  // clear the event counters
1497  auto& stream = streams_[sid];
1498  stream.reset();
1499  ++stream.events;
1500 
1501  subprocess_event_check_[sid] = 0;
1502 
1503  // reuse the same measurement for the Source module and for the explicit begin of the Event
1504  auto& measurement = thread();
1505  measurement.measure_and_accumulate(stream.overhead);
1506  stream.event_measurement = measurement;
1507 }
1508 
1510  edm::ModuleDescription const& md = callgraph_.source();
1511  unsigned int id = md.id();
1512  auto& stream = streams_[sid];
1513  auto& module = stream.modules[id];
1514 
1515  thread().measure_and_store(module.total);
1516  ++stream.modules[id].events;
1517 }
1518 
1520  unsigned int sid = sc.streamID().value();
1521  unsigned int pid = callgraph_.processId(*sc.processContext());
1522  unsigned int id = pc.pathID();
1523  auto& stream = streams_[sid];
1524  auto& data = pc.isEndPath() ? stream.processes[pid].endpaths[id] : stream.processes[pid].paths[id];
1525  data.status = false;
1526  data.last = 0;
1527 }
1528 
1530  edm::PathContext const& pc,
1531  edm::HLTPathStatus const& status) {
1532  unsigned int sid = sc.streamID().value();
1533  unsigned int pid = callgraph_.processId(*sc.processContext());
1534  unsigned int id = pc.pathID();
1535  auto& stream = streams_[sid];
1536  auto& data = pc.isEndPath() ? stream.processes[pid].endpaths[id] : stream.processes[pid].paths[id];
1537 
1538  auto const& path =
1539  pc.isEndPath() ? callgraph_.processDescription(pid).endPaths_[id] : callgraph_.processDescription(pid).paths_[id];
1540  unsigned int index = path.modules_on_path_.empty() ? 0 : status.index() + 1;
1541  data.last = path.modules_on_path_.empty() ? 0 : path.last_dependency_of_module_[status.index()];
1542 
1543  for (unsigned int i = 0; i < index; ++i) {
1544  auto const& module = stream.modules[path.modules_on_path_[i]];
1545  data.active += module.total;
1546  }
1547  for (unsigned int i = 0; i < data.last; ++i) {
1548  auto const& module = stream.modules[path.modules_and_dependencies_[i]];
1549  data.total += module.total;
1550  }
1551 }
1552 
1554  unsigned int sid = sc.streamID().value();
1555  auto& stream = streams_[sid];
1556  thread().measure_and_accumulate(stream.overhead);
1557 }
1558 
1560  edm::ModuleDescription const& md = *mcc.moduleDescription();
1561  unsigned int id = md.id();
1562  unsigned int sid = sc.streamID().value();
1563  auto& stream = streams_[sid];
1564  auto& module = stream.modules[id];
1565 
1566  module.has_acquire = true;
1567  thread().measure_and_store(module.total);
1568 }
1569 
1571  unsigned int sid = sc.streamID().value();
1572  auto& stream = streams_[sid];
1573  thread().measure_and_accumulate(stream.overhead);
1574 }
1575 
1577  edm::ModuleDescription const& md = *mcc.moduleDescription();
1578  unsigned int id = md.id();
1579  unsigned int sid = sc.streamID().value();
1580  auto& stream = streams_[sid];
1581  auto& module = stream.modules[id];
1582 
1583  if (module.has_acquire) {
1584  thread().measure_and_accumulate(module.total);
1585  } else {
1586  thread().measure_and_store(module.total);
1587  }
1588  ++module.events;
1589 }
1590 
1592  unsupportedSignal(__func__);
1593 }
1594 
1596  unsupportedSignal(__func__);
1597 }
1598 
1600  ignoredSignal(__func__);
1601 }
1602 
1604  ignoredSignal(__func__);
1605 }
1606 
1609  auto& stream = streams_[sc.streamID()];
1610  thread().measure_and_accumulate(stream.overhead);
1611  }
1612 }
1613 
1616  edm::ModuleDescription const& md = callgraph_.source();
1617  unsigned int id = md.id();
1618  auto& stream = streams_[sc.streamID()];
1619  auto& module = stream.modules[id];
1620 
1621  thread().measure_and_accumulate(module.total);
1622  }
1623 }
1624 
1626  thread().measure_and_accumulate(overhead_);
1627 }
1628 
1630  auto index = gc.runIndex();
1631  thread().measure_and_accumulate(run_transition_[index]);
1632 }
1633 
1635  thread().measure_and_accumulate(overhead_);
1636 }
1637 
1639  auto index = gc.runIndex();
1640  thread().measure_and_accumulate(run_transition_[index]);
1641 }
1642 
1644  thread().measure_and_accumulate(overhead_);
1645 }
1646 
1648  auto index = gc.luminosityBlockIndex();
1649  thread().measure_and_accumulate(lumi_transition_[index]);
1650 }
1651 
1653  thread().measure_and_accumulate(overhead_);
1654 }
1655 
1657  auto index = gc.luminosityBlockIndex();
1658  thread().measure_and_accumulate(lumi_transition_[index]);
1659 }
1660 
1662  thread().measure_and_accumulate(overhead_);
1663 }
1664 
1666  auto index = sc.runIndex();
1667  thread().measure_and_accumulate(run_transition_[index]);
1668 }
1669 
1671  thread().measure_and_accumulate(overhead_);
1672 }
1673 
1675  auto index = sc.runIndex();
1676  thread().measure_and_accumulate(run_transition_[index]);
1677 }
1678 
1680  thread().measure_and_accumulate(overhead_);
1681 }
1682 
1684  auto index = sc.luminosityBlockIndex();
1685  thread().measure_and_accumulate(lumi_transition_[index]);
1686 }
1687 
1689  thread().measure_and_accumulate(overhead_);
1690 }
1691 
1693  auto index = sc.luminosityBlockIndex();
1694  thread().measure_and_accumulate(lumi_transition_[index]);
1695 }
1696 
1698  auto top = cc.getTopModuleCallingContext();
1699  if (top->type() == edm::ParentContext::Type::kPlaceInPath) {
1700  //Paths are only used when processing an Event
1701  unsigned int sid = top->parent().placeInPathContext()->pathContext()->streamContext()->streamID().value();
1702  auto& stream = streams_[sid];
1703  thread().measure_and_accumulate(stream.overhead);
1704  }
1705 }
1708  auto top = cc.getTopModuleCallingContext();
1709  if (top->type() == edm::ParentContext::Type::kPlaceInPath) {
1710  unsigned int sid = top->parent().placeInPathContext()->pathContext()->streamContext()->streamID().value();
1711  auto& stream = streams_[sid];
1712  thread().measure_and_accumulate(stream.eventsetup);
1713  }
1714 }
1715 
1717  auto err = ::pthread_key_create(&key_, retire_thread);
1718  if (err) {
1719  throw cms::Exception("FastTimerService") << "ThreadGuard key creation failed: " << ::strerror(err);
1720  }
1721 }
1722 
1723 // If this is a new thread, register it and return true
1725  auto ptr = ::pthread_getspecific(key_);
1726 
1727  if (not ptr) {
1728  auto p = thread_resources_.emplace_back(std::make_shared<specific_t>(r));
1729  auto pp = new std::shared_ptr<specific_t>(*p);
1730  auto err = ::pthread_setspecific(key_, pp);
1731  if (err) {
1732  throw cms::Exception("FastTimerService") << "ThreadGuard pthread_setspecific failed: " << ::strerror(err);
1733  }
1734  return true;
1735  }
1736  return false;
1737 }
1738 
1739 std::shared_ptr<FastTimerService::ThreadGuard::specific_t>* FastTimerService::ThreadGuard::ptr(void* p) {
1740  return static_cast<std::shared_ptr<specific_t>*>(p);
1741 }
1742 
1743 // called when a thread exits
1745  auto ps = ptr(p);
1746  auto expected = true;
1747  if ((*ps)->live_.compare_exchange_strong(expected, false)) {
1748  // account any resources used or freed by the thread before leaving the TBB pool
1749  (*ps)->measurement_.measure_and_accumulate((*ps)->resource_);
1750  }
1751  delete ps;
1752 }
1753 
1754 // finalize all threads that have not retired
1756  for (auto& p : thread_resources_) {
1757  auto expected = true;
1758  if (p->live_.compare_exchange_strong(expected, false)) {
1759  p->measurement_.measure_and_accumulate(p->resource_);
1760  }
1761  }
1762 }
1763 
1765  return (*ptr(::pthread_getspecific(key_)))->measurement_;
1766 }
1767 
1770  // initialise the measurement point for a thread that has newly joined the TBB pool
1771  thread().measure();
1772  }
1773 }
1774 
1776 
1778 
1779 // describe the module's configuration
1782  desc.addUntracked<bool>("printEventSummary", false);
1783  desc.addUntracked<bool>("printRunSummary", true);
1784  desc.addUntracked<bool>("printJobSummary", true);
1785  // JSON configuration
1786  //desc.addUntracked<bool>("writeJSONByEvent", false);
1787  //desc.addUntracked<bool>("writeJSONByLumiSection", false);
1788  //desc.addUntracked<bool>("writeJSONByRun", false);
1789  desc.addUntracked<bool>("writeJSONSummary", false);
1790  desc.addUntracked<std::string>("jsonFileName", "resources.json");
1791  // DQM configuration
1792  desc.addUntracked<bool>("enableDQM", true);
1793  desc.addUntracked<bool>("enableDQMbyModule", false);
1794  desc.addUntracked<bool>("enableDQMbyPath", false);
1795  desc.addUntracked<bool>("enableDQMbyLumiSection", false);
1796  desc.addUntracked<bool>("enableDQMbyProcesses", false);
1797  desc.addUntracked<bool>("enableDQMTransitions", false);
1798  desc.addUntracked<double>("dqmTimeRange", 1000.); // ms
1799  desc.addUntracked<double>("dqmTimeResolution", 5.); // ms
1800  desc.addUntracked<double>("dqmMemoryRange", 1000000.); // kB
1801  desc.addUntracked<double>("dqmMemoryResolution", 5000.); // kB
1802  desc.addUntracked<double>("dqmPathTimeRange", 100.); // ms
1803  desc.addUntracked<double>("dqmPathTimeResolution", 0.5); // ms
1804  desc.addUntracked<double>("dqmPathMemoryRange", 1000000.); // kB
1805  desc.addUntracked<double>("dqmPathMemoryResolution", 5000.); // kB
1806  desc.addUntracked<double>("dqmModuleTimeRange", 40.); // ms
1807  desc.addUntracked<double>("dqmModuleTimeResolution", 0.2); // ms
1808  desc.addUntracked<double>("dqmModuleMemoryRange", 100000.); // kB
1809  desc.addUntracked<double>("dqmModuleMemoryResolution", 500.); // kB
1810  desc.addUntracked<unsigned>("dqmLumiSectionsRange", 2500); // ~ 16 hours
1811  desc.addUntracked<std::string>("dqmPath", "HLT/TimerService");
1812 
1813  edm::ParameterSetDescription highlightModulesDescription;
1814  highlightModulesDescription.addUntracked<std::vector<std::string>>("modules", {});
1815  highlightModulesDescription.addUntracked<std::string>("label", "producers");
1816  desc.addVPSetUntracked("highlightModules", highlightModulesDescription, {});
1817 
1818  // # OBSOLETE - these parameters are ignored, they are left only not to break old configurations
1819  // they will not be printed in the generated cfi.py file
1820  desc.addOptionalNode(edm::ParameterDescription<bool>("useRealTimeClock", true, false), false)
1821  ->setComment("This parameter is obsolete and will be ignored.");
1822  desc.addOptionalNode(edm::ParameterDescription<bool>("enableTimingPaths", true, false), false)
1823  ->setComment("This parameter is obsolete and will be ignored.");
1824  desc.addOptionalNode(edm::ParameterDescription<bool>("enableTimingModules", true, false), false)
1825  ->setComment("This parameter is obsolete and will be ignored.");
1826  desc.addOptionalNode(edm::ParameterDescription<bool>("enableTimingExclusive", false, false), false)
1827  ->setComment("This parameter is obsolete and will be ignored.");
1828  desc.addOptionalNode(edm::ParameterDescription<bool>("enableTimingSummary", false, false), false)
1829  ->setComment("This parameter is obsolete and will be ignored.");
1830  desc.addOptionalNode(edm::ParameterDescription<bool>("skipFirstPath", false, false), false)
1831  ->setComment("This parameter is obsolete and will be ignored.");
1832  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathActive", false, false), false)
1833  ->setComment("This parameter is obsolete and will be ignored.");
1834  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathTotal", true, false), false)
1835  ->setComment("This parameter is obsolete and will be ignored.");
1836  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathOverhead", false, false), false)
1837  ->setComment("This parameter is obsolete and will be ignored.");
1838  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathDetails", false, false), false)
1839  ->setComment("This parameter is obsolete and will be ignored.");
1840  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathCounters", true, false), false)
1841  ->setComment("This parameter is obsolete and will be ignored.");
1842  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyPathExclusive", false, false), false)
1843  ->setComment("This parameter is obsolete and will be ignored.");
1844  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMbyModuleType", false, false), false)
1845  ->setComment("This parameter is obsolete and will be ignored.");
1846  desc.addOptionalNode(edm::ParameterDescription<bool>("enableDQMSummary", false, false), false)
1847  ->setComment("This parameter is obsolete and will be ignored.");
1848 
1849  descriptions.add("FastTimerService", desc);
1850 }
1851 
1852 // declare FastTimerService as a framework Service
size
Write out results.
void preGlobalBeginRun(edm::GlobalContext const &)
void preModuleEventDelayedGet(edm::StreamContext const &, edm::ModuleCallingContext const &)
const bool print_run_summary_
constexpr int32_t ceil(float num)
void fill(Resources const &, unsigned int lumisection)
ResourcesPerProcess operator+(ResourcesPerProcess const &other) const
void postStreamBeginRun(edm::StreamContext const &)
ModuleDescription const * moduleDescription() const
void postGlobalEndLumi(edm::GlobalContext const &)
LuminosityBlockNumber_t luminosityBlock() const
void postGlobalBeginLumi(edm::GlobalContext const &)
void on_scheduler_entry(bool worker) final
void postStreamEndLumi(edm::StreamContext const &)
void on_scheduler_exit(bool worker) final
void postModuleGlobalEndLumi(edm::GlobalContext const &, edm::ModuleCallingContext const &)
void preEventReadFromSource(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preGlobalEndRun(edm::GlobalContext const &)
void preBeginJob(edm::PathsAndConsumesOfModulesBase const &, edm::ProcessContext const &)
void fill_lumi(AtomicResources const &, unsigned int lumisection)
void preSourceLumi(edm::LuminosityBlockIndex)
void printSummary(T &out, ResourcesPerJob const &data, std::string const &label) const
boost::date_time::subsecond_duration< boost::posix_time::time_duration, 1000000000 > nanoseconds
ResourcesPerJob operator+(ResourcesPerJob const &other) const
unsigned int concurrent_threads_
void postEventReadFromSource(edm::StreamContext const &, edm::ModuleCallingContext const &)
ParameterDescriptionBase * addUntracked(U const &iLabel, T const &value)
Definition: CLHEP.h:16
const PlotRanges dqm_event_ranges_
void postModuleGlobalEndRun(edm::GlobalContext const &, edm::ModuleCallingContext const &)
void preSourceRun(edm::RunIndex)
void postModuleEvent(edm::StreamContext const &, edm::ModuleCallingContext const &)
void unsupportedSignal(const std::string &signal) const
void writeSummaryJSON(ResourcesPerJob const &data, std::string const &filename) const
virtual void setCurrentFolder(std::string const &fullpath)
Definition: DQMStore.cc:36
const bool write_json_summary_
void book(dqm::reco::DQMStore::IBooker &, ProcessCallGraph const &, ProcessCallGraph::ProcessType const &, PlotRanges const &event_ranges, PlotRanges const &path_ranges, unsigned int lumisections, bool bypath, bool byls)
PlotsPerJob(ProcessCallGraph const &job, std::vector< GroupOfModules > const &groups)
nlohmann::json json
PlotsPerProcess(ProcessCallGraph::ProcessType const &)
void preGlobalEndLumi(edm::GlobalContext const &)
uint32_t cc[maxCellsPerHit]
Definition: gpuFishbone.h:49
edm::ModuleDescription const & source() const
virtual std::string pwd()
Definition: DQMStore.cc:20
AtomicResources overhead_
void preESModule(edm::eventsetup::EventSetupRecordKey const &, edm::ESModuleCallingContext const &)
const std::string json_filename_
bool isFirstSubprocess(edm::StreamContext const &)
const bool enable_dqm_bynproc_
void postESModule(edm::eventsetup::EventSetupRecordKey const &, edm::ESModuleCallingContext const &)
unsigned int concurrent_runs_
void postSourceRun(edm::RunIndex)
Definition: config.py:1
void postPathEvent(edm::StreamContext const &, edm::PathContext const &, edm::HLTPathStatus const &)
void preModuleGlobalBeginLumi(edm::GlobalContext const &, edm::ModuleCallingContext const &)
uint32_t T const *__restrict__ uint32_t const *__restrict__ int32_t int Histo::index_type cudaStream_t stream
ResourcesPerProcess & operator+=(ResourcesPerProcess const &other)
void book(dqm::reco::DQMStore::IBooker &, std::string const &, ProcessCallGraph const &, ProcessCallGraph::PathType const &, PlotRanges const &ranges, unsigned int lumisections, bool byls)
assert(be >=bs)
const bool print_job_summary_
const bool enable_dqm_bypath_
void book(dqm::reco::DQMStore::IBooker &, ProcessCallGraph const &, std::vector< GroupOfModules > const &, PlotRanges const &event_ranges, PlotRanges const &path_ranges, PlotRanges const &module_ranges, unsigned int lumisections, bool bymodule, bool bypath, bool byls, bool transitions)
AtomicResources operator+(AtomicResources const &other) const
Measurement & thread()
LuminosityBlockNumber_t luminosityBlock() const
Definition: EventID.h:39
void printSummary(const std::map< unsigned int, SiStripDetSummary::Values > &map)
edm::ModuleDescription const & module(unsigned int module) const
void postStreamBeginLumi(edm::StreamContext const &)
char const * label
void postModuleStreamEndLumi(edm::StreamContext const &, edm::ModuleCallingContext const &)
std::vector< ProcessType > const & processes() const
MonitorElement * book1DD(TString const &name, TString const &title, int nchX, double lowX, double highX, FUNC onbooking=NOOP())
Definition: DQMStore.h:155
ResourcesPerJob & operator+=(ResourcesPerJob const &other)
virtual void setXTitle(std::string const &title)
unsigned int id() const
void fill(ProcessCallGraph::ProcessType const &, ResourcesPerJob const &, ResourcesPerProcess const &, unsigned int ls)
ResourcesPerModule operator+(ResourcesPerModule const &other) const
void printEvent(T &out, ResourcesPerJob const &) const
void prePathEvent(edm::StreamContext const &, edm::PathContext const &)
MonitorElement * bookProfile(TString const &name, TString const &title, int nchX, double lowX, double highX, int, double lowY, double highY, char const *option="s", FUNC onbooking=NOOP())
Definition: DQMStore.h:399
const std::string processor_model
The Signals That Services Can Subscribe To This is based on ActivityRegistry and is current per Services can connect to the signals distributed by the ActivityRegistry in order to monitor the activity of the application Each possible callback has some defined which we here list in angle e< void, edm::EventID const &, edm::Timestamp const & > We also list in braces which AR_WATCH_USING_METHOD_ is used for those or
Definition: Activities.doc:12
static void fillDescriptions(edm::ConfigurationDescriptions &descriptions)
FastTimerService(const edm::ParameterSet &, edm::ActivityRegistry &)
void preModuleStreamEndLumi(edm::StreamContext const &, edm::ModuleCallingContext const &)
StreamID const & streamID() const
Definition: StreamContext.h:55
void postEvent(edm::StreamContext const &)
void postGlobalEndRun(edm::GlobalContext const &)
static uint64_t deallocated()
Definition: memory_usage.cc:88
void fill_fraction(Resources const &, Resources const &, unsigned int lumisection)
const double infinity
void postStreamEndRun(edm::StreamContext const &)
void preModuleEvent(edm::StreamContext const &, edm::ModuleCallingContext const &)
ResourcesPerPath & operator+=(ResourcesPerPath const &other)
Resources operator+(Resources const &other) const
unsigned int concurrent_lumis_
void printSummaryLine(T &out, Resources const &data, uint64_t events, std::string const &label) const
bool register_thread(FastTimerService::AtomicResources &r)
void printPathSummaryLine(T &out, Resources const &data, Resources const &total, uint64_t events, std::string const &label) const
json encodeToJSON(std::string const &type, std::string const &label, unsigned int events, T const &data) const
ProcessContext const * processContext() const
Definition: StreamContext.h:64
const bool enable_dqm_transitions_
LuminosityBlockIndex const & luminosityBlockIndex() const
Definition: GlobalContext.h:64
void printSummaryHeader(T &out, std::string const &label, bool detailed) const
ProcessContext const * processContext() const
Definition: GlobalContext.h:66
void ignoredSignal(const std::string &signal) const
LuminosityBlockID const & luminosityBlockID() const
Definition: GlobalContext.h:62
void measure_and_store(Resources &store) noexcept
RunNumber_t run() const
const bool enable_dqm_bymodule_
string ranges
Definition: diffTwoXMLs.py:79
unsigned int pathID() const
Definition: PathContext.h:32
void book(dqm::reco::DQMStore::IBooker &, std::string const &name, std::string const &title, PlotRanges const &ranges, unsigned int lumisections, bool byls)
void fill_run(AtomicResources const &)
#define DEFINE_FWK_SERVICE(type)
Definition: ServiceMaker.h:97
static bool is_available()
Definition: memory_usage.cc:84
const bool enable_dqm_byls_
def ls(path, rec=False)
Definition: eostools.py:349
std::vector< PlotsPerProcess > processes_
void postModuleEventAcquire(edm::StreamContext const &, edm::ModuleCallingContext const &)
void postModuleEventDelayedGet(edm::StreamContext const &, edm::ModuleCallingContext const &)
const bool print_event_summary_
virtual void setYTitle(std::string const &title)
LuminosityBlockIndex const & luminosityBlockIndex() const
Definition: StreamContext.h:62
static std::shared_ptr< specific_t > * ptr(void *p)
unsigned long long uint64_t
Definition: Time.h:13
void postModuleStreamBeginLumi(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preModuleStreamEndRun(edm::StreamContext const &, edm::ModuleCallingContext const &)
void postModuleStreamEndRun(edm::StreamContext const &, edm::ModuleCallingContext const &)
part
Definition: HCALResponse.h:20
def load(fileName)
Definition: svgfig.py:547
void printEventHeader(T &out, std::string const &label) const
static uint64_t allocated()
Definition: memory_usage.cc:86
void postModuleStreamBeginRun(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preSourceEvent(edm::StreamID)
static void retire_thread(void *t)
void add(std::string const &label, ParameterSetDescription const &psetDescription)
void preEvent(edm::StreamContext const &)
void postGlobalBeginRun(edm::GlobalContext const &)
void printEventLine(T &out, Resources const &data, std::string const &label) const
void preStreamBeginLumi(edm::StreamContext const &)
ResourcesPerProcess(ProcessCallGraph::ProcessType const &process)
void postSourceEvent(edm::StreamID)
void preModuleStreamBeginLumi(edm::StreamContext const &, edm::ModuleCallingContext const &)
void printPathSummaryHeader(T &out, std::string const &label) const
bool isSubProcess() const
void preStreamEndRun(edm::StreamContext const &)
RunIndex const & runIndex() const
Definition: GlobalContext.h:63
char data[epos_bytes_allocation]
Definition: EPOS_Wrapper.h:79
void preModuleStreamBeginRun(edm::StreamContext const &, edm::ModuleCallingContext const &)
void printHeader(T &out, std::string const &label) const
void preStreamEndLumi(edm::StreamContext const &)
void measure_and_accumulate(Resources &store) noexcept
ResourcesPerModule & operator+=(ResourcesPerModule const &other)
EventID const & eventID() const
Definition: StreamContext.h:60
void postModuleEventPrefetching(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preModuleGlobalEndLumi(edm::GlobalContext const &, edm::ModuleCallingContext const &)
ResourcesPerPath operator+(ResourcesPerPath const &other) const
void preGlobalBeginLumi(edm::GlobalContext const &)
AtomicResources & operator+=(AtomicResources const &other)
Resources & operator+=(Resources const &other)
void preModuleEventPrefetching(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preSourceConstruction(edm::ModuleDescription const &)
void preModuleEventAcquire(edm::StreamContext const &, edm::ModuleCallingContext const &)
void preModuleGlobalEndRun(edm::GlobalContext const &, edm::ModuleCallingContext const &)
ProcessType const & processDescription(unsigned int) const
void printTransition(T &out, AtomicResources const &data, std::string const &label) const
void postSourceLumi(edm::LuminosityBlockIndex)
void postModuleGlobalBeginRun(edm::GlobalContext const &, edm::ModuleCallingContext const &)
unsigned int value() const
Definition: StreamID.h:43
std::vector< ResourcesPerProcess > processes
Log< level::Warning, false > LogWarning
MonitorElement * book1D(TString const &name, TString const &title, int const nchX, double const lowX, double const highX, FUNC onbooking=NOOP())
Definition: DQMStore.h:98
UseScope< MonitorElementData::Scope::RUN > UseRunScope
Definition: DQMStore.h:541
AtomicResources & operator=(AtomicResources const &other)
bool isEndPath() const
Definition: PathContext.h:35
ProcessCallGraph callgraph_
long double T
void postModuleGlobalBeginLumi(edm::GlobalContext const &, edm::ModuleCallingContext const &)
std::string const & moduleLabel() const
void preStreamBeginRun(edm::StreamContext const &)
void preModuleGlobalBeginRun(edm::GlobalContext const &, edm::ModuleCallingContext const &)
RunIndex const & runIndex() const
Definition: StreamContext.h:61
static std::string const source
Definition: EdmProvDump.cc:49
int events
static void fixForDQM(std::string &label)
unsigned int concurrent_streams_
bool isLastSubprocess(std::atomic< unsigned int > &check)
Definition: event.py:1
void preallocate(edm::service::SystemBounds const &)
void fill(ProcessCallGraph const &, ResourcesPerJob const &, unsigned int ls)
#define LogDebug(id)
void fill(ProcessCallGraph::PathType const &, ResourcesPerJob const &, ResourcesPerPath const &, unsigned int lumisection)