CMS 3D CMS Logo

List of all members | Classes | Public Member Functions | Static Public Member Functions | Private Member Functions | Private Attributes
edm::service::Timing Class Reference
Inheritance diagram for edm::service::Timing:
edm::TimingServiceBase

Classes

struct  CountAndTime
 

Public Member Functions

void addToCPUTime (double iTime) override
 
double getTotalCPU () const override
 
 Timing (ParameterSet const &, ActivityRegistry &)
 
 ~Timing () override
 
- Public Member Functions inherited from edm::TimingServiceBase
const TimingServiceBaseoperator= (const TimingServiceBase &)=delete
 
 TimingServiceBase ()
 
 TimingServiceBase (const TimingServiceBase &)=delete
 
virtual ~TimingServiceBase ()
 

Static Public Member Functions

static void fillDescriptions (edm::ConfigurationDescriptions &descriptions)
 
- Static Public Member Functions inherited from edm::TimingServiceBase
static void jobStarted ()
 
static double jobStartTime ()
 

Private Member Functions

void accumulateTimeBegin (std::atomic< CountAndTime *> &countAndTime, double &accumulatedTime)
 
void accumulateTimeEnd (std::atomic< CountAndTime *> &countAndTime, double &accumulatedTime)
 
void lastPostEvent (double curr_event_time, unsigned int index, StreamContext const &iStream)
 
void postBeginJob ()
 
double postCommon () const
 
void postEndJob ()
 
void postEvent (StreamContext const &)
 
void postGlobalBeginLumi (GlobalContext const &)
 
void postGlobalBeginRun (GlobalContext const &)
 
void postModule (ModuleDescription const &md)
 
void postModuleEvent (StreamContext const &, ModuleCallingContext const &)
 
void postModuleGlobal (GlobalContext const &, ModuleCallingContext const &)
 
void postModuleStream (StreamContext const &, ModuleCallingContext const &)
 
void postOpenFile (std::string const &)
 
void postSourceEvent (StreamID)
 
void postSourceLumi (LuminosityBlockIndex)
 
void postSourceRun (RunIndex)
 
void preBeginJob (PathsAndConsumesOfModulesBase const &, ProcessContext const &)
 
void preEvent (StreamContext const &)
 
void preModule (ModuleDescription const &md)
 
void preModuleGlobal (GlobalContext const &, ModuleCallingContext const &)
 
void preModuleStream (StreamContext const &, ModuleCallingContext const &)
 
void preOpenFile (std::string const &)
 
void preSourceEvent (StreamID)
 
void preSourceLumi (LuminosityBlockIndex)
 
void preSourceRun (RunIndex)
 

Private Attributes

double accumulatedTimeForGet_
 
double accumulatedTimeForLock_
 
std::atomic< unsigned long > begin_lumi_count_
 
std::atomic< unsigned long > begin_run_count_
 
bool configuredInTopLevelProcess_
 
std::atomic< CountAndTime * > countAndTimeForGet_
 
std::atomic< CountAndTime * > countAndTimeForLock_
 
CountAndTime countAndTimeZero_
 
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPostEvent_
 
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPreEvent_
 
std::vector< double > curr_events_time_
 
double curr_job_cpu_
 
double curr_job_time_
 
std::atomic< double > end_loop_cpu_
 
std::atomic< double > end_loop_time_
 
std::atomic< double > extra_job_cpu_
 
std::vector< double > max_events_time_
 
std::vector< double > min_events_time_
 
unsigned int nStreams_
 
unsigned int nSubProcesses_
 
unsigned int nThreads_
 
bool report_summary_
 
std::vector< double > sum_events_time_
 
bool summary_only_
 
double threshold_
 
std::atomic< unsigned long > total_event_count_
 

Detailed Description

Definition at line 46 of file Timing.cc.

Constructor & Destructor Documentation

◆ Timing()

edm::service::Timing::Timing ( ParameterSet const &  iPS,
ActivityRegistry iRegistry 
)

Definition at line 217 of file Timing.cc.

