Back to home page

Project CMSSW displayed by LXR

 
 

    


File indexing completed on 2025-04-30 22:24:13

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