From 86e482e6955562eb4f4006355f07ba688cb3d96f Mon Sep 17 00:00:00 2001 From: Chris Jones Date: Fri, 8 Sep 2017 10:00:33 -0500 Subject: [PATCH 1/2] Capture initialization time in total job time Modified the total job timing (and cpu timing) to also include the time it takes to initialize the application. The output now also explicitly includes the initialization time. --- FWCore/Framework/bin/cmsRun.cpp | 3 +++ FWCore/Services/plugins/Timing.cc | 21 ++++++++++++++++--- .../Utilities/interface/TimingServiceBase.h | 5 +++++ FWCore/Utilities/src/TimingServiceBase.cc | 13 ++++++++++++ 4 files changed, 39 insertions(+), 3 deletions(-) diff --git a/FWCore/Framework/bin/cmsRun.cpp b/FWCore/Framework/bin/cmsRun.cpp index 1764a0f25dfd0..b130975d13116 100644 --- a/FWCore/Framework/bin/cmsRun.cpp +++ b/FWCore/Framework/bin/cmsRun.cpp @@ -22,6 +22,7 @@ PSet script. See notes in EventProcessor.cpp for details about it. #include "FWCore/Utilities/interface/EDMException.h" #include "FWCore/Utilities/interface/ConvertException.h" #include "FWCore/Utilities/interface/Presence.h" +#include "FWCore/Utilities/interface/TimingServiceBase.h" #include "TError.h" @@ -121,6 +122,8 @@ namespace { } int main(int argc, char* argv[]) { + + edm::TimingServiceBase::jobStarted(); int returnCode = 0; std::string context; diff --git a/FWCore/Services/plugins/Timing.cc b/FWCore/Services/plugins/Timing.cc index e82d371f1c5a2..c7265cd2cf92b 100644 --- a/FWCore/Services/plugins/Timing.cc +++ b/FWCore/Services/plugins/Timing.cc @@ -299,10 +299,21 @@ namespace edm { } void Timing::postEndJob() { - double total_job_time = getTime() - curr_job_time_; + const double job_end_time =getTime(); + const double job_end_cpu =getCPU(); + double total_job_time = job_end_time - jobStartTime(); - double total_job_cpu = getCPU() - curr_job_cpu_; + double total_job_cpu = job_end_cpu; + const double total_initialization_time = curr_job_time_ - jobStartTime(); + const double total_initialization_cpu = curr_job_cpu_; + + if( 0.0 == jobStartTime()) { + //did not capture beginning time + total_job_time =job_end_time - curr_job_time_; + total_job_cpu =job_end_cpu - curr_job_cpu_; + } + double min_event_time = *(std::min_element(min_events_time_.begin(), min_events_time_.end())); double max_event_time = *(std::max_element(max_events_time_.begin(), @@ -337,11 +348,13 @@ namespace edm { << " - Min event: " << min_event_time << "\n" << " - Max event: " << max_event_time << "\n" << " - Avg event: " << average_event_time << "\n" - << " - Total loop: " <reportPerformanceSummary("Timing", reportData); diff --git a/FWCore/Utilities/interface/TimingServiceBase.h b/FWCore/Utilities/interface/TimingServiceBase.h index 9a88cf6f17d05..f7a6282954d72 100644 --- a/FWCore/Utilities/interface/TimingServiceBase.h +++ b/FWCore/Utilities/interface/TimingServiceBase.h @@ -42,10 +42,15 @@ namespace edm { /// The value returned should be in seconds. virtual double getTotalCPU() const = 0; + static void jobStarted(); + + static double jobStartTime() { return s_jobStartTime; } private: TimingServiceBase(const TimingServiceBase&) =delete; // stop default const TimingServiceBase& operator=(const TimingServiceBase&) =delete; // stop default + + static double s_jobStartTime; }; } diff --git a/FWCore/Utilities/src/TimingServiceBase.cc b/FWCore/Utilities/src/TimingServiceBase.cc index 04156ac9874f8..37c4fe102a6dc 100644 --- a/FWCore/Utilities/src/TimingServiceBase.cc +++ b/FWCore/Utilities/src/TimingServiceBase.cc @@ -11,6 +11,8 @@ // // system include files +#include +#include // user include files #include "FWCore/Utilities/interface/TimingServiceBase.h" @@ -19,6 +21,17 @@ using namespace edm; // // constants, enums and typedefs // +double TimingServiceBase::s_jobStartTime = 0.0; + +void TimingServiceBase::jobStarted() { + if (0.0 == s_jobStartTime) { + struct timeval t; + if(gettimeofday(&t, 0) < 0) { + return; + } + s_jobStartTime = static_cast(t.tv_sec) + (static_cast(t.tv_usec) * 1E-6); + } +} // // constructors and destructor From 7fa6640112cbb986155928d760241111398c90fc Mon Sep 17 00:00:00 2001 From: Chris Jones Date: Fri, 8 Sep 2017 10:13:37 -0500 Subject: [PATCH 2/2] Applied clang-tidy changes --- FWCore/Framework/bin/cmsRun.cpp | 2 +- FWCore/Services/plugins/Timing.cc | 10 +++++----- FWCore/Utilities/src/TimingServiceBase.cc | 2 +- 3 files changed, 7 insertions(+), 7 deletions(-) diff --git a/FWCore/Framework/bin/cmsRun.cpp b/FWCore/Framework/bin/cmsRun.cpp index b130975d13116..76eb411df5947 100644 --- a/FWCore/Framework/bin/cmsRun.cpp +++ b/FWCore/Framework/bin/cmsRun.cpp @@ -383,7 +383,7 @@ int main(int argc, char* argv[]) { } } if (!ex.alreadyPrinted()) { - if (jobRep.get() != 0) { + if (jobRep.get() != nullptr) { edm::printCmsException(ex, &(jobRep->get()), returnCode); } else { diff --git a/FWCore/Services/plugins/Timing.cc b/FWCore/Services/plugins/Timing.cc index c7265cd2cf92b..623753832b86c 100644 --- a/FWCore/Services/plugins/Timing.cc +++ b/FWCore/Services/plugins/Timing.cc @@ -36,12 +36,12 @@ namespace edm { class Timing : public TimingServiceBase { public: Timing(ParameterSet const&, ActivityRegistry&); - ~Timing(); + ~Timing() override; static void fillDescriptions(edm::ConfigurationDescriptions & descriptions); - virtual void addToCPUTime(StreamID id, double iTime) override; - virtual double getTotalCPU() const override; + void addToCPUTime(StreamID id, double iTime) override; + double getTotalCPU() const override; private: @@ -116,7 +116,7 @@ namespace edm { static double getTime() { struct timeval t; - if(gettimeofday(&t, 0) < 0) + if(gettimeofday(&t, nullptr) < 0) throw cms::Exception("SysCallFailed", "Failed call to gettimeofday"); return static_cast(t.tv_sec) + (static_cast(t.tv_usec) * 1E-6); } @@ -151,7 +151,7 @@ namespace edm { static double popStack() { auto& modStack = moduleTimeStack(); - assert(modStack.size() > 0); + assert(!modStack.empty()); double curr_module_time = modStack.back(); modStack.pop_back(); double t = getTime() - curr_module_time; diff --git a/FWCore/Utilities/src/TimingServiceBase.cc b/FWCore/Utilities/src/TimingServiceBase.cc index 37c4fe102a6dc..c4468f8b9328a 100644 --- a/FWCore/Utilities/src/TimingServiceBase.cc +++ b/FWCore/Utilities/src/TimingServiceBase.cc @@ -26,7 +26,7 @@ double TimingServiceBase::s_jobStartTime = 0.0; void TimingServiceBase::jobStarted() { if (0.0 == s_jobStartTime) { struct timeval t; - if(gettimeofday(&t, 0) < 0) { + if(gettimeofday(&t, nullptr) < 0) { return; } s_jobStartTime = static_cast(t.tv_sec) + (static_cast(t.tv_usec) * 1E-6);