218  : curr_job_time_(0.),
219  curr_job_cpu_(0.),
220  extra_job_cpu_(0.0),
221  end_loop_time_(0.0),
222  end_loop_cpu_(0.0),
224  summary_only_(iPS.getUntrackedParameter<bool>("summaryOnly")),
225  report_summary_(iPS.getUntrackedParameter<bool>("useJobReport")),
226  threshold_(iPS.getUntrackedParameter<double>("excessiveTimeThreshold")),
231  begin_run_count_(0),
232  countAndTimeZero_{0, 0.0},
238  nSubProcesses_{0} {
239  iRegistry.watchPreBeginJob(this, &Timing::preBeginJob);
240  iRegistry.watchPostBeginJob(this, &Timing::postBeginJob);
241  iRegistry.preEndJobSignal_.connect([this]() {
243  end_loop_cpu_ = getCPU();
244  });
245  iRegistry.watchPostEndJob(this, &Timing::postEndJob);
246 
247  iRegistry.watchPreEvent(this, &Timing::preEvent);
248  iRegistry.watchPostEvent(this, &Timing::postEvent);
249 
250  bool checkThreshold = true;
251  if (threshold_ <= 0.0) {
252  //we need to ignore the threshold check
254  checkThreshold = false;
255  }
256 
257  if ((not summary_only_) || (checkThreshold)) {
258  iRegistry.watchPreModuleEvent(this, &Timing::preModuleStream);
259  iRegistry.watchPostModuleEvent(this, &Timing::postModuleEvent);
260  }
261  if (checkThreshold) {
262  iRegistry.watchPreSourceEvent(this, &Timing::preSourceEvent);
263  iRegistry.watchPostSourceEvent(this, &Timing::postSourceEvent);
264 
265  iRegistry.watchPreSourceLumi(this, &Timing::preSourceLumi);
266  iRegistry.watchPostSourceLumi(this, &Timing::postSourceLumi);
267 
268  iRegistry.watchPreSourceRun(this, &Timing::preSourceRun);
269  iRegistry.watchPostSourceRun(this, &Timing::postSourceRun);
270 
271  iRegistry.watchPreOpenFile(this, &Timing::preOpenFile);
272  iRegistry.watchPostOpenFile(this, &Timing::postOpenFile);
273 
274  iRegistry.watchPreEventReadFromSource(this, &Timing::preModuleStream);
275  iRegistry.watchPostEventReadFromSource(this, &Timing::postModuleStream);
276 
277  iRegistry.watchPreModuleConstruction(this, &Timing::preModule);
278  iRegistry.watchPostModuleConstruction(this, &Timing::postModule);
279 
280  iRegistry.watchPreModuleDestruction(this, &Timing::preModule);
281  iRegistry.watchPostModuleDestruction(this, &Timing::postModule);
282 
283  iRegistry.watchPreModuleBeginJob(this, &Timing::preModule);
284  iRegistry.watchPostModuleBeginJob(this, &Timing::postModule);
285 
286  iRegistry.watchPreModuleEndJob(this, &Timing::preModule);
287  iRegistry.watchPostModuleEndJob(this, &Timing::postModule);
288 
289  iRegistry.watchPreModuleStreamBeginRun(this, &Timing::preModuleStream);
290  iRegistry.watchPostModuleStreamBeginRun(this, &Timing::postModuleStream);
291  iRegistry.watchPreModuleStreamEndRun(this, &Timing::preModuleStream);
292  iRegistry.watchPostModuleStreamEndRun(this, &Timing::postModuleStream);
293 
294  iRegistry.watchPreModuleStreamBeginLumi(this, &Timing::preModuleStream);
295  iRegistry.watchPostModuleStreamBeginLumi(this, &Timing::postModuleStream);
296  iRegistry.watchPreModuleStreamEndLumi(this, &Timing::preModuleStream);
297  iRegistry.watchPostModuleStreamEndLumi(this, &Timing::postModuleStream);
298 
299  iRegistry.watchPreModuleGlobalBeginRun(this, &Timing::preModuleGlobal);
300  iRegistry.watchPostModuleGlobalBeginRun(this, &Timing::postModuleGlobal);
301  iRegistry.watchPreModuleGlobalEndRun(this, &Timing::preModuleGlobal);
302  iRegistry.watchPostModuleGlobalEndRun(this, &Timing::postModuleGlobal);
303 
304  iRegistry.watchPreModuleGlobalBeginLumi(this, &Timing::preModuleGlobal);
305  iRegistry.watchPostModuleGlobalBeginLumi(this, &Timing::postModuleGlobal);
306  iRegistry.watchPreModuleGlobalEndLumi(this, &Timing::preModuleGlobal);
307  iRegistry.watchPostModuleGlobalEndLumi(this, &Timing::postModuleGlobal);
308 
309  iRegistry.watchPreSourceConstruction(this, &Timing::preModule);
310  iRegistry.watchPostSourceConstruction(this, &Timing::postModule);
311  }
312 
313  iRegistry.watchPostGlobalBeginRun(this, &Timing::postGlobalBeginRun);
314  iRegistry.watchPostGlobalBeginLumi(this, &Timing::postGlobalBeginLumi);
315 
316  iRegistry.preallocateSignal_.connect([this](service::SystemBounds const& iBounds) {
317  nStreams_ = iBounds.maxNumberOfStreams();
318  nThreads_ = iBounds.maxNumberOfThreads();
319  curr_events_time_.resize(nStreams_, 0.);
320  sum_events_time_.resize(nStreams_, 0.);
321  max_events_time_.resize(nStreams_, 0.);
322  min_events_time_.resize(nStreams_, 1.E6);
323  for (unsigned int i = 0; i < nStreams_; ++i) {
324  countSubProcessesPreEvent_.emplace_back(std::make_unique<std::atomic<unsigned int>>(0));
325  countSubProcessesPostEvent_.emplace_back(std::make_unique<std::atomic<unsigned int>>(0));
326  }
327  });
328  }
std::vector< double > sum_events_time_
Definition: Timing.cc:118
double curr_job_time_
Definition: Timing.cc:103
std::vector< double > max_events_time_
Definition: Timing.cc:116
std::vector< double > curr_events_time_
Definition: Timing.cc:109
void preModule(ModuleDescription const &md)
Definition: Timing.cc:560
static double getCPU()
Definition: Timing.cc:174
void postEvent(StreamContext const &)
Definition: Timing.cc:501
void preModuleStream(StreamContext const &, ModuleCallingContext const &)
Definition: Timing.cc:588
double curr_job_cpu_
Definition: Timing.cc:104
std::atomic< unsigned long > begin_lumi_count_
Definition: Timing.cc:120
void preSourceLumi(LuminosityBlockIndex)
Definition: Timing.cc:548
unsigned int nThreads_
Definition: Timing.cc:123
unsigned int nStreams_
Definition: Timing.cc:122
void preModuleGlobal(GlobalContext const &, ModuleCallingContext const &)
Definition: Timing.cc:564
void postModule(ModuleDescription const &md)
Definition: Timing.cc:562
void postGlobalBeginRun(GlobalContext const &)
Definition: Timing.cc:570
void preSourceRun(RunIndex)
Definition: Timing.cc:552
void postModuleStream(StreamContext const &, ModuleCallingContext const &)
Definition: Timing.cc:592
void preOpenFile(std::string const &)
Definition: Timing.cc:556
std::atomic< CountAndTime * > countAndTimeForGet_
Definition: Timing.cc:130
std::atomic< double > end_loop_time_
Definition: Timing.cc:107
void postModuleEvent(StreamContext const &, ModuleCallingContext const &)
Definition: Timing.cc:531
void postSourceLumi(LuminosityBlockIndex)
Definition: Timing.cc:550
std::atomic< double > end_loop_cpu_
Definition: Timing.cc:108
std::atomic< CountAndTime * > countAndTimeForLock_
Definition: Timing.cc:127
double accumulatedTimeForLock_
Definition: Timing.cc:128
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPreEvent_
Definition: Timing.cc:133
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPostEvent_
Definition: Timing.cc:134
void postOpenFile(std::string const &)
Definition: Timing.cc:558
void postGlobalBeginLumi(GlobalContext const &)
Definition: Timing.cc:579
std::atomic< unsigned long > begin_run_count_
Definition: Timing.cc:121
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:119
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
void postSourceRun(RunIndex)
Definition: Timing.cc:554
double accumulatedTimeForGet_
Definition: Timing.cc:131
void postModuleGlobal(GlobalContext const &, ModuleCallingContext const &)
Definition: Timing.cc:568
void preBeginJob(PathsAndConsumesOfModulesBase const &, ProcessContext const &)
Definition: Timing.cc:353
CountAndTime countAndTimeZero_
Definition: Timing.cc:125
static double getTime()
Definition: Timing.cc:157
void postSourceEvent(StreamID)
Definition: Timing.cc:546
std::atomic< double > extra_job_cpu_
Definition: Timing.cc:105
void preSourceEvent(StreamID)
Definition: Timing.cc:544
void preEvent(StreamContext const &)
Definition: Timing.cc:484
std::vector< double > min_events_time_
Definition: Timing.cc:117
unsigned int nSubProcesses_
Definition: Timing.cc:137

