Services/plugins/Timing.cc

0001 // -*- C++ -*-
0002 //
0003 // Package:     Services
0004 // Class  :     Timing
0005 //
0006 // Implementation:
0007 //
0008 // Original Author:  Jim Kowalkowski
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   }  // namespace eventsetup
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_;               // seconds
0104       double curr_job_cpu_;                // seconds
0105       std::atomic<double> extra_job_cpu_;  //seconds
0106                                            //use last run time for determining end of processing
0107       std::atomic<double> end_loop_time_;
0108       std::atomic<double> end_loop_cpu_;
0109       std::vector<double> curr_events_time_;  // seconds
0110       bool summary_only_;
0111       bool report_summary_;
0112       double threshold_;
0113       //
0114       // Min Max and total event times for each Stream.
0115       //  Used for summary at end of job
0116       std::vector<double> max_events_time_;  // seconds
0117       std::vector<double> min_events_time_;  // seconds
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   }  // namespace service
0140 }  // namespace edm
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       // User code
0180       totalCPUTime = (double)usage.ru_utime.tv_sec + (double(usage.ru_utime.tv_usec) * 1E-6);
0181       // System functions
0182       totalCPUTime += (double)usage.ru_stime.tv_sec + (double(usage.ru_stime.tv_usec) * 1E-6);
0183
0184       // Additionally, add in CPU usage from our child processes.
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     //NOTE: We use a per thread stack for module times since unscheduled
0193     // exectuion or tbb task spawning can cause a module to run on the
0194     // same thread as an already running module
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         //we need to ignore the threshold check
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       //For accounting purposes we effectively can say we started earlier
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         //did not capture beginning time
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   }  // namespace service
0659 }  // namespace edm
0660
0661 using edm::service::Timing;
0662
0663 typedef edm::serviceregistry::AllArgsMaker<edm::TimingServiceBase, Timing> TimingMaker;
0664 DEFINE_FWK_SERVICE_MAKER(Timing, TimingMaker);