File indexing completed on 2023-03-17 11:09:50
0001
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
0014 #include <boost/range/irange.hpp>
0015
0016
0017 #include <fmt/printf.h>
0018
0019
0020 #include <nlohmann/json.hpp>
0021 using json = nlohmann::json;
0022
0023
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
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
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
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
0070 uint64_t kB(uint64_t bytes) { return bytes / 1024; }
0071
0072
0073 uint64_t kB(std::atomic<uint64_t> const& bytes) { return bytes.load() / 1024; }
0074
0075 }
0076
0077
0078
0079
0080
0081
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
0125
0126
0127
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
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
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;
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
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
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
0307
0308
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
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
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
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
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
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
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
0622 total_.fill(path.total, ls);
0623
0624
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
0676 event_.fill(process.total, ls);
0677
0678
0679 for (unsigned int id : boost::irange(0ul, paths_.size()))
0680 paths_[id].fill(description.paths_[id], data, process.paths[id], ls);
0681
0682
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
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
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
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
0748 event_.fill(data.total, ls);
0749 event_ex_.fill(data.event, ls);
0750 overhead_.fill(data.overhead, ls);
0751
0752
0753 for (unsigned int group : boost::irange(0ul, highlight_.size()))
0754 highlight_[group].fill_fraction(data.total, data.highlight[group], ls);
0755
0756
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
0766 run_.fill(data, 0);
0767 }
0768
0769 void FastTimerService::PlotsPerJob::fill_lumi(AtomicResources const& data, unsigned int ls) {
0770
0771 lumi_.fill(data, ls);
0772 }
0773
0774
0775
0776 FastTimerService::FastTimerService(const edm::ParameterSet& config, edm::ActivityRegistry& registry)
0777 :
0778 callgraph_(),
0779
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
0788
0789
0790
0791 write_json_summary_(config.getUntrackedParameter<bool>("writeJSONSummary")),
0792 json_filename_(config.getUntrackedParameter<std::string>("jsonFileName")),
0793
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"),
0801 config.getUntrackedParameter<double>("dqmTimeResolution"),
0802 config.getUntrackedParameter<double>("dqmMemoryRange"),
0803 config.getUntrackedParameter<double>("dqmMemoryResolution")}),
0804 dqm_path_ranges_({config.getUntrackedParameter<double>("dqmPathTimeRange"),
0805 config.getUntrackedParameter<double>("dqmPathTimeResolution"),
0806 config.getUntrackedParameter<double>("dqmPathMemoryRange"),
0807 config.getUntrackedParameter<double>("dqmPathMemoryResolution")}),
0808 dqm_module_ranges_({config.getUntrackedParameter<double>("dqmModuleTimeRange"),
0809 config.getUntrackedParameter<double>("dqmModuleTimeResolution"),
0810 config.getUntrackedParameter<double>("dqmModuleMemoryRange"),
0811 config.getUntrackedParameter<double>("dqmModuleMemoryResolution")}),
0812 dqm_lumisections_range_(config.getUntrackedParameter<unsigned int>("dqmLumiSectionsRange")),
0813 dqm_path_(config.getUntrackedParameter<std::string>("dqmPath")),
0814
0815 highlight_module_psets_(config.getUntrackedParameter<std::vector<edm::ParameterSet>>("highlightModules")),
0816 highlight_modules_(highlight_module_psets_.size())
0817 {
0818
0819 tbb::task_scheduler_observer::observe();
0820
0821
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
0828
0829 registry.watchPostGlobalEndRun(this, &FastTimerService::postGlobalEndRun);
0830 registry.watchPreStreamBeginRun(this, &FastTimerService::preStreamBeginRun);
0831
0832
0833 registry.watchPostStreamEndRun(this, &FastTimerService::postStreamEndRun);
0834 registry.watchPreGlobalBeginLumi(this, &FastTimerService::preGlobalBeginLumi);
0835
0836
0837 registry.watchPostGlobalEndLumi(this, &FastTimerService::postGlobalEndLumi);
0838 registry.watchPreStreamBeginLumi(this, &FastTimerService::preStreamBeginLumi);
0839
0840
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
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
0855
0856
0857
0858
0859
0860
0861
0862
0863
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
0881
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
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
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
0918 if (enable_dqm_) {
0919
0920 auto bookTransactionCallback = [&, this](dqm::reco::DQMStore::IBooker& booker, dqm::reco::DQMStore::IGetter&) {
0921 auto scope = dqm::reco::DQMStore::IBooker::UseRunScope(booker);
0922
0923
0924
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
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
0951
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
0969 fixForDQM(dqm_path_);
0970
0971
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
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
1000 for (unsigned int group : boost::irange(0ul, highlight_module_psets_.size())) {
1001
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
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
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
1023 if (enable_dqm_ and not edm::Service<dqm::legacy::DQMStore>().isAvailable()) {
1024
1025 enable_dqm_ = false;
1026 edm::LogWarning("FastTimerService") << "The DQMStore is not avalable, the DQM plots will not be generated";
1027 }
1028
1029
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
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
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
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
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
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
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
1226 else
1227 out << "FastReport CPU time avg. Real time avg. Alloc. avg. Dealloc. avg. ";
1228
1229 out << label << '\n';
1230
1231 }
1232
1233 template <typename T>
1234 void FastTimerService::printPathSummaryHeader(T& out, std::string const& label) const {
1235
1236 out << "FastReport CPU time sched. / depend. Real time sched. / depend. Alloc. sched. / depend. Dealloc. sched. / depend. ";
1237
1238 out << label << '\n';
1239
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
1246 "FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1247
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
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
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
1280 "FastReport %10.1f ms %10.1f ms %+10d kB %+10d kB %s\n",
1281
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
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
1409 j["total"] = encodeToJSON(
1410 "Job", callgraph_.processDescription(0).name_, data.events, data.total + data.overhead + data.eventsetup);
1411
1412
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
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
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
1438 bool FastTimerService::isLastSubprocess(std::atomic<unsigned int>& check) {
1439
1440
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
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
1462 bool last = isLastSubprocess(subprocess_event_check_[sid]);
1463 if (not last)
1464 return;
1465
1466
1467 stream.event_measurement.measure_and_store(stream.event);
1468
1469
1470 unsigned int id = 0;
1471 stream.total += stream.modules[id].total;
1472
1473
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
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
1497 auto& stream = streams_[sid];
1498 stream.reset();
1499 ++stream.events;
1500
1501 subprocess_event_check_[sid] = 0;
1502
1503
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
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
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
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
1749 (*ps)->measurement_.measure_and_accumulate((*ps)->resource_);
1750 }
1751 delete ps;
1752 }
1753
1754
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
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
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
1786
1787
1788
1789 desc.addUntracked<bool>("writeJSONSummary", false);
1790 desc.addUntracked<std::string>("jsonFileName", "resources.json");
1791
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.);
1799 desc.addUntracked<double>("dqmTimeResolution", 5.);
1800 desc.addUntracked<double>("dqmMemoryRange", 1000000.);
1801 desc.addUntracked<double>("dqmMemoryResolution", 5000.);
1802 desc.addUntracked<double>("dqmPathTimeRange", 100.);
1803 desc.addUntracked<double>("dqmPathTimeResolution", 0.5);
1804 desc.addUntracked<double>("dqmPathMemoryRange", 1000000.);
1805 desc.addUntracked<double>("dqmPathMemoryResolution", 5000.);
1806 desc.addUntracked<double>("dqmModuleTimeRange", 40.);
1807 desc.addUntracked<double>("dqmModuleTimeResolution", 0.2);
1808 desc.addUntracked<double>("dqmModuleMemoryRange", 100000.);
1809 desc.addUntracked<double>("dqmModuleMemoryResolution", 500.);
1810 desc.addUntracked<unsigned>("dqmLumiSectionsRange", 2500);
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
1819
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
1853 #include "FWCore/ServiceRegistry/interface/ServiceMaker.h"
1854 DEFINE_FWK_SERVICE(FastTimerService);