◆ ~Timing()

edm::service::Timing::~Timing ( )
override

Definition at line 330 of file Timing.cc.

330 {}

Member Function Documentation

◆ accumulateTimeBegin()

void edm::service::Timing::accumulateTimeBegin ( std::atomic< CountAndTime *> &  countAndTime,
double &  accumulatedTime 
)
private

Definition at line 608 of file Timing.cc.

References edm::service::Timing::CountAndTime::count_, countAndTimeZero_, and edm::service::getTime().

608  {
609  double newTime = getTime();
610  auto newStat = std::make_unique<CountAndTime>(0, newTime);
611 
612  CountAndTime* oldStat = countAndTime.load();
613  while (true) {
614  if (oldStat == nullptr) {
615  oldStat = countAndTime.load();
616  } else if (countAndTime.compare_exchange_strong(oldStat, nullptr)) {
617  break;
618  }
619  }
620 
621  newStat->count_ = oldStat->count_ + 1;
622  if (oldStat->count_ != 0) {
623  accumulatedTime += (newTime - oldStat->time_) * oldStat->count_;
624  }
625  countAndTime.store(newStat.release());
626  if (oldStat != &countAndTimeZero_) {
627  delete oldStat;
628  }
629  }
CountAndTime countAndTimeZero_
Definition: Timing.cc:125
static double getTime()
Definition: Timing.cc:157

◆ accumulateTimeEnd()

void edm::service::Timing::accumulateTimeEnd ( std::atomic< CountAndTime *> &  countAndTime,
double &  accumulatedTime 
)
private

Definition at line 631 of file Timing.cc.

References edm::service::Timing::CountAndTime::count_, countAndTimeZero_, cppFunctionSkipper::exception, edm::service::getTime(), and edm::service::Timing::CountAndTime::time_.

