File indexing completed on 2025-04-30 22:24:13
0001
0002
0003
0004
0005
0006
0007
0008
0009
0010
0011
0012
0013
0014 #include "DataFormats/Provenance/interface/ModuleDescription.h"
0015 #include "FWCore/AbstractServices/interface/TimingServiceBase.h"
0016 #include "FWCore/Framework/interface/EventSetupRecordKey.h"
0017 #include "FWCore/MessageLogger/interface/JobReport.h"
0018 #include "FWCore/MessageLogger/interface/MessageLogger.h"
0019 #include "FWCore/ParameterSet/interface/ConfigurationDescriptions.h"
0020 #include "FWCore/ParameterSet/interface/ParameterSet.h"
0021 #include "FWCore/ParameterSet/interface/ParameterSetDescription.h"
0022 #include "FWCore/ServiceRegistry/interface/ActivityRegistry.h"
0023 #include "FWCore/ServiceRegistry/interface/ESModuleCallingContext.h"
0024 #include "FWCore/ServiceRegistry/interface/GlobalContext.h"
0025 #include "FWCore/ServiceRegistry/interface/ModuleCallingContext.h"
0026 #include "FWCore/ServiceRegistry/interface/Service.h"
0027 #include "FWCore/ServiceRegistry/interface/ServiceMaker.h"
0028 #include "FWCore/ServiceRegistry/interface/ServiceRegistryfwd.h"
0029 #include "FWCore/ServiceRegistry/interface/StreamContext.h"
0030 #include "FWCore/ServiceRegistry/interface/SystemBounds.h"
0031 #include "FWCore/Utilities/interface/thread_safety_macros.h"
0032 #include "FWCore/Utilities/interface/LuminosityBlockIndex.h"
0033 #include "FWCore/Utilities/interface/RunIndex.h"
0034 #include "FWCore/Utilities/interface/StreamID.h"
0035
0036 #include <atomic>
0037 #include <chrono>
0038 #include <map>
0039 #include <memory>
0040 #include <ratio>
0041 #include <sstream>
0042 #include <string>
0043 #include <sys/resource.h>
0044 #include <utility>
0045 #include <vector>
0046
0047 namespace edm {
0048
0049 namespace eventsetup {
0050 struct ComponentDescription;
0051 }
0052
0053 namespace service {
0054 class Timing : public TimingServiceBase {
0055 public:
0056 using time_point = std::chrono::steady_clock::time_point;
0057 using double_seconds = std::chrono::duration<double, std::ratio<1, 1>>;
0058
0059 Timing(ParameterSet const&, ActivityRegistry&);
0060 ~Timing() override;
0061
0062 static void fillDescriptions(edm::ConfigurationDescriptions& descriptions);
0063
0064 void addToCPUTime(double iTime) override;
0065 double getTotalCPU() const override;
0066
0067 private:
0068 void beginProcessing();
0069 void postEndJob();
0070
0071 void preEvent(StreamContext const&);
0072 void postEvent(StreamContext const&);
0073
0074 void postModuleEvent(StreamContext const&, ModuleCallingContext const&);
0075
0076 void preSourceEvent(StreamID);
0077 void postSourceEvent(StreamID);
0078
0079 void preSourceLumi(LuminosityBlockIndex);
0080 void postSourceLumi(LuminosityBlockIndex);
0081
0082 void preSourceRun(RunIndex);
0083 void postSourceRun(RunIndex);
0084
0085 void preOpenFile(std::string const&);
0086 void postOpenFile(std::string const&);
0087
0088 void preModule(ModuleDescription const&);
0089 void postModule(ModuleDescription const&);
0090
0091 void preModuleGlobal(GlobalContext const&, ModuleCallingContext const&);
0092 void postModuleGlobal(GlobalContext const&, ModuleCallingContext const&);
0093
0094 void postGlobalBeginRun(GlobalContext const&);
0095 void postGlobalBeginLumi(GlobalContext const&);
0096
0097 void preModuleStream(StreamContext const&, ModuleCallingContext const&);
0098 void postModuleStream(StreamContext const&, ModuleCallingContext const&);
0099
0100 double postCommon() const;
0101
0102 void setTaskCallbacks(ActivityRegistry&);
0103 inline void addTask() { runningTasksChanged(true); }
0104 inline void removeTask() { runningTasksChanged(false); }
0105 void runningTasksChanged(bool iMoreTasks);
0106
0107 time_point curr_job_time_;
0108 double curr_job_cpu_;
0109 std::atomic<double> extra_job_cpu_;
0110
0111 std::atomic<time_point> end_loop_time_;
0112 std::atomic<double> end_loop_cpu_;
0113 std::vector<time_point> curr_events_time_;
0114 bool summary_only_;
0115 bool report_summary_;
0116 double threshold_;
0117
0118 std::atomic<bool> updating_task_info_ = false;
0119 CMS_THREAD_GUARD(updating_task_info_) unsigned int num_running_tasks_ = 0;
0120 CMS_THREAD_GUARD(updating_task_info_) time_point last_task_change_time_ = time_point();
0121 CMS_THREAD_GUARD(updating_task_info_) double total_time_without_tasks_ = 0;
0122
0123
0124
0125 std::vector<double> max_events_time_;
0126 std::vector<double> min_events_time_;
0127 std::vector<double> sum_events_time_;
0128 std::atomic<unsigned long> total_event_count_;
0129 std::atomic<unsigned long> begin_lumi_count_;
0130 std::atomic<unsigned long> begin_run_count_;
0131 unsigned int nStreams_;
0132 unsigned int nThreads_;
0133
0134 std::vector<std::unique_ptr<std::atomic<time_point>>> eventSetupModuleStartTimes_;
0135 std::vector<std::pair<uintptr_t, eventsetup::EventSetupRecordKey>> eventSetupModuleCallInfo_;
0136 std::atomic<double> accumulatedEventSetupModuleTimings_ = 0.;
0137 };
0138 }
0139 }
0140
0141 namespace edm {
0142 namespace service {
0143
0144 static std::string d2str(double d) {
0145 std::stringstream t;
0146 t << d;
0147 return t.str();
0148 }
0149
0150 static std::string ui2str(unsigned int i) {
0151 std::stringstream t;
0152 t << i;
0153 return t.str();
0154 }
0155
0156 static std::chrono::steady_clock::time_point getTime() { return std::chrono::steady_clock::now(); }
0157
0158 static double getChildrenCPU() {
0159 struct rusage usage;
0160
0161 getrusage(RUSAGE_CHILDREN, &usage);
0162 double totalCPUTime = (double)usage.ru_utime.tv_sec + (double(usage.ru_utime.tv_usec) * 1E-6);
0163 totalCPUTime += (double)usage.ru_stime.tv_sec + (double(usage.ru_stime.tv_usec) * 1E-6);
0164
0165 return totalCPUTime;
0166 }
0167
0168 static double getCPU() {
0169 struct rusage usage;
0170 getrusage(RUSAGE_SELF, &usage);
0171
0172 double totalCPUTime = 0.0;
0173
0174 totalCPUTime = (double)usage.ru_utime.tv_sec + (double(usage.ru_utime.tv_usec) * 1E-6);
0175
0176 totalCPUTime += (double)usage.ru_stime.tv_sec + (double(usage.ru_stime.tv_usec) * 1E-6);
0177
0178
0179 getrusage(RUSAGE_CHILDREN, &usage);
0180 totalCPUTime += (double)usage.ru_utime.tv_sec + (double(usage.ru_utime.tv_usec) * 1E-6);
0181 totalCPUTime += (double)usage.ru_stime.tv_sec + (double(usage.ru_stime.tv_usec) * 1E-6);
0182
0183 return totalCPUTime;
0184 }
0185
0186
0187
0188
0189 static std::vector<std::chrono::steady_clock::time_point>& moduleTimeStack() {
0190 static thread_local std::vector<std::chrono::steady_clock::time_point> s_stack;
0191 return s_stack;
0192 }
0193
0194 static double popStack() {
0195 auto& modStack = moduleTimeStack();
0196 assert(!modStack.empty());
0197 auto curr_module_time = modStack.back();
0198 modStack.pop_back();
0199 std::chrono::duration<double, std::ratio<1, 1>> t = getTime() - curr_module_time;
0200 return t.count();
0201 }
0202
0203 static void pushStack() {
0204 auto& modStack = moduleTimeStack();
0205 modStack.push_back(getTime());
0206 }
0207
0208 Timing::Timing(ParameterSet const& iPS, ActivityRegistry& iRegistry)
0209 : curr_job_time_(),
0210 curr_job_cpu_(0.),
0211 extra_job_cpu_(0.0),
0212 end_loop_time_(),
0213 end_loop_cpu_(0.0),
0214 curr_events_time_(),
0215 summary_only_(iPS.getUntrackedParameter<bool>("summaryOnly")),
0216 report_summary_(iPS.getUntrackedParameter<bool>("useJobReport")),
0217 threshold_(iPS.getUntrackedParameter<double>("excessiveTimeThreshold")),
0218 max_events_time_(),
0219 min_events_time_(),
0220 total_event_count_(0),
0221 begin_lumi_count_(0),
0222 begin_run_count_(0) {
0223 iRegistry.watchBeginProcessing(this, &Timing::beginProcessing);
0224 iRegistry.watchPreEndJob([this]() {
0225 end_loop_time_ = getTime();
0226 end_loop_cpu_ = getCPU();
0227 });
0228 iRegistry.watchPostEndJob(this, &Timing::postEndJob);
0229
0230 iRegistry.watchPreEvent(this, &Timing::preEvent);
0231 iRegistry.watchPostEvent(this, &Timing::postEvent);
0232
0233 bool checkThreshold = true;
0234 if (threshold_ <= 0.0) {
0235
0236 threshold_ = std::numeric_limits<double>::max();
0237 checkThreshold = false;
0238 }
0239
0240 if ((not summary_only_) || (checkThreshold)) {
0241 iRegistry.watchPreModuleEvent(this, &Timing::preModuleStream);
0242 iRegistry.watchPostModuleEvent(this, &Timing::postModuleEvent);
0243 iRegistry.watchPreModuleEventAcquire(this, &Timing::preModuleStream);
0244 iRegistry.watchPostModuleEventAcquire(this, &Timing::postModuleEvent);
0245 }
0246 if (checkThreshold) {
0247 iRegistry.watchPreSourceEvent(this, &Timing::preSourceEvent);
0248 iRegistry.watchPostSourceEvent(this, &Timing::postSourceEvent);
0249
0250 iRegistry.watchPreSourceLumi(this, &Timing::preSourceLumi);
0251 iRegistry.watchPostSourceLumi(this, &Timing::postSourceLumi);
0252
0253 iRegistry.watchPreSourceRun(this, &Timing::preSourceRun);
0254 iRegistry.watchPostSourceRun(this, &Timing::postSourceRun);
0255
0256 iRegistry.watchPreOpenFile(this, &Timing::preOpenFile);
0257 iRegistry.watchPostOpenFile(this, &Timing::postOpenFile);
0258
0259 iRegistry.watchPreEventReadFromSource(this, &Timing::preModuleStream);
0260 iRegistry.watchPostEventReadFromSource(this, &Timing::postModuleStream);
0261
0262 iRegistry.watchPreModuleConstruction(this, &Timing::preModule);
0263 iRegistry.watchPostModuleConstruction(this, &Timing::postModule);
0264
0265 iRegistry.watchPreModuleDestruction(this, &Timing::preModule);
0266 iRegistry.watchPostModuleDestruction(this, &Timing::postModule);
0267
0268 iRegistry.watchPreModuleBeginJob(this, &Timing::preModule);
0269 iRegistry.watchPostModuleBeginJob(this, &Timing::postModule);
0270
0271 iRegistry.watchPreModuleEndJob(this, &Timing::preModule);
0272 iRegistry.watchPostModuleEndJob(this, &Timing::postModule);
0273
0274 iRegistry.watchPreModuleStreamBeginRun(this, &Timing::preModuleStream);
0275 iRegistry.watchPostModuleStreamBeginRun(this, &Timing::postModuleStream);
0276 iRegistry.watchPreModuleStreamEndRun(this, &Timing::preModuleStream);
0277 iRegistry.watchPostModuleStreamEndRun(this, &Timing::postModuleStream);
0278
0279 iRegistry.watchPreModuleStreamBeginLumi(this, &Timing::preModuleStream);
0280 iRegistry.watchPostModuleStreamBeginLumi(this, &Timing::postModuleStream);
0281 iRegistry.watchPreModuleStreamEndLumi(this, &Timing::preModuleStream);
0282 iRegistry.watchPostModuleStreamEndLumi(this, &Timing::postModuleStream);
0283
0284 iRegistry.watchPreModuleGlobalBeginRun(this, &Timing::preModuleGlobal);
0285 iRegistry.watchPostModuleGlobalBeginRun(this, &Timing::postModuleGlobal);
0286 iRegistry.watchPreModuleGlobalEndRun(this, &Timing::preModuleGlobal);
0287 iRegistry.watchPostModuleGlobalEndRun(this, &Timing::postModuleGlobal);
0288
0289 iRegistry.watchPreModuleGlobalBeginLumi(this, &Timing::preModuleGlobal);
0290 iRegistry.watchPostModuleGlobalBeginLumi(this, &Timing::postModuleGlobal);
0291 iRegistry.watchPreModuleGlobalEndLumi(this, &Timing::preModuleGlobal);
0292 iRegistry.watchPostModuleGlobalEndLumi(this, &Timing::postModuleGlobal);
0293
0294 iRegistry.watchPreSourceConstruction(this, &Timing::preModule);
0295 iRegistry.watchPostSourceConstruction(this, &Timing::postModule);
0296 }
0297
0298 auto preESModuleLambda = [this](auto const& recordKey, auto const& context) {
0299 addTask();
0300
0301 auto startTime = getTime();
0302 bool foundSlot = false;
0303 do {
0304 for (size_t i = 0; i < eventSetupModuleStartTimes_.size(); ++i) {
0305 auto& slot = *eventSetupModuleStartTimes_[i];
0306 std::chrono::steady_clock::time_point expect;
0307 if (slot.compare_exchange_strong(expect, startTime)) {
0308 foundSlot = true;
0309 eventSetupModuleCallInfo_[i].first = uintptr_t(context.componentDescription());
0310 eventSetupModuleCallInfo_[i].second = recordKey;
0311 break;
0312 }
0313 }
0314
0315
0316 } while (not foundSlot);
0317 };
0318 iRegistry.watchPreESModule(preESModuleLambda);
0319 iRegistry.watchPreESModuleAcquire(preESModuleLambda);
0320
0321 auto postESModuleLambda = [this](auto const& recordKey, auto const& context) {
0322 removeTask();
0323 auto stopTime = getTime();
0324 for (size_t i = 0; i < eventSetupModuleStartTimes_.size(); ++i) {
0325 auto const& info = eventSetupModuleCallInfo_[i];
0326 if (info.first == uintptr_t(context.componentDescription()) and info.second == recordKey) {
0327 auto startTime = eventSetupModuleStartTimes_[i]->exchange(std::chrono::steady_clock::time_point());
0328 auto expect = accumulatedEventSetupModuleTimings_.load();
0329 double_seconds timeDiff = stopTime - startTime;
0330 auto accumulatedTime = expect + timeDiff.count();
0331 while (not accumulatedEventSetupModuleTimings_.compare_exchange_strong(expect, accumulatedTime)) {
0332 accumulatedTime = expect + timeDiff.count();
0333 }
0334 break;
0335 }
0336 }
0337 };
0338 iRegistry.watchPostESModule(postESModuleLambda);
0339 iRegistry.watchPostESModuleAcquire(postESModuleLambda);
0340
0341 iRegistry.watchPostGlobalBeginRun(this, &Timing::postGlobalBeginRun);
0342 iRegistry.watchPostGlobalBeginLumi(this, &Timing::postGlobalBeginLumi);
0343
0344 iRegistry.watchPreallocate([this](service::SystemBounds const& iBounds) {
0345 nStreams_ = iBounds.maxNumberOfStreams();
0346 nThreads_ = iBounds.maxNumberOfThreads();
0347 curr_events_time_.resize(nStreams_, time_point());
0348 sum_events_time_.resize(nStreams_, 0.);
0349 max_events_time_.resize(nStreams_, 0.);
0350 min_events_time_.resize(nStreams_, 1.E6);
0351 eventSetupModuleStartTimes_.reserve(nThreads_);
0352 for (unsigned int i = 0; i < nThreads_; ++i) {
0353 eventSetupModuleStartTimes_.emplace_back(std::make_unique<std::atomic<time_point>>());
0354 }
0355 eventSetupModuleCallInfo_.resize(nThreads_);
0356 });
0357 setTaskCallbacks(iRegistry);
0358 }
0359
0360 void Timing::setTaskCallbacks(ActivityRegistry& iRegistry) {
0361 iRegistry.watchPreSourceEvent([this](auto) { addTask(); });
0362 iRegistry.watchPostSourceEvent([this](auto) { removeTask(); });
0363
0364 iRegistry.watchPreModuleEvent([this](auto, auto) { addTask(); });
0365 iRegistry.watchPostModuleEvent([this](auto, auto) { removeTask(); });
0366 iRegistry.watchPreModuleEventAcquire([this](auto, auto) { addTask(); });
0367 iRegistry.watchPostModuleEventAcquire([this](auto, auto) { removeTask(); });
0368
0369 iRegistry.watchPreSourceLumi([this](auto) { addTask(); });
0370 iRegistry.watchPostSourceLumi([this](auto) { removeTask(); });
0371
0372 iRegistry.watchPreSourceRun([this](auto) { addTask(); });
0373 iRegistry.watchPostSourceRun([this](auto) { removeTask(); });
0374
0375 iRegistry.watchPreEventReadFromSource([this](auto, auto) { addTask(); });
0376 iRegistry.watchPostEventReadFromSource([this](auto, auto) { removeTask(); });
0377
0378 iRegistry.watchPreModuleStreamBeginRun([this](auto, auto) { addTask(); });
0379 iRegistry.watchPostModuleStreamBeginRun([this](auto, auto) { removeTask(); });
0380 iRegistry.watchPreModuleStreamEndRun([this](auto, auto) { addTask(); });
0381 iRegistry.watchPostModuleStreamEndRun([this](auto, auto) { removeTask(); });
0382
0383 iRegistry.watchPreModuleStreamBeginLumi([this](auto, auto) { addTask(); });
0384 iRegistry.watchPostModuleStreamBeginLumi([this](auto, auto) { removeTask(); });
0385 iRegistry.watchPreModuleStreamEndLumi([this](auto, auto) { addTask(); });
0386 iRegistry.watchPostModuleStreamEndLumi([this](auto, auto) { removeTask(); });
0387
0388 iRegistry.watchPreModuleGlobalBeginRun([this](auto, auto) { addTask(); });
0389 iRegistry.watchPostModuleGlobalBeginRun([this](auto, auto) { removeTask(); });
0390 iRegistry.watchPreModuleGlobalEndRun([this](auto, auto) { addTask(); });
0391 iRegistry.watchPostModuleGlobalEndRun([this](auto, auto) { removeTask(); });
0392
0393 iRegistry.watchPreModuleGlobalBeginLumi([this](auto, auto) { addTask(); });
0394 iRegistry.watchPostModuleGlobalBeginLumi([this](auto, auto) { removeTask(); });
0395 iRegistry.watchPreModuleGlobalEndLumi([this](auto, auto) { addTask(); });
0396 iRegistry.watchPostModuleGlobalEndLumi([this](auto, auto) { removeTask(); });
0397
0398
0399 iRegistry.watchPreESSyncIOV([this](auto const&) { addTask(); });
0400 iRegistry.watchPostESSyncIOV([this](auto const&) { removeTask(); });
0401 }
0402
0403 Timing::~Timing() {}
0404
0405 void Timing::addToCPUTime(double iTime) {
0406
0407 double expected = extra_job_cpu_.load();
0408 while (not extra_job_cpu_.compare_exchange_strong(expected, expected + iTime)) {
0409 }
0410 }
0411
0412 double Timing::getTotalCPU() const { return getCPU(); }
0413
0414 void Timing::fillDescriptions(ConfigurationDescriptions& descriptions) {
0415 ParameterSetDescription desc;
0416 desc.addUntracked<bool>("summaryOnly", false)->setComment("If 'true' do not report timing for each event");
0417 desc.addUntracked<bool>("useJobReport", true)->setComment("If 'true' write summary information to JobReport");
0418 desc.addUntracked<double>("excessiveTimeThreshold", 0.)
0419 ->setComment(
0420 "Amount of time in seconds before reporting a module or source has taken excessive time. A value of 0.0 "
0421 "turns off this reporting.");
0422 descriptions.add("Timing", desc);
0423 descriptions.setComment("This service reports the time it takes to run each module in a job.");
0424 }
0425
0426 void Timing::beginProcessing() {
0427 curr_job_time_ = getTime();
0428 curr_job_cpu_ = getCPU();
0429 last_task_change_time_ = curr_job_time_;
0430
0431 if (not summary_only_) {
0432 LogImportant("TimeReport")
0433 << "TimeReport> Report activated"
0434 << "\n"
0435 << "TimeReport> Report columns headings for events: "
0436 << "eventnum runnum timetaken\n"
0437 << "TimeReport> Report columns headings for modules: "
0438 << "eventnum runnum modulelabel modulename timetaken\n"
0439 << "TimeReport> JobTime="
0440 << std::chrono::time_point_cast<std::chrono::seconds>(curr_job_time_).time_since_epoch().count()
0441 << " JobCPU=" << curr_job_cpu_ << "\n";
0442 }
0443 }
0444
0445 void Timing::postEndJob() {
0446 const auto job_end_time = getTime();
0447 const double job_end_cpu = getCPU();
0448 auto total_job_time = double_seconds(job_end_time - jobStartTime()).count();
0449
0450 double total_job_cpu = job_end_cpu + extra_job_cpu_;
0451
0452 const double job_end_children_cpu = getChildrenCPU();
0453
0454 const double total_initialization_time = double_seconds(curr_job_time_ - jobStartTime()).count();
0455 const double total_initialization_cpu = curr_job_cpu_;
0456
0457 if (time_point() == jobStartTime()) {
0458
0459 total_job_time = double_seconds(job_end_time - curr_job_time_).count();
0460 total_job_cpu = job_end_cpu + extra_job_cpu_ - curr_job_cpu_;
0461 }
0462
0463 double min_event_time = *(std::min_element(min_events_time_.begin(), min_events_time_.end()));
0464 double max_event_time = *(std::max_element(max_events_time_.begin(), max_events_time_.end()));
0465
0466 auto total_loop_time = double_seconds(end_loop_time_.load() - curr_job_time_).count();
0467 auto total_loop_cpu = end_loop_cpu_ + extra_job_cpu_ - curr_job_cpu_;
0468
0469 if (end_loop_time_.load() == time_point()) {
0470 total_loop_time = 0.0;
0471 total_loop_cpu = 0.0;
0472 }
0473
0474 double sum_all_events_time = 0;
0475 for (auto t : sum_events_time_) {
0476 sum_all_events_time += t;
0477 }
0478
0479 double average_event_time = 0.0;
0480 if (total_event_count_ != 0) {
0481 average_event_time = sum_all_events_time / total_event_count_;
0482 }
0483
0484 double event_throughput = 0.0;
0485 if (total_loop_time != 0.0) {
0486 event_throughput = total_event_count_ / total_loop_time;
0487 }
0488
0489 LogImportant("TimeReport") << "TimeReport> Time report complete in " << total_job_time << " seconds"
0490 << "\n"
0491 << " Time Summary: \n"
0492 << " - Min event: " << min_event_time << "\n"
0493 << " - Max event: " << max_event_time << "\n"
0494 << " - Avg event: " << average_event_time << "\n"
0495 << " - Total loop: " << total_loop_time << "\n"
0496 << " - Total init: " << total_initialization_time << "\n"
0497 << " - Total job: " << total_job_time << "\n"
0498 << " - Total EventSetup: " << accumulatedEventSetupModuleTimings_.load() << "\n"
0499 << " - Total non-module: " << total_time_without_tasks_ << "\n"
0500 << " Event Throughput: " << event_throughput << " ev/s\n"
0501 << " CPU Summary: \n"
0502 << " - Total loop: " << total_loop_cpu << "\n"
0503 << " - Total init: " << total_initialization_cpu << "\n"
0504 << " - Total extra: " << extra_job_cpu_ << "\n"
0505 << " - Total children: " << job_end_children_cpu << "\n"
0506 << " - Total job: " << total_job_cpu << "\n"
0507 << " Processing Summary: \n"
0508 << " - Number of Events: " << total_event_count_ << "\n"
0509 << " - Number of Global Begin Lumi Calls: " << begin_lumi_count_ << "\n"
0510 << " - Number of Global Begin Run Calls: " << begin_run_count_ << "\n";
0511
0512 if (report_summary_) {
0513 Service<JobReport> reportSvc;
0514 std::map<std::string, std::string> reportData;
0515
0516 reportData.insert(std::make_pair("MinEventTime", d2str(min_event_time)));
0517 reportData.insert(std::make_pair("MaxEventTime", d2str(max_event_time)));
0518 reportData.insert(std::make_pair("AvgEventTime", d2str(average_event_time)));
0519 reportData.insert(std::make_pair("EventThroughput", d2str(event_throughput)));
0520 reportData.insert(std::make_pair("TotalJobTime", d2str(total_job_time)));
0521 reportData.insert(std::make_pair("TotalJobCPU", d2str(total_job_cpu)));
0522 reportData.insert(std::make_pair("TotalJobChildrenCPU", d2str(job_end_children_cpu)));
0523 reportData.insert(std::make_pair("TotalLoopTime", d2str(total_loop_time)));
0524 reportData.insert(std::make_pair("TotalEventSetupTime", d2str(accumulatedEventSetupModuleTimings_.load())));
0525 reportData.insert(std::make_pair("TotalNonModuleTime", d2str(total_time_without_tasks_)));
0526 reportData.insert(std::make_pair("TotalLoopCPU", d2str(total_loop_cpu)));
0527 reportData.insert(std::make_pair("TotalInitTime", d2str(total_initialization_time)));
0528 reportData.insert(std::make_pair("TotalInitCPU", d2str(total_initialization_cpu)));
0529 reportData.insert(std::make_pair("NumberOfStreams", ui2str(nStreams_)));
0530 reportData.insert(std::make_pair("NumberOfThreads", ui2str(nThreads_)));
0531 reportSvc->reportPerformanceSummary("Timing", reportData);
0532
0533 std::map<std::string, std::string> reportData1;
0534 reportData1.insert(std::make_pair("NumberEvents", ui2str(total_event_count_)));
0535 reportData1.insert(std::make_pair("NumberBeginLumiCalls", ui2str(begin_lumi_count_)));
0536 reportData1.insert(std::make_pair("NumberBeginRunCalls", ui2str(begin_run_count_)));
0537 reportSvc->reportPerformanceSummary("ProcessingSummary", reportData1);
0538 }
0539 }
0540
0541 void Timing::preEvent(StreamContext const& iStream) {
0542 auto index = iStream.streamID().value();
0543 curr_events_time_[index] = getTime();
0544 }
0545
0546 void Timing::postEvent(StreamContext const& iStream) {
0547 auto index = iStream.streamID().value();
0548 std::chrono::steady_clock::duration curr_event_time = getTime() - curr_events_time_[index];
0549
0550 double curr_event_time_d = double_seconds(curr_event_time).count();
0551 sum_events_time_[index] += curr_event_time_d;
0552
0553 if (not summary_only_) {
0554 auto const& eventID = iStream.eventID();
0555 LogPrint("TimeEvent") << "TimeEvent> " << eventID.event() << " " << eventID.run() << " " << curr_event_time_d;
0556 }
0557 if (curr_event_time_d > max_events_time_[index])
0558 max_events_time_[index] = curr_event_time_d;
0559 if (curr_event_time_d < min_events_time_[index])
0560 min_events_time_[index] = curr_event_time_d;
0561 ++total_event_count_;
0562 }
0563
0564 void Timing::postModuleEvent(StreamContext const& iStream, ModuleCallingContext const& iModule) {
0565 auto const& eventID = iStream.eventID();
0566 auto const& desc = *(iModule.moduleDescription());
0567 double t = postCommon();
0568 if (not summary_only_) {
0569 LogPrint("TimeModule") << "TimeModule> " << eventID.event() << " " << eventID.run() << " " << desc.moduleLabel()
0570 << " " << desc.moduleName() << " " << t;
0571 }
0572 }
0573
0574 void Timing::preSourceEvent(StreamID) { pushStack(); }
0575
0576 void Timing::postSourceEvent(StreamID) { postCommon(); }
0577
0578 void Timing::preSourceLumi(LuminosityBlockIndex) { pushStack(); }
0579
0580 void Timing::postSourceLumi(LuminosityBlockIndex) { postCommon(); }
0581
0582 void Timing::preSourceRun(RunIndex) { pushStack(); }
0583
0584 void Timing::postSourceRun(RunIndex) { postCommon(); }
0585
0586 void Timing::preOpenFile(std::string const&) { pushStack(); }
0587
0588 void Timing::postOpenFile(std::string const&) { postCommon(); }
0589
0590 void Timing::preModule(ModuleDescription const&) { pushStack(); }
0591
0592 void Timing::postModule(ModuleDescription const&) { postCommon(); }
0593
0594 void Timing::preModuleGlobal(GlobalContext const&, ModuleCallingContext const&) { pushStack(); }
0595
0596 void Timing::postModuleGlobal(GlobalContext const&, ModuleCallingContext const& mcc) { postCommon(); }
0597
0598 void Timing::postGlobalBeginRun(GlobalContext const& gc) { ++begin_run_count_; }
0599
0600 void Timing::postGlobalBeginLumi(GlobalContext const& gc) { ++begin_lumi_count_; }
0601
0602 void Timing::preModuleStream(StreamContext const&, ModuleCallingContext const&) { pushStack(); }
0603
0604 void Timing::postModuleStream(StreamContext const&, ModuleCallingContext const& mcc) { postCommon(); }
0605
0606 double Timing::postCommon() const {
0607 double t = popStack();
0608 if (t > threshold_) {
0609 LogError("ExcessiveTime")
0610 << "ExcessiveTime: Module used " << t
0611 << " seconds of time which exceeds the error threshold configured in the Timing Service of " << threshold_
0612 << " seconds.";
0613 }
0614 return t;
0615 }
0616
0617 void Timing::runningTasksChanged(bool iMoreTasks) {
0618 const auto presentTime = getTime();
0619 bool expected = false;
0620 while (not updating_task_info_.compare_exchange_strong(expected, true)) {
0621 expected = false;
0622 }
0623 auto previousNumberOfTasks = iMoreTasks ? num_running_tasks_++ : num_running_tasks_--;
0624 total_time_without_tasks_ +=
0625 (nThreads_ - previousNumberOfTasks) * double_seconds(presentTime - last_task_change_time_).count();
0626 last_task_change_time_ = presentTime;
0627 updating_task_info_ = false;
0628 }
0629 }
0630 }
0631
0632 using edm::service::Timing;
0633
0634 typedef edm::serviceregistry::AllArgsMaker<edm::TimingServiceBase, Timing> TimingMaker;
0635 DEFINE_FWK_SERVICE_MAKER(Timing, TimingMaker);
