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