631  {
632  double newTime = getTime();
633 
634  CountAndTime* oldStat = countAndTime.load();
635  while (true) {
636  if (oldStat == nullptr) {
637  oldStat = countAndTime.load();
638  } else if (countAndTime.compare_exchange_strong(oldStat, nullptr)) {
639  break;
640  }
641  }
642 
643  if (oldStat->count_ == 1) {
644  accumulatedTime += newTime - oldStat->time_;
645  countAndTime.store(&countAndTimeZero_);
646  } else {
647  try {
648  auto newStat = std::make_unique<CountAndTime>(oldStat->count_ - 1, newTime);
649  accumulatedTime += (newTime - oldStat->time_) * oldStat->count_;
650  countAndTime.store(newStat.release());
651  } catch (std::exception&) {
652  countAndTime.store(oldStat);
653  throw;
654  }
655  }
656  delete oldStat;
657  }
CountAndTime countAndTimeZero_
Definition: Timing.cc:125
static double getTime()
Definition: Timing.cc:157

◆ addToCPUTime()

void edm::service::Timing::addToCPUTime ( double  iTime)
overridevirtual

Extra CPU time used by a job but not seen by cmsRun The value should be in seconds. This function is safe to call from multiple threads

Implements edm::TimingServiceBase.

Definition at line 332 of file Timing.cc.

References extra_job_cpu_.

332  {
333  //For accounting purposes we effectively can say we started earlier
334  double expected = extra_job_cpu_.load();
335  while (not extra_job_cpu_.compare_exchange_strong(expected, expected + iTime)) {
336  }
337  }
std::atomic< double > extra_job_cpu_
Definition: Timing.cc:105

◆ fillDescriptions()

void edm::service::Timing::fillDescriptions ( edm::ConfigurationDescriptions descriptions)
static

Definition at line 341 of file Timing.cc.

References edm::ConfigurationDescriptions::add(), submitPVResolutionJobs::desc, and edm::ConfigurationDescriptions::setComment().

341  {
343  desc.addUntracked<bool>("summaryOnly", false)->setComment("If 'true' do not report timing for each event");
344  desc.addUntracked<bool>("useJobReport", true)->setComment("If 'true' write summary information to JobReport");
345  desc.addUntracked<double>("excessiveTimeThreshold", 0.)
346  ->setComment(
347  "Amount of time in seconds before reporting a module or source has taken excessive time. A value of 0.0 "
348  "turns off this reporting.");
349  descriptions.add("Timing", desc);
350  descriptions.setComment("This service reports the time it takes to run each module in a job.");
351  }
void setComment(std::string const &value)
void add(std::string const &label, ParameterSetDescription const &psetDescription)

◆ getTotalCPU()

double edm::service::Timing::getTotalCPU ( ) const
overridevirtual

CPU time used by this process and all its children. The value returned should be in seconds.

Implements edm::TimingServiceBase.

Definition at line 339 of file Timing.cc.

References edm::service::getCPU().

339 { return getCPU(); }
static double getCPU()
Definition: Timing.cc:174

◆ lastPostEvent()

void edm::service::Timing::lastPostEvent ( double  curr_event_time,
unsigned int  index,
StreamContext const &  iStream 
)
private

Definition at line 517 of file Timing.cc.

References edm::StreamContext::eventID(), max_events_time_, min_events_time_, sum_events_time_, summary_only_, and total_event_count_.

Referenced by postEvent().

517  {
518  sum_events_time_[index] += curr_event_time;
519 
520  if (not summary_only_) {
521  auto const& eventID = iStream.eventID();
522  LogPrint("TimeEvent") << "TimeEvent> " << eventID.event() << " " << eventID.run() << " " << curr_event_time;
523  }
524  if (curr_event_time > max_events_time_[index])
525  max_events_time_[index] = curr_event_time;
526  if (curr_event_time < min_events_time_[index])
527  min_events_time_[index] = curr_event_time;
529  }
std::vector< double > sum_events_time_
Definition: Timing.cc:118
std::vector< double > max_events_time_
Definition: Timing.cc:116
Log< level::Warning, true > LogPrint
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:119
std::vector< double > min_events_time_
Definition: Timing.cc:117

◆ postBeginJob()

void edm::service::Timing::postBeginJob ( )
private

Definition at line 361 of file Timing.cc.

References configuredInTopLevelProcess_, curr_job_cpu_, curr_job_time_, edm::service::getCPU(), edm::service::getTime(), and summary_only_.

361  {
363  return;
364  }
366  curr_job_cpu_ = getCPU();
367 
368  if (not summary_only_) {
369  LogImportant("TimeReport") << "TimeReport> Report activated"
370  << "\n"
371  << "TimeReport> Report columns headings for events: "
372  << "eventnum runnum timetaken\n"
373  << "TimeReport> Report columns headings for modules: "
374  << "eventnum runnum modulelabel modulename timetakeni\n"
375  << "TimeReport> JobTime=" << curr_job_time_ << " JobCPU=" << curr_job_cpu_ << "\n";
376  }
377  }
double curr_job_time_
Definition: Timing.cc:103
static double getCPU()
Definition: Timing.cc:174
double curr_job_cpu_
Definition: Timing.cc:104
Log< level::Error, true > LogImportant
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
static double getTime()
Definition: Timing.cc:157

◆ postCommon()

double edm::service::Timing::postCommon ( ) const
private

Definition at line 594 of file Timing.cc.

