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