Back to home page

Project CMSSW displayed by LXR

 
 

    


File indexing completed on 2023-03-17 11:09:50

0001 // C++ headers
0002 #include <cmath>
0003 #include <fstream>
0004 #include <iomanip>
0005 #include <iostream>
0006 #include <limits>
0007 #include <mutex>
0008 #include <sstream>
0009 #include <string>
0010 #include <unordered_map>
0011 #include <unordered_set>
0012 
0013 // boost headers
0014 #include <boost/range/irange.hpp>
0015 
0016 // {fmt} headers
0017 #include <fmt/printf.h>
0018 
0019 // JSON headers
0020 #include <nlohmann/json.hpp>
0021 using json = nlohmann::json;
0022 
0023 // CMSSW headers
0024 #include "DQMServices/Core/interface/DQMStore.h"
0025 #include "DataFormats/Common/interface/HLTPathStatus.h"
0026 #include "DataFormats/Provenance/interface/EventID.h"
0027 #include "DataFormats/Provenance/interface/ModuleDescription.h"
0028 #include "DataFormats/Provenance/interface/Timestamp.h"
0029 #include "DataFormats/Scalers/interface/LumiScalers.h"
0030 #include "FWCore/Framework/interface/Event.h"
0031 #include "FWCore/Framework/interface/LuminosityBlock.h"
0032 #include "FWCore/Framework/interface/TriggerNamesService.h"
0033 #include "FWCore/ServiceRegistry/interface/PlaceInPathContext.h"
0034 #include "FWCore/MessageLogger/interface/MessageLogger.h"
0035 #include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h"
0036 #include "FWCore/ParameterSet/interface/ParameterSet.h"
0037 #include "FWCore/ParameterSet/interface/ParameterSetDescription.h"
0038 #include "FWCore/Utilities/interface/Exception.h"
0039 #include "FWCore/Utilities/interface/StreamID.h"
0040 #include "HLTrigger/Timer/interface/memory_usage.h"
0041 #include "HLTrigger/Timer/interface/processor_model.h"
0042 #include "FastTimerService.h"
0043 
0044 using namespace std::literals;
0045 
0046 ///////////////////////////////////////////////////////////////////////////////
0047 
0048 namespace {
0049 
0050   // convert any std::chrono::duration to milliseconds
0051   template <class Rep, class Period>
0052   double ms(std::chrono::duration<Rep, Period> duration) {
0053     return std::chrono::duration_cast<std::chrono::duration<double, std::milli>>(duration).count();
0054   }
0055 
0056   // convert any boost::chrono::duration to milliseconds
0057   template <class Rep, class Period>
0058   double ms(boost::chrono::duration<Rep, Period> duration) {
0059     return boost::chrono::duration_cast<boost::chrono::duration<double, boost::milli>>(duration).count();
0060   }
0061 
0062   // convert a std::atomic<boost::chrono::nanoseconds::rep> to milliseconds
0063   double ms(std::atomic<boost::chrono::nanoseconds::rep> const& duration) {
0064     return boost::chrono::duration_cast<boost::chrono::duration<double, boost::milli>>(
0065                boost::chrono::nanoseconds(duration.load()))
0066         .count();
0067   }
0068 
0069   // convert from bytes to kilobytes, rounding down
0070   uint64_t kB(uint64_t bytes) { return bytes / 1024; }
0071 
0072   // convert from bytes to kilobytes, rounding down
0073   uint64_t kB(std::atomic<uint64_t> const& bytes) { return bytes.load() / 1024; }
0074 
0075 }  // namespace
0076 
0077 ///////////////////////////////////////////////////////////////////////////////
0078 
0079 // resources being monitored by the service
0080 
0081 // Resources
0082 
0083 FastTimerService::Resources::Resources()
0084     : time_thread(boost::chrono::nanoseconds::zero()),
0085       time_real(boost::chrono::nanoseconds::zero()),
0086       allocated(0ul),
0087       deallocated(0ul) {}
0088 
0089 void FastTimerService::Resources::reset() {
0090   time_thread = boost::chrono::nanoseconds::zero();
0091   time_real = boost::chrono::nanoseconds::zero();
0092   allocated = 0ul;
0093   deallocated = 0ul;
0094 }
0095 
0096 FastTimerService::Resources& FastTimerService::Resources::operator+=(Resources const& other) {
0097   time_thread += other.time_thread;
0098   time_real += other.time_real;
0099   allocated += other.allocated;
0100   deallocated += other.deallocated;
0101   return *this;
0102 }
0103 
0104 FastTimerService::Resources& FastTimerService::Resources::operator+=(AtomicResources const& other) {
0105   time_thread += boost::chrono::nanoseconds(other.time_thread.load());
0106   time_real += boost::chrono::nanoseconds(other.time_real.load());
0107   allocated += other.allocated.load();
0108   deallocated += other.deallocated.load();
0109   return *this;
0110 }
0111 
0112 FastTimerService::Resources FastTimerService::Resources::operator+(Resources const& other) const {
0113   Resources result(*this);
0114   result += other;
0115   return result;
0116 }
0117 
0118 FastTimerService::Resources FastTimerService::Resources::operator+(AtomicResources const& other) const {
0119   Resources result(*this);
0120   result += other;
0121   return result;
0122 }
0123 
0124 // AtomicResources
0125 // operation on the whole object are not atomic, as the operations
0126 // on the individual fields could be interleaved; however, accumulation
0127 // of results should yield the correct result.
0128 
0129 FastTimerService::AtomicResources::AtomicResources()
0130     : time_thread(0ul), time_real(0ul), allocated(0ul), deallocated(0ul) {}
0131 
0132 FastTimerService::AtomicResources::AtomicResources(AtomicResources const& other)
0133     : time_thread(other.time_thread.load()),
0134       time_real(other.time_real.load()),
0135       allocated(other.allocated.load()),
0136       deallocated(other.deallocated.load()) {}
0137 
0138 void FastTimerService::AtomicResources::reset() {
0139   time_thread = 0ul;
0140   time_real = 0ul;
0141   allocated = 0ul;
0142   deallocated = 0ul;
0143 }
0144 
0145 FastTimerService::AtomicResources& FastTimerService::AtomicResources::operator=(AtomicResources const& other) {
0146   time_thread = other.time_thread.load();
0147   time_real = other.time_real.load();
0148   allocated = other.allocated.load();
0149   deallocated = other.deallocated.load();
0150   return *this;
0151 }
0152 
0153 FastTimerService::AtomicResources& FastTimerService::AtomicResources::operator+=(AtomicResources const& other) {
0154   time_thread += other.time_thread.load();
0155   time_real += other.time_real.load();
0156   allocated += other.allocated.load();
0157   deallocated += other.deallocated.load();
0158   return *this;
0159 }
0160 
0161 FastTimerService::AtomicResources& FastTimerService::AtomicResources::operator+=(Resources const& other) {
0162   time_thread += other.time_thread.count();
0163   time_real += other.time_real.count();
0164   allocated += other.allocated;
0165   deallocated += other.deallocated;
0166   return *this;
0167 }
0168 
0169 FastTimerService::AtomicResources FastTimerService::AtomicResources::operator+(AtomicResources const& other) const {
0170   AtomicResources result(*this);
0171   result += other;
0172   return result;
0173 }
0174 
0175 FastTimerService::Resources FastTimerService::AtomicResources::operator+(Resources const& other) const {
0176   return other + *this;
0177 }
0178 
0179 // ResourcesPerModule
0180 
0181 FastTimerService::ResourcesPerModule::ResourcesPerModule() noexcept : total(), events(0), has_acquire(false) {}
0182 
0183 void FastTimerService::ResourcesPerModule::reset() noexcept {
0184   total.reset();
0185   events = 0;
0186   has_acquire = false;
0187 }
0188 
0189 FastTimerService::ResourcesPerModule& FastTimerService::ResourcesPerModule::operator+=(ResourcesPerModule const& other) {
0190   total += other.total;
0191   events += other.events;
0192   has_acquire = has_acquire or other.has_acquire;
0193   return *this;
0194 }
0195 
0196 FastTimerService::ResourcesPerModule FastTimerService::ResourcesPerModule::operator+(
0197     ResourcesPerModule const& other) const {
0198   ResourcesPerModule result(*this);
0199   result += other;
0200   return result;
0201 }
0202 
0203 // ResourcesPerPath
0204 
0205 void FastTimerService::ResourcesPerPath::reset() {
0206   active.reset();
0207   total.reset();
0208   last = 0;
0209   status = false;
0210 }
0211 
0212 FastTimerService::ResourcesPerPath& FastTimerService::ResourcesPerPath::operator+=(ResourcesPerPath const& other) {
0213   active += other.active;
0214   total += other.total;
0215   last = 0;  // summing these makes no sense, reset them instead
0216   status = false;
0217   return *this;
0218 }
0219 
0220 FastTimerService::ResourcesPerPath FastTimerService::ResourcesPerPath::operator+(ResourcesPerPath const& other) const {
0221   ResourcesPerPath result(*this);
0222   result += other;
0223   return result;
0224 }
0225 
0226 // ResourcesPerProcess
0227 
0228 FastTimerService::ResourcesPerProcess::ResourcesPerProcess(ProcessCallGraph::ProcessType const& process)
0229     : total(), paths(process.paths_.size()), endpaths(process.endPaths_.size()) {}
0230 
0231 void FastTimerService::ResourcesPerProcess::reset() {
0232   total.reset();
0233   for (auto& path : paths)
0234     path.reset();
0235   for (auto& path : endpaths)
0236     path.reset();
0237 }
0238 
0239 FastTimerService::ResourcesPerProcess& FastTimerService::ResourcesPerProcess::operator+=(
0240     ResourcesPerProcess const& other) {
0241   total += other.total;
0242   assert(paths.size() == other.paths.size());
0243   for (unsigned int i : boost::irange(0ul, paths.size()))
0244     paths[i] += other.paths[i];
0245   assert(endpaths.size() == other.endpaths.size());
0246   for (unsigned int i : boost::irange(0ul, endpaths.size()))
0247     endpaths[i] += other.endpaths[i];
0248   return *this;
0249 }
0250 
0251 FastTimerService::ResourcesPerProcess FastTimerService::ResourcesPerProcess::operator+(
0252     ResourcesPerProcess const& other) const {
0253   ResourcesPerProcess result(*this);
0254   result += other;
0255   return result;
0256 }
0257 
0258 // ResourcesPerJob
0259 
0260 FastTimerService::ResourcesPerJob::ResourcesPerJob(ProcessCallGraph const& job,
0261                                                    std::vector<GroupOfModules> const& groups)
0262     : total(), overhead(), eventsetup(), event(), highlight(groups.size()), modules(job.size()), processes(), events(0) {
0263   processes.reserve(job.processes().size());
0264   for (auto const& process : job.processes())
0265     processes.emplace_back(process);
0266 }
0267 
0268 void FastTimerService::ResourcesPerJob::reset() {
0269   total.reset();
0270   overhead.reset();
0271   eventsetup.reset();
0272   event.reset();
0273   for (auto& module : highlight)
0274     module.reset();
0275   for (auto& module : modules)
0276     module.reset();
0277   for (auto& process : processes)
0278     process.reset();
0279   events = 0;
0280 }
0281 
0282 FastTimerService::ResourcesPerJob& FastTimerService::ResourcesPerJob::operator+=(ResourcesPerJob const& other) {
0283   total += other.total;
0284   overhead += other.overhead;
0285   eventsetup += other.eventsetup;
0286   event += other.event;
0287   assert(highlight.size() == other.highlight.size());
0288   for (unsigned int i : boost::irange(0ul, highlight.size()))
0289     highlight[i] += other.highlight[i];
0290   assert(modules.size() == other.modules.size());
0291   for (unsigned int i : boost::irange(0ul, modules.size()))
0292     modules[i] += other.modules[i];
0293   assert(processes.size() == other.processes.size());
0294   for (unsigned int i : boost::irange(0ul, processes.size()))
0295     processes[i] += other.processes[i];
0296   events += other.events;
0297   return *this;
0298 }
0299 
0300 FastTimerService::ResourcesPerJob FastTimerService::ResourcesPerJob::operator+(ResourcesPerJob const& other) const {
0301   ResourcesPerJob result(*this);
0302   result += other;
0303   return result;
0304 }
0305 
0306 // per-thread measurements
0307 
0308 // Measurement
0309 
0310 FastTimerService::Measurement::Measurement() noexcept { measure(); }
0311 
0312 void FastTimerService::Measurement::measure() noexcept {
0313 #ifdef DEBUG_THREAD_CONCURRENCY
0314   id = std::this_thread::get_id();
0315 #endif  // DEBUG_THREAD_CONCURRENCY
0316   time_thread = boost::chrono::thread_clock::now();
0317   time_real = boost::chrono::high_resolution_clock::now();
0318   allocated = memory_usage::allocated();
0319   deallocated = memory_usage::deallocated();
0320 }
0321 
0322 void FastTimerService::Measurement::measure_and_store(Resources& store) noexcept {
0323 #ifdef DEBUG_THREAD_CONCURRENCY
0324   assert(std::this_thread::get_id() == id);
0325 #endif  // DEBUG_THREAD_CONCURRENCY
0326   auto new_time_thread = boost::chrono::thread_clock::now();
0327   auto new_time_real = boost::chrono::high_resolution_clock::now();
0328   auto new_allocated = memory_usage::allocated();
0329   auto new_deallocated = memory_usage::deallocated();
0330   store.time_thread = new_time_thread - time_thread;
0331   store.time_real = new_time_real - time_real;
0332   store.allocated = new_allocated - allocated;
0333   store.deallocated = new_deallocated - deallocated;
0334   time_thread = new_time_thread;
0335   time_real = new_time_real;
0336   allocated = new_allocated;
0337   deallocated = new_deallocated;
0338 }
0339 
0340 void FastTimerService::Measurement::measure_and_accumulate(Resources& store) noexcept {
0341 #ifdef DEBUG_THREAD_CONCURRENCY
0342   assert(std::this_thread::get_id() == id);
0343 #endif  // DEBUG_THREAD_CONCURRENCY
0344   auto new_time_thread = boost::chrono::thread_clock::now();
0345   auto new_time_real = boost::chrono::high_resolution_clock::now();
0346   auto new_allocated = memory_usage::allocated();
0347   auto new_deallocated = memory_usage::deallocated();
0348   store.time_thread += new_time_thread - time_thread;
0349   store.time_real += new_time_real - time_real;
0350   store.allocated += new_allocated - allocated;
0351   store.deallocated += new_deallocated - deallocated;
0352   time_thread = new_time_thread;
0353   time_real = new_time_real;
0354   allocated = new_allocated;
0355   deallocated = new_deallocated;
0356 }
0357 
0358 void FastTimerService::Measurement::measure_and_accumulate(AtomicResources& store) noexcept {
0359 #ifdef DEBUG_THREAD_CONCURRENCY
0360   assert(std::this_thread::get_id() == id);
0361 #endif  // DEBUG_THREAD_CONCURRENCY
0362   auto new_time_thread = boost::chrono::thread_clock::now();
0363   auto new_time_real = boost::chrono::high_resolution_clock::now();
0364   auto new_allocated = memory_usage::allocated();
0365   auto new_deallocated = memory_usage::deallocated();
0366   store.time_thread += boost::chrono::duration_cast<boost::chrono::nanoseconds>(new_time_thread - time_thread).count();
0367   store.time_real += boost::chrono::duration_cast<boost::chrono::nanoseconds>(new_time_real - time_real).count();
0368   store.allocated += new_allocated - allocated;
0369   store.deallocated += new_deallocated - deallocated;
0370   time_thread = new_time_thread;
0371   time_real = new_time_real;
0372   allocated = new_allocated;
0373   deallocated = new_deallocated;
0374 }
0375 
0376 ///////////////////////////////////////////////////////////////////////////////
0377 
0378 void FastTimerService::PlotsPerElement::book(dqm::reco::DQMStore::IBooker& booker,
0379                                              std::string const& name,
0380                                              std::string const& title,
0381                                              PlotRanges const& ranges,
0382                                              unsigned int lumisections,
0383                                              bool byls) {
0384   int time_bins = (int)std::ceil(ranges.time_range / ranges.time_resolution);
0385   int mem_bins = (int)std::ceil(ranges.memory_range / ranges.memory_resolution);
0386   std::string y_title_ms = fmt::sprintf("events / %.1f ms", ranges.time_resolution);
0387   std::string y_title_kB = fmt::sprintf("events / %.1f kB", ranges.memory_resolution);
0388 
0389   // MonitorElement::setStatOverflows(kTRUE) includes underflows and overflows in the computation of mean and RMS
0390   time_thread_ =
0391       booker.book1D(name + " time_thread", title + " processing time (cpu)", time_bins, 0., ranges.time_range);
0392   time_thread_->setXTitle("processing time [ms]");
0393   time_thread_->setYTitle(y_title_ms);
0394   time_thread_->setStatOverflows(kTRUE);
0395 
0396   time_real_ = booker.book1D(name + " time_real", title + " processing time (real)", time_bins, 0., ranges.time_range);
0397   time_real_->setXTitle("processing time [ms]");
0398   time_real_->setYTitle(y_title_ms);
0399   time_real_->setStatOverflows(kTRUE);
0400 
0401   if (memory_usage::is_available()) {
0402     allocated_ = booker.book1D(name + " allocated", title + " allocated memory", mem_bins, 0., ranges.memory_range);
0403     allocated_->setXTitle("memory [kB]");
0404     allocated_->setYTitle(y_title_kB);
0405     allocated_->setStatOverflows(kTRUE);
0406 
0407     deallocated_ =
0408         booker.book1D(name + " deallocated", title + " deallocated memory", mem_bins, 0., ranges.memory_range);
0409     deallocated_->setXTitle("memory [kB]");
0410     deallocated_->setYTitle(y_title_kB);
0411     deallocated_->setStatOverflows(kTRUE);
0412   }
0413 
0414   if (not byls)
0415     return;
0416 
0417   time_thread_byls_ = booker.bookProfile(name + " time_thread_byls",
0418                                          title + " processing time (cpu) vs. lumisection",
0419                                          lumisections,
0420                                          0.5,
0421                                          lumisections + 0.5,
0422                                          time_bins,
0423                                          0.,
0424                                          std::numeric_limits<double>::infinity(),
0425                                          " ");
0426   time_thread_byls_->setXTitle("lumisection");
0427   time_thread_byls_->setYTitle("processing time [ms]");
0428   time_thread_byls_->setStatOverflows(kTRUE);
0429 
0430   time_real_byls_ = booker.bookProfile(name + " time_real_byls",
0431                                        title + " processing time (real) vs. lumisection",
0432                                        lumisections,
0433                                        0.5,
0434                                        lumisections + 0.5,
0435                                        time_bins,
0436                                        0.,
0437                                        std::numeric_limits<double>::infinity(),
0438                                        " ");
0439   time_real_byls_->setXTitle("lumisection");
0440   time_real_byls_->setYTitle("processing time [ms]");
0441   time_real_byls_->setStatOverflows(kTRUE);
0442 
0443   if (memory_usage::is_available()) {
0444     allocated_byls_ = booker.bookProfile(name + " allocated_byls",
0445                                          title + " allocated memory vs. lumisection",
0446                                          lumisections,
0447                                          0.5,
0448                                          lumisections + 0.5,
0449                                          mem_bins,
0450                                          0.,
0451                                          std::numeric_limits<double>::infinity(),
0452                                          " ");
0453     allocated_byls_->setXTitle("lumisection");
0454     allocated_byls_->setYTitle("memory [kB]");
0455     allocated_byls_->setStatOverflows(kTRUE);
0456 
0457     deallocated_byls_ = booker.bookProfile(name + " deallocated_byls",
0458                                            title + " deallocated memory vs. lumisection",
0459                                            lumisections,
0460                                            0.5,
0461                                            lumisections + 0.5,
0462                                            mem_bins,
0463                                            0.,
0464                                            std::numeric_limits<double>::infinity(),
0465                                            " ");
0466     deallocated_byls_->setXTitle("lumisection");
0467     deallocated_byls_->setYTitle("memory [kB]");
0468     deallocated_byls_->setStatOverflows(kTRUE);
0469   }
0470 }
0471 
0472 void FastTimerService::PlotsPerElement::fill(Resources const& data, unsigned int lumisection) {
0473   if (time_thread_)
0474     time_thread_->Fill(ms(data.time_thread));
0475 
0476   if (time_thread_byls_)
0477     time_thread_byls_->Fill(lumisection, ms(data.time_thread));
0478 
0479   if (time_real_)
0480     time_real_->Fill(ms(data.time_real));
0481 
0482   if (time_real_byls_)
0483     time_real_byls_->Fill(lumisection, ms(data.time_real));
0484 
0485   if (allocated_)
0486     allocated_->Fill(kB(data.allocated));
0487 
0488   if (allocated_byls_)
0489     allocated_byls_->Fill(lumisection, kB(data.allocated));
0490 
0491   if (deallocated_)
0492     deallocated_->Fill(kB(data.deallocated));
0493 
0494   if (deallocated_byls_)
0495     deallocated_byls_->Fill(lumisection, kB(data.deallocated));
0496 }
0497 
0498 void FastTimerService::PlotsPerElement::fill(AtomicResources const& data, unsigned int lumisection) {
0499   if (time_thread_)
0500     time_thread_->Fill(ms(boost::chrono::nanoseconds(data.time_thread.load())));
0501 
0502   if (time_thread_byls_)
0503     time_thread_byls_->Fill(lumisection, ms(boost::chrono::nanoseconds(data.time_thread.load())));
0504 
0505   if (time_real_)
0506     time_real_->Fill(ms(boost::chrono::nanoseconds(data.time_real.load())));
0507 
0508   if (time_real_byls_)
0509     time_real_byls_->Fill(lumisection, ms(boost::chrono::nanoseconds(data.time_real.load())));
0510 
0511   if (allocated_)
0512     allocated_->Fill(kB(data.allocated));
0513 
0514   if (allocated_byls_)
0515     allocated_byls_->Fill(lumisection, kB(data.allocated));
0516 
0517   if (deallocated_)
0518     deallocated_->Fill(kB(data.deallocated));
0519 
0520   if (deallocated_byls_)
0521     deallocated_byls_->Fill(lumisection, kB(data.deallocated));
0522 }
0523 
0524 void FastTimerService::PlotsPerElement::fill_fraction(Resources const& data,
0525                                                       Resources const& part,
0526                                                       unsigned int lumisection) {
0527   float total;
0528   float fraction;
0529 
0530   total = ms(data.time_thread);
0531   fraction = (total > 0.) ? (ms(part.time_thread) / total) : 0.;
0532   if (time_thread_)
0533     time_thread_->Fill(total, fraction);
0534 
0535   if (time_thread_byls_)
0536     time_thread_byls_->Fill(lumisection, total, fraction);
0537 
0538   total = ms(data.time_real);
0539   fraction = (total > 0.) ? (ms(part.time_real) / total) : 0.;
0540   if (time_real_)
0541     time_real_->Fill(total, fraction);
0542 
0543   if (time_real_byls_)
0544     time_real_byls_->Fill(lumisection, total, fraction);
0545 
0546   total = kB(data.allocated);
0547   fraction = (total > 0.) ? (kB(part.allocated) / total) : 0.;
0548   if (allocated_)
0549     allocated_->Fill(total, fraction);
0550 
0551   if (allocated_byls_)
0552     allocated_byls_->Fill(lumisection, total, fraction);
0553 
0554   total = kB(data.deallocated);
0555   fraction = (total > 0.) ? (kB(part.deallocated) / total) : 0.;
0556   if (deallocated_)
0557     deallocated_->Fill(total, fraction);
0558 
0559   if (deallocated_byls_)
0560     deallocated_byls_->Fill(lumisection, total, fraction);
0561 }
0562 
0563 void FastTimerService::PlotsPerPath::book(dqm::reco::DQMStore::IBooker& booker,
0564                                           std::string const& prefixDir,
0565                                           ProcessCallGraph const& job,
0566                                           ProcessCallGraph::PathType const& path,
0567                                           PlotRanges const& ranges,
0568                                           unsigned int lumisections,
0569                                           bool byls) {
0570   const std::string basedir = booker.pwd();
0571   std::string folderName = basedir + "/" + prefixDir + path.name_;
0572   fixForDQM(folderName);
0573   booker.setCurrentFolder(folderName);
0574 
0575   total_.book(booker, "path", path.name_, ranges, lumisections, byls);
0576 
0577   // MonitorElement::setStatOverflows(kTRUE) includes underflows and overflows in the computation of mean and RMS
0578   unsigned int bins = path.modules_and_dependencies_.size();
0579   module_counter_ = booker.book1DD("module_counter", "module counter", bins + 1, -0.5, bins + 0.5);
0580   module_counter_->setYTitle("events");
0581   module_counter_->setStatOverflows(kTRUE);
0582   module_time_thread_total_ =
0583       booker.book1DD("module_time_thread_total", "total module time (cpu)", bins, -0.5, bins - 0.5);
0584   module_time_thread_total_->setYTitle("processing time [ms]");
0585   module_time_thread_total_->setStatOverflows(kTRUE);
0586   module_time_real_total_ =
0587       booker.book1DD("module_time_real_total", "total module time (real)", bins, -0.5, bins - 0.5);
0588   module_time_real_total_->setYTitle("processing time [ms]");
0589   module_time_real_total_->setStatOverflows(kTRUE);
0590   if (memory_usage::is_available()) {
0591     module_allocated_total_ =
0592         booker.book1DD("module_allocated_total", "total allocated memory", bins, -0.5, bins - 0.5);
0593     module_allocated_total_->setYTitle("memory [kB]");
0594     module_allocated_total_->setStatOverflows(kTRUE);
0595     module_deallocated_total_ =
0596         booker.book1DD("module_deallocated_total", "total deallocated memory", bins, -0.5, bins - 0.5);
0597     module_deallocated_total_->setYTitle("memory [kB]");
0598     module_deallocated_total_->setStatOverflows(kTRUE);
0599   }
0600   for (unsigned int bin : boost::irange(0u, bins)) {
0601     auto const& module = job[path.modules_and_dependencies_[bin]];
0602     std::string const& label =
0603         module.scheduled_ ? module.module_.moduleLabel() : module.module_.moduleLabel() + " (unscheduled)";
0604     module_counter_->setBinLabel(bin + 1, label);
0605     module_time_thread_total_->setBinLabel(bin + 1, label);
0606     module_time_real_total_->setBinLabel(bin + 1, label);
0607     if (memory_usage::is_available()) {
0608       module_allocated_total_->setBinLabel(bin + 1, label);
0609       module_deallocated_total_->setBinLabel(bin + 1, label);
0610     }
0611   }
0612   module_counter_->setBinLabel(bins + 1, "");
0613 
0614   booker.setCurrentFolder(basedir);
0615 }
0616 
0617 void FastTimerService::PlotsPerPath::fill(ProcessCallGraph::PathType const& description,
0618                                           ResourcesPerJob const& data,
0619                                           ResourcesPerPath const& path,
0620                                           unsigned int ls) {
0621   // fill the total path time
0622   total_.fill(path.total, ls);
0623 
0624   // fill the modules that actually ran and the total time spent in each od them
0625   for (unsigned int i = 0; i < path.last; ++i) {
0626     auto const& module = data.modules[description.modules_and_dependencies_[i]];
0627     if (module_counter_)
0628       module_counter_->Fill(i);
0629 
0630     if (module_time_thread_total_)
0631       module_time_thread_total_->Fill(i, ms(module.total.time_thread));
0632 
0633     if (module_time_real_total_)
0634       module_time_real_total_->Fill(i, ms(module.total.time_real));
0635 
0636     if (module_allocated_total_)
0637       module_allocated_total_->Fill(i, kB(module.total.allocated));
0638 
0639     if (module_deallocated_total_)
0640       module_deallocated_total_->Fill(i, kB(module.total.deallocated));
0641   }
0642   if (module_counter_ and path.status)
0643     module_counter_->Fill(path.last);
0644 }
0645 
0646 FastTimerService::PlotsPerProcess::PlotsPerProcess(ProcessCallGraph::ProcessType const& process)
0647     : event_(), paths_(process.paths_.size()), endpaths_(process.endPaths_.size()) {}
0648 
0649 void FastTimerService::PlotsPerProcess::book(dqm::reco::DQMStore::IBooker& booker,
0650                                              ProcessCallGraph const& job,
0651                                              ProcessCallGraph::ProcessType const& process,
0652                                              PlotRanges const& event_ranges,
0653                                              PlotRanges const& path_ranges,
0654                                              unsigned int lumisections,
0655                                              bool bypath,
0656                                              bool byls) {
0657   const std::string basedir = booker.pwd();
0658   event_.book(booker, "process " + process.name_, "process " + process.name_, event_ranges, lumisections, byls);
0659   if (bypath) {
0660     booker.setCurrentFolder(basedir + "/process " + process.name_ + " paths");
0661     for (unsigned int id : boost::irange(0ul, paths_.size())) {
0662       paths_[id].book(booker, "path ", job, process.paths_[id], path_ranges, lumisections, byls);
0663     }
0664     for (unsigned int id : boost::irange(0ul, endpaths_.size())) {
0665       endpaths_[id].book(booker, "endpath ", job, process.endPaths_[id], path_ranges, lumisections, byls);
0666     }
0667     booker.setCurrentFolder(basedir);
0668   }
0669 }
0670 
0671 void FastTimerService::PlotsPerProcess::fill(ProcessCallGraph::ProcessType const& description,
0672                                              ResourcesPerJob const& data,
0673                                              ResourcesPerProcess const& process,
0674                                              unsigned int ls) {
0675   // fill process event plots
0676   event_.fill(process.total, ls);
0677 
0678   // fill all paths plots
0679   for (unsigned int id : boost::irange(0ul, paths_.size()))
0680     paths_[id].fill(description.paths_[id], data, process.paths[id], ls);
0681 
0682   // fill all endpaths plots
0683   for (unsigned int id : boost::irange(0ul, endpaths_.size()))
0684     endpaths_[id].fill(description.endPaths_[id], data, process.endpaths[id], ls);
0685 }
0686 
0687 FastTimerService::PlotsPerJob::PlotsPerJob(ProcessCallGraph const& job, std::vector<GroupOfModules> const& groups)
0688     : event_(), event_ex_(), overhead_(), highlight_(groups.size()), modules_(job.size()), processes_() {
0689   processes_.reserve(job.processes().size());
0690   for (auto const& process : job.processes())
0691     processes_.emplace_back(process);
0692 }
0693 
0694 void FastTimerService::PlotsPerJob::book(dqm::reco::DQMStore::IBooker& booker,
0695                                          ProcessCallGraph const& job,
0696                                          std::vector<GroupOfModules> const& groups,
0697                                          PlotRanges const& event_ranges,
0698                                          PlotRanges const& path_ranges,
0699                                          PlotRanges const& module_ranges,
0700                                          unsigned int lumisections,
0701                                          bool bymodule,
0702                                          bool bypath,
0703                                          bool byls,
0704                                          bool transitions) {
0705   const std::string basedir = booker.pwd();
0706 
0707   // event summary plots
0708   event_.book(booker, "event", "Event", event_ranges, lumisections, byls);
0709 
0710   event_ex_.book(booker, "explicit", "Event (explicit)", event_ranges, lumisections, byls);
0711 
0712   overhead_.book(booker, "overhead", "Overhead", event_ranges, lumisections, byls);
0713 
0714   modules_[job.source().id()].book(booker, "source", "Source", module_ranges, lumisections, byls);
0715 
0716   if (transitions) {
0717     lumi_.book(booker, "lumi", "LumiSection transitions", event_ranges, lumisections, byls);
0718 
0719     run_.book(booker, "run", "Run transtions", event_ranges, lumisections, false);
0720   }
0721 
0722   // plot the time spent in few given groups of modules
0723   for (unsigned int group : boost::irange(0ul, groups.size())) {
0724     auto const& label = groups[group].label;
0725     highlight_[group].book(booker, "highlight " + label, "Highlight " + label, event_ranges, lumisections, byls);
0726   }
0727 
0728   // plots per subprocess (event, modules, paths and endpaths)
0729   for (unsigned int pid : boost::irange(0ul, job.processes().size())) {
0730     auto const& process = job.processDescription(pid);
0731     processes_[pid].book(booker, job, process, event_ranges, path_ranges, lumisections, bypath, byls);
0732 
0733     if (bymodule) {
0734       booker.setCurrentFolder(basedir + "/process " + process.name_ + " modules");
0735       for (unsigned int id : process.modules_) {
0736         std::string const& module_label = job.module(id).moduleLabel();
0737         std::string safe_label = module_label;
0738         fixForDQM(safe_label);
0739         modules_[id].book(booker, safe_label, module_label, module_ranges, lumisections, byls);
0740       }
0741       booker.setCurrentFolder(basedir);
0742     }
0743   }
0744 }
0745 
0746 void FastTimerService::PlotsPerJob::fill(ProcessCallGraph const& job, ResourcesPerJob const& data, unsigned int ls) {
0747   // fill total event plots
0748   event_.fill(data.total, ls);
0749   event_ex_.fill(data.event, ls);
0750   overhead_.fill(data.overhead, ls);
0751 
0752   // fill highltight plots
0753   for (unsigned int group : boost::irange(0ul, highlight_.size()))
0754     highlight_[group].fill_fraction(data.total, data.highlight[group], ls);
0755 
0756   // fill modules plots
0757   for (unsigned int id : boost::irange(0ul, modules_.size()))
0758     modules_[id].fill(data.modules[id].total, ls);
0759 
0760   for (unsigned int pid : boost::irange(0ul, processes_.size()))
0761     processes_[pid].fill(job.processDescription(pid), data, data.processes[pid], ls);
0762 }
0763 
0764 void FastTimerService::PlotsPerJob::fill_run(AtomicResources const& data) {
0765   // fill run transition plots
0766   run_.fill(data, 0);
0767 }
0768 
0769 void FastTimerService::PlotsPerJob::fill_lumi(AtomicResources const& data, unsigned int ls) {
0770   // fill lumisection transition plots
0771   lumi_.fill(data, ls);
0772 }
0773 
0774 ///////////////////////////////////////////////////////////////////////////////
0775 
0776 FastTimerService::FastTimerService(const edm::ParameterSet& config, edm::ActivityRegistry& registry)
0777     :  // configuration
0778       callgraph_(),
0779       // job configuration
0780       concurrent_lumis_(0),
0781       concurrent_runs_(0),
0782       concurrent_streams_(0),
0783       concurrent_threads_(0),
0784       print_event_summary_(config.getUntrackedParameter<bool>("printEventSummary")),
0785       print_run_summary_(config.getUntrackedParameter<bool>("printRunSummary")),
0786       print_job_summary_(config.getUntrackedParameter<bool>("printJobSummary")),
0787       // JSON configuration
0788       //write_json_per_event_(config.getUntrackedParameter<bool>("writeJSONByEvent")),
0789       //write_json_per_ls_(config.getUntrackedParameter<bool>("writeJSONByLumiSection")),
0790       //write_json_per_run_(config.getUntrackedParameter<bool>("writeJSONByRun")),
0791       write_json_summary_(config.getUntrackedParameter<bool>("writeJSONSummary")),
0792       json_filename_(config.getUntrackedParameter<std::string>("jsonFileName")),
0793       // DQM configuration
0794       enable_dqm_(config.getUntrackedParameter<bool>("enableDQM")),
0795       enable_dqm_bymodule_(config.getUntrackedParameter<bool>("enableDQMbyModule")),
0796       enable_dqm_bypath_(config.getUntrackedParameter<bool>("enableDQMbyPath")),
0797       enable_dqm_byls_(config.getUntrackedParameter<bool>("enableDQMbyLumiSection")),
0798       enable_dqm_bynproc_(config.getUntrackedParameter<bool>("enableDQMbyProcesses")),
0799       enable_dqm_transitions_(config.getUntrackedParameter<bool>("enableDQMTransitions")),
0800       dqm_event_ranges_({config.getUntrackedParameter<double>("dqmTimeRange"),                  // ms
0801                          config.getUntrackedParameter<double>("dqmTimeResolution"),             // ms
0802                          config.getUntrackedParameter<double>("dqmMemoryRange"),                // kB
0803                          config.getUntrackedParameter<double>("dqmMemoryResolution")}),         // kB
0804       dqm_path_ranges_({config.getUntrackedParameter<double>("dqmPathTimeRange"),               // ms
0805                         config.getUntrackedParameter<double>("dqmPathTimeResolution"),          // ms
0806                         config.getUntrackedParameter<double>("dqmPathMemoryRange"),             // kB
0807                         config.getUntrackedParameter<double>("dqmPathMemoryResolution")}),      // kB
0808       dqm_module_ranges_({config.getUntrackedParameter<double>("dqmModuleTimeRange"),           // ms
0809                           config.getUntrackedParameter<double>("dqmModuleTimeResolution"),      // ms
0810                           config.getUntrackedParameter<double>("dqmModuleMemoryRange"),         // kB
0811                           config.getUntrackedParameter<double>("dqmModuleMemoryResolution")}),  // kB
0812       dqm_lumisections_range_(config.getUntrackedParameter<unsigned int>("dqmLumiSectionsRange")),
0813       dqm_path_(config.getUntrackedParameter<std::string>("dqmPath")),
0814       // highlight configuration
0815       highlight_module_psets_(config.getUntrackedParameter<std::vector<edm::ParameterSet>>("highlightModules")),
0816       highlight_modules_(highlight_module_psets_.size())  // filled in postBeginJob()
0817 {
0818   // start observing when a thread enters or leaves the TBB global thread arena
0819   tbb::task_scheduler_observer::observe();
0820 
0821   // register EDM call backs
0822   registry.watchPreallocate(this, &FastTimerService::preallocate);
0823   registry.watchPreBeginJob(this, &FastTimerService::preBeginJob);
0824   registry.watchPostBeginJob(this, &FastTimerService::postBeginJob);
0825   registry.watchPostEndJob(this, &FastTimerService::postEndJob);
0826   registry.watchPreGlobalBeginRun(this, &FastTimerService::preGlobalBeginRun);
0827   //registry.watchPostGlobalBeginRun(         this, & FastTimerService::postGlobalBeginRun );
0828   //registry.watchPreGlobalEndRun(            this, & FastTimerService::preGlobalEndRun );
0829   registry.watchPostGlobalEndRun(this, &FastTimerService::postGlobalEndRun);
0830   registry.watchPreStreamBeginRun(this, &FastTimerService::preStreamBeginRun);
0831   //registry.watchPostStreamBeginRun(         this, & FastTimerService::postStreamBeginRun );
0832   //registry.watchPreStreamEndRun(            this, & FastTimerService::preStreamEndRun );
0833   registry.watchPostStreamEndRun(this, &FastTimerService::postStreamEndRun);
0834   registry.watchPreGlobalBeginLumi(this, &FastTimerService::preGlobalBeginLumi);
0835   //registry.watchPostGlobalBeginLumi(        this, & FastTimerService::postGlobalBeginLumi );
0836   //registry.watchPreGlobalEndLumi(           this, & FastTimerService::preGlobalEndLumi );
0837   registry.watchPostGlobalEndLumi(this, &FastTimerService::postGlobalEndLumi);
0838   registry.watchPreStreamBeginLumi(this, &FastTimerService::preStreamBeginLumi);
0839   //registry.watchPostStreamBeginLumi(        this, & FastTimerService::postStreamBeginLumi );
0840   //registry.watchPreStreamEndLumi(           this, & FastTimerService::preStreamEndLumi );
0841   registry.watchPostStreamEndLumi(this, &FastTimerService::postStreamEndLumi);
0842   registry.watchPreEvent(this, &FastTimerService::preEvent);
0843   registry.watchPostEvent(this, &FastTimerService::postEvent);
0844   registry.watchPrePathEvent(this, &FastTimerService::prePathEvent);
0845   registry.watchPostPathEvent(this, &FastTimerService::postPathEvent);
0846   registry.watchPreSourceConstruction(this, &FastTimerService::preSourceConstruction);
0847   //registry.watchPostSourceConstruction(     this, & FastTimerService::postSourceConstruction);
0848   registry.watchPreSourceRun(this, &FastTimerService::preSourceRun);
0849   registry.watchPostSourceRun(this, &FastTimerService::postSourceRun);
0850   registry.watchPreSourceLumi(this, &FastTimerService::preSourceLumi);
0851   registry.watchPostSourceLumi(this, &FastTimerService::postSourceLumi);
0852   registry.watchPreSourceEvent(this, &FastTimerService::preSourceEvent);
0853   registry.watchPostSourceEvent(this, &FastTimerService::postSourceEvent);
0854   //registry.watchPreModuleConstruction(      this, & FastTimerService::preModuleConstruction);
0855   //registry.watchPostModuleConstruction(     this, & FastTimerService::postModuleConstruction);
0856   //registry.watchPreModuleBeginJob(          this, & FastTimerService::preModuleBeginJob );
0857   //registry.watchPostModuleBeginJob(         this, & FastTimerService::postModuleBeginJob );
0858   //registry.watchPreModuleEndJob(            this, & FastTimerService::preModuleEndJob );
0859   //registry.watchPostModuleEndJob(           this, & FastTimerService::postModuleEndJob );
0860   //registry.watchPreModuleBeginStream(       this, & FastTimerService::preModuleBeginStream );
0861   //registry.watchPostModuleBeginStream(      this, & FastTimerService::postModuleBeginStream );
0862   //registry.watchPreModuleEndStream(         this, & FastTimerService::preModuleEndStream );
0863   //registry.watchPostModuleEndStream(        this, & FastTimerService::postModuleEndStream );
0864   registry.watchPreModuleGlobalBeginRun(this, &FastTimerService::preModuleGlobalBeginRun);
0865   registry.watchPostModuleGlobalBeginRun(this, &FastTimerService::postModuleGlobalBeginRun);
0866   registry.watchPreModuleGlobalEndRun(this, &FastTimerService::preModuleGlobalEndRun);
0867   registry.watchPostModuleGlobalEndRun(this, &FastTimerService::postModuleGlobalEndRun);
0868   registry.watchPreModuleGlobalBeginLumi(this, &FastTimerService::preModuleGlobalBeginLumi);
0869   registry.watchPostModuleGlobalBeginLumi(this, &FastTimerService::postModuleGlobalBeginLumi);
0870   registry.watchPreModuleGlobalEndLumi(this, &FastTimerService::preModuleGlobalEndLumi);
0871   registry.watchPostModuleGlobalEndLumi(this, &FastTimerService::postModuleGlobalEndLumi);
0872   registry.watchPreModuleStreamBeginRun(this, &FastTimerService::preModuleStreamBeginRun);
0873   registry.watchPostModuleStreamBeginRun(this, &FastTimerService::postModuleStreamBeginRun);
0874   registry.watchPreModuleStreamEndRun(this, &FastTimerService::preModuleStreamEndRun);
0875   registry.watchPostModuleStreamEndRun(this, &FastTimerService::postModuleStreamEndRun);
0876   registry.watchPreModuleStreamBeginLumi(this, &FastTimerService::preModuleStreamBeginLumi);
0877   registry.watchPostModuleStreamBeginLumi(this, &FastTimerService::postModuleStreamBeginLumi);
0878   registry.watchPreModuleStreamEndLumi(this, &FastTimerService::preModuleStreamEndLumi);
0879   registry.watchPostModuleStreamEndLumi(this, &FastTimerService::postModuleStreamEndLumi);
0880   //registry.watchPreModuleEventPrefetching(  this, & FastTimerService::preModuleEventPrefetching );
0881   //registry.watchPostModuleEventPrefetching( this, & FastTimerService::postModuleEventPrefetching );
0882   registry.watchPreModuleEventAcquire(this, &FastTimerService::preModuleEventAcquire);
0883   registry.watchPostModuleEventAcquire(this, &FastTimerService::postModuleEventAcquire);
0884   registry.watchPreModuleEvent(this, &FastTimerService::preModuleEvent);
0885   registry.watchPostModuleEvent(this, &FastTimerService::postModuleEvent);
0886   registry.watchPreModuleEventDelayedGet(this, &FastTimerService::preModuleEventDelayedGet);
0887   registry.watchPostModuleEventDelayedGet(this, &FastTimerService::postModuleEventDelayedGet);
0888   registry.watchPreEventReadFromSource(this, &FastTimerService::preEventReadFromSource);
0889   registry.watchPostEventReadFromSource(this, &FastTimerService::postEventReadFromSource);
0890   registry.watchPreESModule(this, &FastTimerService::preESModule);
0891   registry.watchPostESModule(this, &FastTimerService::postESModule);
0892 }
0893 
0894 void FastTimerService::ignoredSignal(const std::string& signal) const {
0895   LogDebug("FastTimerService") << "The FastTimerService received is currently not monitoring the signal \"" << signal
0896                                << "\".\n";
0897 }
0898 
0899 void FastTimerService::unsupportedSignal(const std::string& signal) const {
0900   // warn about each signal only once per job
0901   if (unsupported_signals_.insert(signal).second)
0902     edm::LogWarning("FastTimerService") << "The FastTimerService received the unsupported signal \"" << signal
0903                                         << "\".\n"
0904                                         << "Please report how to reproduce the issue to cms-hlt@cern.ch .";
0905 }
0906 
0907 void FastTimerService::preGlobalBeginRun(edm::GlobalContext const& gc) {
0908   ignoredSignal(__func__);
0909 
0910   // reset the run counters only during the main process being run
0911   if (isFirstSubprocess(gc)) {
0912     auto index = gc.runIndex();
0913     subprocess_global_run_check_[index] = 0;
0914     run_transition_[index].reset();
0915     run_summary_[index].reset();
0916 
0917     // book the DQM plots
0918     if (enable_dqm_) {
0919       // define a callback to book the MonitorElements
0920       auto bookTransactionCallback = [&, this](dqm::reco::DQMStore::IBooker& booker, dqm::reco::DQMStore::IGetter&) {
0921         auto scope = dqm::reco::DQMStore::IBooker::UseRunScope(booker);
0922         // we should really do this, but only DQMStore is allowed to touch it
0923         // We could move to postGlobalBeginRun, then the DQMStore has sure set it up.
0924         //booker.setRunLumi(gc.luminosityBlockID());
0925         booker.setCurrentFolder(dqm_path_);
0926         plots_->book(booker,
0927                      callgraph_,
0928                      highlight_modules_,
0929                      dqm_event_ranges_,
0930                      dqm_path_ranges_,
0931                      dqm_module_ranges_,
0932                      dqm_lumisections_range_,
0933                      enable_dqm_bymodule_,
0934                      enable_dqm_bypath_,
0935                      enable_dqm_byls_,
0936                      enable_dqm_transitions_);
0937       };
0938 
0939       // book MonitorElements for this stream
0940       edm::Service<dqm::legacy::DQMStore>()->meBookerGetter(bookTransactionCallback);
0941     }
0942   }
0943 }
0944 
0945 void FastTimerService::postGlobalBeginRun(edm::GlobalContext const& gc) { ignoredSignal(__func__); }
0946 
0947 void FastTimerService::preStreamBeginRun(edm::StreamContext const& sc) { ignoredSignal(__func__); }
0948 
0949 void FastTimerService::fixForDQM(std::string& label) {
0950   // clean characters that are deemed unsafe for DQM
0951   // see the definition of `s_safe` in DQMServices/Core/src/DQMStore.cc
0952   static const auto safe_for_dqm = "/ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789-+=_()# "s;
0953   for (auto& c : label)
0954     if (safe_for_dqm.find(c) == std::string::npos)
0955       c = '_';
0956 }
0957 
0958 void FastTimerService::preallocate(edm::service::SystemBounds const& bounds) {
0959   concurrent_lumis_ = bounds.maxNumberOfConcurrentLuminosityBlocks();
0960   concurrent_runs_ = bounds.maxNumberOfConcurrentRuns();
0961   concurrent_streams_ = bounds.maxNumberOfStreams();
0962   concurrent_threads_ = bounds.maxNumberOfThreads();
0963 
0964   if (enable_dqm_bynproc_)
0965     dqm_path_ += fmt::sprintf(
0966         "/Running on %s with %d streams on %d threads", processor_model, concurrent_streams_, concurrent_threads_);
0967 
0968   // fix the DQM path to avoid invalid characters
0969   fixForDQM(dqm_path_);
0970 
0971   // allocate atomic variables to keep track of the completion of each step, process by process
0972   subprocess_event_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_streams_);
0973   for (unsigned int i = 0; i < concurrent_streams_; ++i)
0974     subprocess_event_check_[i] = 0;
0975   subprocess_global_run_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_runs_);
0976   for (unsigned int i = 0; i < concurrent_runs_; ++i)
0977     subprocess_global_run_check_[i] = 0;
0978   subprocess_global_lumi_check_ = std::make_unique<std::atomic<unsigned int>[]>(concurrent_lumis_);
0979   for (unsigned int i = 0; i < concurrent_lumis_; ++i)
0980     subprocess_global_lumi_check_[i] = 0;
0981 
0982   // allocate buffers to keep track of the resources spent in the lumi and run transitions
0983   lumi_transition_.resize(concurrent_lumis_);
0984   run_transition_.resize(concurrent_runs_);
0985 }
0986 
0987 void FastTimerService::preSourceConstruction(edm::ModuleDescription const& module) {
0988   callgraph_.preSourceConstruction(module);
0989 }
0990 
0991 void FastTimerService::preBeginJob(edm::PathsAndConsumesOfModulesBase const& pathsAndConsumes,
0992                                    edm::ProcessContext const& context) {
0993   callgraph_.preBeginJob(pathsAndConsumes, context);
0994 }
0995 
0996 void FastTimerService::postBeginJob() {
0997   unsigned int modules = callgraph_.size();
0998 
0999   // 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 
1041 void FastTimerService::preGlobalBeginLumi(edm::GlobalContext const& gc) {
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 
1056 void FastTimerService::postGlobalEndLumi(edm::GlobalContext const& gc) {
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 
1085 void FastTimerService::postGlobalEndRun(edm::GlobalContext const& gc) {
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 
1112 void FastTimerService::postSourceLumi(edm::LuminosityBlockIndex index) {
1113   thread().measure_and_accumulate(lumi_transition_[index]);
1114 }
1115 
1116 void FastTimerService::postEndJob() {
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>
1130 void FastTimerService::printHeader(T& out, std::string const& label) const {
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>
1143 void FastTimerService::printEventHeader(T& out, std::string const& label) const {
1144   out << "FastReport       CPU time      Real time      Allocated    Deallocated  " << label << "\n";
1145   //      FastReport  ########.# ms  ########.# ms  +######### kB  -######### kB  ...
1146 }
1147 
1148 template <typename T>
1149 void FastTimerService::printEventLine(T& out, Resources const& data, std::string const& label) const {
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>
1159 void FastTimerService::printEventLine(T& out, AtomicResources const& data, std::string const& label) const {
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>
1169 void FastTimerService::printEvent(T& out, ResourcesPerJob const& data) const {
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>
1234 void FastTimerService::printPathSummaryHeader(T& out, std::string const& label) const {
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>
1243 void FastTimerService::printSummaryLine(T& out, Resources const& data, uint64_t events, std::string const& label) const {
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>
1256 void FastTimerService::printSummaryLine(
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>
1274 void FastTimerService::printSummaryLine(T& out,
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>
1290 void FastTimerService::printSummaryLine(
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>
1306 void FastTimerService::printPathSummaryLine(
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>
1322 void FastTimerService::printSummary(T& out, ResourcesPerJob const& data, std::string const& label) const {
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>
1376 void FastTimerService::printTransition(T& out, AtomicResources const& data, std::string const& label) const {
1377   printEventHeader(out, "Transition");
1378   printEventLine(out, data, label);
1379 }
1380 
1381 template <typename T>
1382 json FastTimerService::encodeToJSON(std::string const& type,
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 
1395 json FastTimerService::encodeToJSON(edm::ModuleDescription const& module, ResourcesPerModule const& data) const {
1396   return encodeToJSON(module.moduleName(), module.moduleLabel(), data.events, data.total);
1397 }
1398 
1399 void FastTimerService::writeSummaryJSON(ResourcesPerJob const& data, std::string const& filename) const {
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
1429 bool FastTimerService::isFirstSubprocess(edm::StreamContext const& sc) {
1430   return (not sc.processContext()->isSubProcess());
1431 }
1432 
1433 bool FastTimerService::isFirstSubprocess(edm::GlobalContext const& gc) {
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 
1447 void FastTimerService::postEvent(edm::StreamContext const& sc) {
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 
1495 void FastTimerService::preSourceEvent(edm::StreamID sid) {
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 
1509 void FastTimerService::postSourceEvent(edm::StreamID sid) {
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 
1519 void FastTimerService::prePathEvent(edm::StreamContext const& sc, edm::PathContext const& pc) {
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 
1529 void FastTimerService::postPathEvent(edm::StreamContext const& sc,
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 
1553 void FastTimerService::preModuleEventAcquire(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1554   unsigned int sid = sc.streamID().value();
1555   auto& stream = streams_[sid];
1556   thread().measure_and_accumulate(stream.overhead);
1557 }
1558 
1559 void FastTimerService::postModuleEventAcquire(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
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 
1570 void FastTimerService::preModuleEvent(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1571   unsigned int sid = sc.streamID().value();
1572   auto& stream = streams_[sid];
1573   thread().measure_and_accumulate(stream.overhead);
1574 }
1575 
1576 void FastTimerService::postModuleEvent(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
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 
1591 void FastTimerService::preModuleEventDelayedGet(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1592   unsupportedSignal(__func__);
1593 }
1594 
1595 void FastTimerService::postModuleEventDelayedGet(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1596   unsupportedSignal(__func__);
1597 }
1598 
1599 void FastTimerService::preModuleEventPrefetching(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1600   ignoredSignal(__func__);
1601 }
1602 
1603 void FastTimerService::postModuleEventPrefetching(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1604   ignoredSignal(__func__);
1605 }
1606 
1607 void FastTimerService::preEventReadFromSource(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1608   if (mcc.state() == edm::ModuleCallingContext::State::kPrefetching) {
1609     auto& stream = streams_[sc.streamID()];
1610     thread().measure_and_accumulate(stream.overhead);
1611   }
1612 }
1613 
1614 void FastTimerService::postEventReadFromSource(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1615   if (mcc.state() == edm::ModuleCallingContext::State::kPrefetching) {
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 
1625 void FastTimerService::preModuleGlobalBeginRun(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1626   thread().measure_and_accumulate(overhead_);
1627 }
1628 
1629 void FastTimerService::postModuleGlobalBeginRun(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1630   auto index = gc.runIndex();
1631   thread().measure_and_accumulate(run_transition_[index]);
1632 }
1633 
1634 void FastTimerService::preModuleGlobalEndRun(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1635   thread().measure_and_accumulate(overhead_);
1636 }
1637 
1638 void FastTimerService::postModuleGlobalEndRun(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1639   auto index = gc.runIndex();
1640   thread().measure_and_accumulate(run_transition_[index]);
1641 }
1642 
1643 void FastTimerService::preModuleGlobalBeginLumi(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1644   thread().measure_and_accumulate(overhead_);
1645 }
1646 
1647 void FastTimerService::postModuleGlobalBeginLumi(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1648   auto index = gc.luminosityBlockIndex();
1649   thread().measure_and_accumulate(lumi_transition_[index]);
1650 }
1651 
1652 void FastTimerService::preModuleGlobalEndLumi(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1653   thread().measure_and_accumulate(overhead_);
1654 }
1655 
1656 void FastTimerService::postModuleGlobalEndLumi(edm::GlobalContext const& gc, edm::ModuleCallingContext const& mcc) {
1657   auto index = gc.luminosityBlockIndex();
1658   thread().measure_and_accumulate(lumi_transition_[index]);
1659 }
1660 
1661 void FastTimerService::preModuleStreamBeginRun(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1662   thread().measure_and_accumulate(overhead_);
1663 }
1664 
1665 void FastTimerService::postModuleStreamBeginRun(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1666   auto index = sc.runIndex();
1667   thread().measure_and_accumulate(run_transition_[index]);
1668 }
1669 
1670 void FastTimerService::preModuleStreamEndRun(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1671   thread().measure_and_accumulate(overhead_);
1672 }
1673 
1674 void FastTimerService::postModuleStreamEndRun(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1675   auto index = sc.runIndex();
1676   thread().measure_and_accumulate(run_transition_[index]);
1677 }
1678 
1679 void FastTimerService::preModuleStreamBeginLumi(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1680   thread().measure_and_accumulate(overhead_);
1681 }
1682 
1683 void FastTimerService::postModuleStreamBeginLumi(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1684   auto index = sc.luminosityBlockIndex();
1685   thread().measure_and_accumulate(lumi_transition_[index]);
1686 }
1687 
1688 void FastTimerService::preModuleStreamEndLumi(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1689   thread().measure_and_accumulate(overhead_);
1690 }
1691 
1692 void FastTimerService::postModuleStreamEndLumi(edm::StreamContext const& sc, edm::ModuleCallingContext const& mcc) {
1693   auto index = sc.luminosityBlockIndex();
1694   thread().measure_and_accumulate(lumi_transition_[index]);
1695 }
1696 
1697 void FastTimerService::preESModule(edm::eventsetup::EventSetupRecordKey const&, edm::ESModuleCallingContext const& cc) {
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 }
1706 void FastTimerService::postESModule(edm::eventsetup::EventSetupRecordKey const&,
1707                                     edm::ESModuleCallingContext const& cc) {
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 
1716 FastTimerService::ThreadGuard::ThreadGuard() {
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
1724 bool FastTimerService::ThreadGuard::register_thread(FastTimerService::AtomicResources& r) {
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
1744 void FastTimerService::ThreadGuard::retire_thread(void* p) {
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
1755 void FastTimerService::ThreadGuard::finalize() {
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 
1764 FastTimerService::Measurement& FastTimerService::ThreadGuard::thread() {
1765   return (*ptr(::pthread_getspecific(key_)))->measurement_;
1766 }
1767 
1768 void FastTimerService::on_scheduler_entry(bool worker) {
1769   if (guard_.register_thread(overhead_)) {
1770     // initialise the measurement point for a thread that has newly joined the TBB pool
1771     thread().measure();
1772   }
1773 }
1774 
1775 void FastTimerService::on_scheduler_exit(bool worker) {}
1776 
1777 FastTimerService::Measurement& FastTimerService::thread() { return guard_.thread(); }
1778 
1779 // describe the module's configuration
1780 void FastTimerService::fillDescriptions(edm::ConfigurationDescriptions& descriptions) {
1781   edm::ParameterSetDescription desc;
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
1853 #include "FWCore/ServiceRegistry/interface/ServiceMaker.h"
1854 DEFINE_FWK_SERVICE(FastTimerService);