References configuredInTopLevelProcess_, edm::service::popStack(), submitPVValidationJobs::t, and threshold_.

Referenced by postModule(), postModuleEvent(), postModuleGlobal(), postModuleStream(), postOpenFile(), postSourceEvent(), postSourceLumi(), and postSourceRun().

594  {
596  return 0.0;
597  }
598  double t = popStack();
599  if (t > threshold_) {
600  LogError("ExcessiveTime")
601  << "ExcessiveTime: Module used " << t
602  << " seconds of time which exceeds the error threshold configured in the Timing Service of " << threshold_
603  << " seconds.";
604  }
605  return t;
606  }
Log< level::Error, false > LogError
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
static double popStack()
Definition: Timing.cc:200

◆ postEndJob()

void edm::service::Timing::postEndJob ( )
private

Definition at line 379 of file Timing.cc.

References accumulatedTimeForGet_, accumulatedTimeForLock_, begin_lumi_count_, begin_run_count_, configuredInTopLevelProcess_, curr_job_cpu_, curr_job_time_, edm::service::d2str(), end_loop_cpu_, end_loop_time_, extra_job_cpu_, edm::service::getChildrenCPU(), edm::service::getCPU(), edm::service::getTime(), edm::TimingServiceBase::jobStartTime(), max_events_time_, min_events_time_, nStreams_, nThreads_, report_summary_, sum_events_time_, submitPVValidationJobs::t, total_event_count_, and edm::service::ui2str().

379  {
381  LogImportant("TimeReport") << "\nTimeReport> This instance of the Timing Service will be disabled because it "
382  "is configured in a SubProcess.\n"
383  << "If multiple instances of the TimingService were configured only the one in the "
384  "top level process will function.\n"
385  << "The other instance(s) will simply print this message and do nothing.\n\n";
386  return;
387  }
388 
389  const double job_end_time = getTime();
390  const double job_end_cpu = getCPU();
391  double total_job_time = job_end_time - jobStartTime();
392 
393  double total_job_cpu = job_end_cpu + extra_job_cpu_;
394 
395  const double job_end_children_cpu = getChildrenCPU();
396 
397  const double total_initialization_time = curr_job_time_ - jobStartTime();
398  const double total_initialization_cpu = curr_job_cpu_;
399 
400  if (0.0 == jobStartTime()) {
401  //did not capture beginning time
402  total_job_time = job_end_time - curr_job_time_;
403  total_job_cpu = job_end_cpu + extra_job_cpu_ - curr_job_cpu_;
404  }
405 
406  double min_event_time = *(std::min_element(min_events_time_.begin(), min_events_time_.end()));
407  double max_event_time = *(std::max_element(max_events_time_.begin(), max_events_time_.end()));
408 
409  auto total_loop_time = end_loop_time_ - curr_job_time_;
410  auto total_loop_cpu = end_loop_cpu_ + extra_job_cpu_ - curr_job_cpu_;
411 
412  if (end_loop_time_ == 0.0) {
413  total_loop_time = 0.0;
414  total_loop_cpu = 0.0;
415  }
416 
417  double sum_all_events_time = 0;
418  for (auto t : sum_events_time_) {
419  sum_all_events_time += t;
420  }
421 
422  double average_event_time = 0.0;
423  if (total_event_count_ != 0) {
424  average_event_time = sum_all_events_time / total_event_count_;
425  }
426 
427  double event_throughput = 0.0;
428  if (total_loop_time != 0.0) {
429  event_throughput = total_event_count_ / total_loop_time;
430  }
431 
432  LogImportant("TimeReport") << "TimeReport> Time report complete in " << total_job_time << " seconds"
433  << "\n"
434  << " Time Summary: \n"
435  << " - Min event: " << min_event_time << "\n"
436  << " - Max event: " << max_event_time << "\n"
437  << " - Avg event: " << average_event_time << "\n"
438  << " - Total loop: " << total_loop_time << "\n"
439  << " - Total init: " << total_initialization_time << "\n"
440  << " - Total job: " << total_job_time << "\n"
441  << " - EventSetup Lock: " << accumulatedTimeForLock_ << "\n"
442  << " - EventSetup Get: " << accumulatedTimeForGet_ << "\n"
443  << " Event Throughput: " << event_throughput << " ev/s\n"
444  << " CPU Summary: \n"
445  << " - Total loop: " << total_loop_cpu << "\n"
446  << " - Total init: " << total_initialization_cpu << "\n"
447  << " - Total extra: " << extra_job_cpu_ << "\n"
448  << " - Total children: " << job_end_children_cpu << "\n"
449  << " - Total job: " << total_job_cpu << "\n"
450  << " Processing Summary: \n"
451  << " - Number of Events: " << total_event_count_ << "\n"
452  << " - Number of Global Begin Lumi Calls: " << begin_lumi_count_ << "\n"
453  << " - Number of Global Begin Run Calls: " << begin_run_count_ << "\n";
454 
455  if (report_summary_) {
456  Service<JobReport> reportSvc;
457  std::map<std::string, std::string> reportData;
458 
459  reportData.insert(std::make_pair("MinEventTime", d2str(min_event_time)));
460  reportData.insert(std::make_pair("MaxEventTime", d2str(max_event_time)));
461  reportData.insert(std::make_pair("AvgEventTime", d2str(average_event_time)));
462  reportData.insert(std::make_pair("EventThroughput", d2str(event_throughput)));
463  reportData.insert(std::make_pair("TotalJobTime", d2str(total_job_time)));
464  reportData.insert(std::make_pair("TotalJobCPU", d2str(total_job_cpu)));
465  reportData.insert(std::make_pair("TotalJobChildrenCPU", d2str(job_end_children_cpu)));
466  reportData.insert(std::make_pair("TotalLoopTime", d2str(total_loop_time)));
467  reportData.insert(std::make_pair("TotalLoopCPU", d2str(total_loop_cpu)));
468  reportData.insert(std::make_pair("TotalInitTime", d2str(total_initialization_time)));
469  reportData.insert(std::make_pair("TotalInitCPU", d2str(total_initialization_cpu)));
470  reportData.insert(std::make_pair("NumberOfStreams", ui2str(nStreams_)));
471  reportData.insert(std::make_pair("NumberOfThreads", ui2str(nThreads_)));
472  reportData.insert(std::make_pair("EventSetup Lock", d2str(accumulatedTimeForLock_)));
473  reportData.insert(std::make_pair("EventSetup Get", d2str(accumulatedTimeForGet_)));
474  reportSvc->reportPerformanceSummary("Timing", reportData);
475 
476  std::map<std::string, std::string> reportData1;
477  reportData1.insert(std::make_pair("NumberEvents", ui2str(total_event_count_)));
478  reportData1.insert(std::make_pair("NumberBeginLumiCalls", ui2str(begin_lumi_count_)));
479  reportData1.insert(std::make_pair("NumberBeginRunCalls", ui2str(begin_run_count_)));
480  reportSvc->reportPerformanceSummary("ProcessingSummary", reportData1);
481  }
482  }
std::vector< double > sum_events_time_
Definition: Timing.cc:118
double curr_job_time_
Definition: Timing.cc:103
std::vector< double > max_events_time_
Definition: Timing.cc:116
static double getCPU()
Definition: Timing.cc:174
double curr_job_cpu_
Definition: Timing.cc:104
std::atomic< unsigned long > begin_lumi_count_
Definition: Timing.cc:120
unsigned int nThreads_
Definition: Timing.cc:123
unsigned int nStreams_
Definition: Timing.cc:122
std::atomic< double > end_loop_time_
Definition: Timing.cc:107
Log< level::Error, true > LogImportant
std::atomic< double > end_loop_cpu_
Definition: Timing.cc:108
double accumulatedTimeForLock_
Definition: Timing.cc:128
static double jobStartTime()
static std::string ui2str(unsigned int i)
Definition: Timing.cc:151
std::atomic< unsigned long > begin_run_count_
Definition: Timing.cc:121
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:119
static std::string d2str(double d)
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
double accumulatedTimeForGet_
Definition: Timing.cc:131
static double getTime()
Definition: Timing.cc:157
std::atomic< double > extra_job_cpu_
Definition: Timing.cc:105
static double getChildrenCPU()
Definition: Timing.cc:164
std::vector< double > min_events_time_
Definition: Timing.cc:117

◆ postEvent()

void edm::service::Timing::postEvent ( StreamContext const &  iStream)
private

Definition at line 501 of file Timing.cc.

References configuredInTopLevelProcess_, submitPVResolutionJobs::count, countSubProcessesPostEvent_, curr_events_time_, edm::service::getTime(), lastPostEvent(), nSubProcesses_, edm::StreamContext::streamID(), and edm::StreamID::value().

501  {
503  return;
504  }
505  auto index = iStream.streamID().value();
506  if (nSubProcesses_ == 0u) {
508  } else {
509  unsigned int count = ++(*countSubProcessesPostEvent_[index]);
510  if (count == (nSubProcesses_ + 1)) {
513  }
514  }
515  }
std::vector< double > curr_events_time_
Definition: Timing.cc:109
void lastPostEvent(double curr_event_time, unsigned int index, StreamContext const &iStream)
Definition: Timing.cc:517
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPostEvent_
Definition: Timing.cc:134
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
static double getTime()
Definition: Timing.cc:157
unsigned int nSubProcesses_
Definition: Timing.cc:137

◆ postGlobalBeginLumi()

void edm::service::Timing::postGlobalBeginLumi ( GlobalContext const &  gc)
private

Definition at line 579 of file Timing.cc.

References begin_lumi_count_, configuredInTopLevelProcess_, edm::ProcessContext::isSubProcess(), and edm::GlobalContext::processContext().

579  {
581  return;
582  }
583  if (!gc.processContext()->isSubProcess()) {
585  }
586  }
std::atomic< unsigned long > begin_lumi_count_
Definition: Timing.cc:120
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ postGlobalBeginRun()

void edm::service::Timing::postGlobalBeginRun ( GlobalContext const &  gc)
private

Definition at line 570 of file Timing.cc.

References begin_run_count_, configuredInTopLevelProcess_, edm::ProcessContext::isSubProcess(), and edm::GlobalContext::processContext().

570  {
572  return;
573  }
574  if (!gc.processContext()->isSubProcess()) {
576  }
577  }
std::atomic< unsigned long > begin_run_count_
Definition: Timing.cc:121
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ postModule()

void edm::service::Timing::postModule ( ModuleDescription const &  md)
private

Definition at line 562 of file Timing.cc.

References postCommon().

562 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postModuleEvent()

void edm::service::Timing::postModuleEvent ( StreamContext const &  iStream,
ModuleCallingContext const &  iModule 
)
private

Definition at line 531 of file Timing.cc.

References configuredInTopLevelProcess_, submitPVResolutionJobs::desc, edm::StreamContext::eventID(), edm::ModuleCallingContext::moduleDescription(), postCommon(), summary_only_, and submitPVValidationJobs::t.

531  {
533  return;
534  }
535  auto const& eventID = iStream.eventID();
536  auto const& desc = *(iModule.moduleDescription());
537  double t = postCommon();
538  if (not summary_only_) {
539  LogPrint("TimeModule") << "TimeModule> " << eventID.event() << " " << eventID.run() << " " << desc.moduleLabel()
540  << " " << desc.moduleName() << " " << t;
541  }
542  }
double postCommon() const
Definition: Timing.cc:594
Log< level::Warning, true > LogPrint
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ postModuleGlobal()

void edm::service::Timing::postModuleGlobal ( GlobalContext const &  ,
ModuleCallingContext const &  mcc 
)
private

Definition at line 568 of file Timing.cc.

References postCommon().

568 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postModuleStream()

void edm::service::Timing::postModuleStream ( StreamContext const &  ,
ModuleCallingContext const &  mcc 
)
private

Definition at line 592 of file Timing.cc.

References postCommon().

592 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postOpenFile()

void edm::service::Timing::postOpenFile ( std::string const &  lfn)
private

Definition at line 558 of file Timing.cc.

References postCommon().

558 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postSourceEvent()

void edm::service::Timing::postSourceEvent ( StreamID  sid)
private

Definition at line 546 of file Timing.cc.

References postCommon().

546 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postSourceLumi()

void edm::service::Timing::postSourceLumi ( LuminosityBlockIndex  index)
private

Definition at line 550 of file Timing.cc.

References postCommon().

550 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ postSourceRun()

void edm::service::Timing::postSourceRun ( RunIndex  index)
private

Definition at line 554 of file Timing.cc.

References postCommon().

554 { postCommon(); }
double postCommon() const
Definition: Timing.cc:594

◆ preBeginJob()

void edm::service::Timing::preBeginJob ( PathsAndConsumesOfModulesBase const &  pathsAndConsumes,
ProcessContext const &  pc 
)
private

Definition at line 353 of file Timing.cc.

References configuredInTopLevelProcess_, edm::ProcessContext::isSubProcess(), and nSubProcesses_.

353  {
354  if (pc.isSubProcess()) {
355  ++nSubProcesses_;
356  } else {
358  }
359  }
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
unsigned int nSubProcesses_
Definition: Timing.cc:137

◆ preEvent()

void edm::service::Timing::preEvent ( StreamContext const &  iStream)
private

Definition at line 484 of file Timing.cc.

References configuredInTopLevelProcess_, submitPVResolutionJobs::count, countSubProcessesPreEvent_, curr_events_time_, edm::service::getTime(), nSubProcesses_, edm::StreamContext::streamID(), and edm::StreamID::value().

484  {
486  return;
487  }
488  auto index = iStream.streamID().value();
489  if (nSubProcesses_ == 0u) {
491  } else {
492  unsigned int count = ++(*countSubProcessesPreEvent_[index]);
493  if (count == 1) {
495  } else if (count == (nSubProcesses_ + 1)) {
497  }
498  }
499  }
std::vector< double > curr_events_time_
Definition: Timing.cc:109
std::vector< std::unique_ptr< std::atomic< unsigned int > > > countSubProcessesPreEvent_
Definition: Timing.cc:133
bool configuredInTopLevelProcess_
Definition: Timing.cc:136
static double getTime()
Definition: Timing.cc:157
unsigned int nSubProcesses_
Definition: Timing.cc:137

◆ preModule()

void edm::service::Timing::preModule ( ModuleDescription const &  md)
private

Definition at line 560 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preModuleGlobal()

void edm::service::Timing::preModuleGlobal ( GlobalContext const &  ,
ModuleCallingContext const &   
)
private

Definition at line 564 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

564  {
566  }
static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preModuleStream()

void edm::service::Timing::preModuleStream ( StreamContext const &  ,
ModuleCallingContext const &   
)
private

Definition at line 588 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

588  {
590  }
static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preOpenFile()

void edm::service::Timing::preOpenFile ( std::string const &  lfn)
private

Definition at line 556 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preSourceEvent()

void edm::service::Timing::preSourceEvent ( StreamID  sid)
private

Definition at line 544 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preSourceLumi()

void edm::service::Timing::preSourceLumi ( LuminosityBlockIndex  index)
private

Definition at line 548 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

◆ preSourceRun()

void edm::service::Timing::preSourceRun ( RunIndex  index)
private

Definition at line 552 of file Timing.cc.

References configuredInTopLevelProcess_, and edm::service::pushStack().

static void pushStack(bool configuredInTopLevelProcess)
Definition: Timing.cc:209
bool configuredInTopLevelProcess_
Definition: Timing.cc:136

Member Data Documentation

◆ accumulatedTimeForGet_

double edm::service::Timing::accumulatedTimeForGet_
private

Definition at line 131 of file Timing.cc.

Referenced by postEndJob().

◆ accumulatedTimeForLock_

double edm::service::Timing::accumulatedTimeForLock_
private

Definition at line 128 of file Timing.cc.

Referenced by postEndJob().

◆ begin_lumi_count_

std::atomic<unsigned long> edm::service::Timing::begin_lumi_count_
private

Definition at line 120 of file Timing.cc.

Referenced by postEndJob(), and postGlobalBeginLumi().

◆ begin_run_count_

std::atomic<unsigned long> edm::service::Timing::begin_run_count_
private

Definition at line 121 of file Timing.cc.

Referenced by postEndJob(), and postGlobalBeginRun().

◆ configuredInTopLevelProcess_

bool edm::service::Timing::configuredInTopLevelProcess_
private

◆ countAndTimeForGet_

std::atomic<CountAndTime*> edm::service::Timing::countAndTimeForGet_
private

Definition at line 130 of file Timing.cc.

◆ countAndTimeForLock_

std::atomic<CountAndTime*> edm::service::Timing::countAndTimeForLock_
private

Definition at line 127 of file Timing.cc.

◆ countAndTimeZero_

CountAndTime edm::service::Timing::countAndTimeZero_
private

Definition at line 125 of file Timing.cc.

Referenced by accumulateTimeBegin(), and accumulateTimeEnd().

◆ countSubProcessesPostEvent_

std::vector<std::unique_ptr<std::atomic<unsigned int> > > edm::service::Timing::countSubProcessesPostEvent_
private

Definition at line 134 of file Timing.cc.

Referenced by postEvent().

◆ countSubProcessesPreEvent_

std::vector<std::unique_ptr<std::atomic<unsigned int> > > edm::service::Timing::countSubProcessesPreEvent_
private

Definition at line 133 of file Timing.cc.

Referenced by preEvent().

◆ curr_events_time_

std::vector<double> edm::service::Timing::curr_events_time_
private

Definition at line 109 of file Timing.cc.

Referenced by postEvent(), and preEvent().

◆ curr_job_cpu_

double edm::service::Timing::curr_job_cpu_
private

Definition at line 104 of file Timing.cc.

Referenced by postBeginJob(), and postEndJob().

◆ curr_job_time_

double edm::service::Timing::curr_job_time_
private

Definition at line 103 of file Timing.cc.

Referenced by postBeginJob(), and postEndJob().

◆ end_loop_cpu_

std::atomic<double> edm::service::Timing::end_loop_cpu_
private

Definition at line 108 of file Timing.cc.

Referenced by postEndJob().

◆ end_loop_time_

std::atomic<double> edm::service::Timing::end_loop_time_
private

Definition at line 107 of file Timing.cc.

Referenced by postEndJob().

◆ extra_job_cpu_

std::atomic<double> edm::service::Timing::extra_job_cpu_
private

Definition at line 105 of file Timing.cc.

Referenced by addToCPUTime(), and postEndJob().

◆ max_events_time_

std::vector<double> edm::service::Timing::max_events_time_
private

Definition at line 116 of file Timing.cc.

Referenced by lastPostEvent(), and postEndJob().

◆ min_events_time_

std::vector<double> edm::service::Timing::min_events_time_
private

Definition at line 117 of file Timing.cc.

Referenced by lastPostEvent(), and postEndJob().

◆ nStreams_

unsigned int edm::service::Timing::nStreams_
private

Definition at line 122 of file Timing.cc.

Referenced by postEndJob().

◆ nSubProcesses_

unsigned int edm::service::Timing::nSubProcesses_
private

Definition at line 137 of file Timing.cc.

Referenced by postEvent(), preBeginJob(), and preEvent().

◆ nThreads_

unsigned int edm::service::Timing::nThreads_
private

Definition at line 123 of file Timing.cc.

Referenced by postEndJob().

◆ report_summary_

bool edm::service::Timing::report_summary_
private

Definition at line 111 of file Timing.cc.

Referenced by postEndJob().

◆ sum_events_time_

std::vector<double> edm::service::Timing::sum_events_time_
private

Definition at line 118 of file Timing.cc.

Referenced by lastPostEvent(), and postEndJob().

◆ summary_only_

bool edm::service::Timing::summary_only_
private

Definition at line 110 of file Timing.cc.

Referenced by lastPostEvent(), postBeginJob(), and postModuleEvent().

◆ threshold_

double edm::service::Timing::threshold_
private

Definition at line 112 of file Timing.cc.

Referenced by postCommon().

◆ total_event_count_

std::atomic<unsigned long> edm::service::Timing::total_event_count_
private

Definition at line 119 of file Timing.cc.

Referenced by lastPostEvent(), and postEndJob().