#include <Timing.h>

Public Member Functions
	Timing (ParameterSet const &, ActivityRegistry &)

	~Timing ()

Static Public Member Functions
static void	fillDescriptions (edm::ConfigurationDescriptions &descriptions)

Private Member Functions
void	postBeginJob ()

void	postEndJob ()

void	postEvent (StreamContext const &)

void	postModule (StreamContext const &, ModuleCallingContext const &)

void	preEvent (StreamContext const &)

void	preModule (StreamContext const &, ModuleCallingContext const &)

Private Attributes
std::vector< double >	curr_events_cpu_

std::vector< double >	curr_events_time_

double	curr_job_cpu_

double	curr_job_time_

std::vector< double >	max_events_cpu_

std::vector< double >	max_events_time_

std::vector< double >	min_events_cpu_

std::vector< double >	min_events_time_

bool	report_summary_

bool	summary_only_

std::atomic< unsigned long >	total_event_count_

std::vector< double >	total_events_cpu_

Detailed Description

Definition at line 24 of file Timing.h.

Constructor & Destructor Documentation

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

Definition at line 68 of file Timing.cc.

References edm::signalslot::Signal< T >::connect(), curr_events_cpu_, curr_events_time_, max_events_cpu_, max_events_time_, edm::service::SystemBounds::maxNumberOfStreams(), min_events_cpu_, min_events_time_, postBeginJob(), postEndJob(), postEvent(), postModule(), edm::ActivityRegistry::preallocateSignal_, preEvent(), preModule(), summary_only_, total_events_cpu_, edm::ActivityRegistry::watchPostBeginJob(), edm::ActivityRegistry::watchPostEndJob(), edm::ActivityRegistry::watchPostEvent(), edm::ActivityRegistry::watchPostModuleEvent(), edm::ActivityRegistry::watchPreEvent(), and edm::ActivityRegistry::watchPreModuleEvent().

                                                                        :
         curr_job_time_(0.),
         curr_job_cpu_(0.),
         curr_events_time_(),
         curr_events_cpu_(),
         total_events_cpu_(),
         summary_only_(iPS.getUntrackedParameter<bool>("summaryOnly")),
         report_summary_(iPS.getUntrackedParameter<bool>("useJobReport")),
         max_events_time_(),
         max_events_cpu_(),
         min_events_time_(),
         min_events_cpu_(),
         total_event_count_(0) {
       iRegistry.watchPostBeginJob(this, &Timing::postBeginJob);
       iRegistry.watchPostEndJob(this, &Timing::postEndJob);
 
       iRegistry.watchPreEvent(this, &Timing::preEvent);
       iRegistry.watchPostEvent(this, &Timing::postEvent);
 
       if(not summary_only_) {
         iRegistry.watchPreModuleEvent(this, &Timing::preModule);
         iRegistry.watchPostModuleEvent(this, &Timing::postModule);
       }
           
       iRegistry.preallocateSignal_.connect([this](service::SystemBounds const& iBounds){
         auto nStreams = iBounds.maxNumberOfStreams();
         curr_events_time_.resize(nStreams,0.);
         curr_events_cpu_.resize(nStreams,0.);
         total_events_cpu_.resize(nStreams,0.);
         max_events_time_.resize(nStreams,0.);
         max_events_cpu_.resize(nStreams,0.);
         min_events_time_.resize(nStreams,1.E6);
         min_events_cpu_.resize(nStreams,1.E6);
       });
     }

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

Definition at line 104 of file Timing.cc.

104 {

105 }

Member Function Documentation

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

static

Definition at line 107 of file Timing.cc.

References edm::ConfigurationDescriptions::add(), edm::ParameterSetDescription::addUntracked(), and edm::ConfigurationDescriptions::setComment().

                                                                          {
       ParameterSetDescription desc;
       desc.addUntracked<bool>("summaryOnly", false)->setComment(
       "If 'true' do not report timing for each event");
       desc.addUntracked<bool>("useJobReport", true)->setComment(
        "If 'true' write summary information to JobReport");
       descriptions.add("Timing", desc);
       descriptions.setComment(
        "This service reports the time it takes to run each module in a job.");
     }

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

private

Definition at line 118 of file Timing.cc.

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

Referenced by Timing().

                               {
       curr_job_time_ = getTime();
       curr_job_cpu_ = getCPU();
 
       if(not summary_only_) {
         LogImportant("TimeReport")
         << "TimeReport> Report activated" << "\n"
         << "TimeReport> Report columns headings for events: "
         << "eventnum runnum timetaken\n"
         << "TimeReport> Report columns headings for modules: "
         << "eventnum runnum modulelabel modulename timetakeni\n"
         << "TimeReport> JobTime=" << curr_job_time_  << " JobCPU=" << curr_job_cpu_  << "\n";
       }
     }

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

private

Definition at line 133 of file Timing.cc.

References curr_job_cpu_, curr_job_time_, edm::service::d2str(), edm::service::getCPU(), edm::service::getTime(), max_events_cpu_, max_events_time_, min_events_cpu_, min_events_time_, report_summary_, edmStreamStallGrapher::t, total_event_count_, and total_events_cpu_.

Referenced by Timing().

                             {
       double total_job_time = getTime() - curr_job_time_;
       double average_event_time = total_job_time / total_event_count_;
 
       double total_job_cpu = getCPU() - curr_job_cpu_;
       double total_event_cpu = 0.;
       for(auto t : total_events_cpu_) {
         total_event_cpu +=t;
       }
       double average_event_cpu = total_event_cpu / total_event_count_;
 
       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(),
                                                max_events_time_.end()));
       double min_event_cpu = *(std::min_element(min_events_cpu_.begin(),
                                                  min_events_cpu_.end()));
       double max_event_cpu = *(std::max_element(max_events_cpu_.begin(),
                                                  max_events_cpu_.end()));
       LogImportant("TimeReport")
         << "TimeReport> Time report complete in "
         << total_job_time << " seconds"
         << "\n"
         << " Time Summary: \n"
         << " - Min event:   " << min_event_time << "\n"
         << " - Max event:   " << max_event_time << "\n"
         << " - Avg event:   " << average_event_time << "\n"
         << " - Total job:   " << total_job_time << "\n"
         << " CPU Summary: \n"
         << " - Min event:   " << min_event_cpu << "\n"
         << " - Max event:   " << max_event_cpu << "\n"
         << " - Avg event:   " << average_event_cpu << "\n"
         << " - Total job:   " << total_job_cpu << "\n"
         << " - Total event: " << total_event_cpu << "\n";
 
       if(report_summary_) {
         Service<JobReport> reportSvc;
         std::map<std::string, std::string> reportData;
 
         reportData.insert(std::make_pair("MinEventTime", d2str(min_event_time)));
         reportData.insert(std::make_pair("MaxEventTime", d2str(max_event_time)));
         reportData.insert(std::make_pair("AvgEventTime", d2str(average_event_time)));
         reportData.insert(std::make_pair("TotalJobTime", d2str(total_job_time)));
         reportData.insert(std::make_pair("MinEventCPU", d2str(min_event_cpu)));
         reportData.insert(std::make_pair("MaxEventCPU", d2str(max_event_cpu)));
         reportData.insert(std::make_pair("AvgEventCPU", d2str(average_event_cpu)));
         reportData.insert(std::make_pair("TotalJobCPU", d2str(total_job_cpu)));
         reportData.insert(std::make_pair("TotalEventCPU", d2str(total_event_cpu)));
 
         reportSvc->reportPerformanceSummary("Timing", reportData);
       }
     }

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

private

Definition at line 192 of file Timing.cc.

References curr_events_cpu_, curr_events_time_, edm::StreamContext::eventID(), edm::service::getCPU(), edm::service::getTime(), cmsHarvester::index, max_events_cpu_, max_events_time_, min_events_cpu_, min_events_time_, edm::StreamContext::streamID(), summary_only_, total_event_count_, total_events_cpu_, and edm::StreamID::value().

Referenced by Timing().

                                                        {
       auto index = iStream.streamID().value();
       double curr_event_cpu = getCPU() - curr_events_cpu_[index];
       total_events_cpu_[index] += curr_event_cpu;
 
       double curr_event_time = getTime() - curr_events_time_[index];
 
       if(not summary_only_) {
         auto const & eventID = iStream.eventID();
         LogPrint("TimeEvent")
         << "TimeEvent> "
         << eventID.event() << " "
         << eventID.run() << " "
         << curr_event_time << " "
         << curr_event_cpu << " "
         << total_events_cpu_[index];
       }
       if(curr_event_time > max_events_time_[index]) max_events_time_[index] = curr_event_time;
       if(curr_event_time < min_events_time_[index]) min_events_time_[index] = curr_event_time;
       if(curr_event_cpu > max_events_cpu_[index]) max_events_cpu_[index] = curr_event_cpu;
       if(curr_event_cpu < min_events_cpu_[index]) min_events_cpu_[index] = curr_event_cpu;
       ++total_event_count_;
     }

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

private

Definition at line 221 of file Timing.cc.

References edm::StreamContext::eventID(), edm::service::getTime(), edm::ModuleCallingContext::moduleDescription(), edm::service::moduleTimeStack(), and edmStreamStallGrapher::t.

Referenced by Timing().

                                                                                              {
       //LogInfo("TimeModule")
       auto& modStack = moduleTimeStack();
       assert(modStack.size() > 0);
       double curr_module_time = modStack.back();
       modStack.pop_back();
       double t = getTime() - curr_module_time;
       //move waiting module start times forward to account
       // for the fact that they were paused while this module ran
       for(auto& waitingModuleStartTime : modStack) {
         waitingModuleStartTime +=t;
       }
       auto const & eventID = iStream.eventID();
       auto const & desc = *(iModule.moduleDescription());
       
       LogPrint("TimeModule") << "TimeModule> "
       << eventID.event() << " "
       << eventID.run() << " "
       << desc.moduleLabel() << " "
       << desc.moduleName() << " "
       << t;
     }

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

private

Definition at line 186 of file Timing.cc.

References curr_events_cpu_, curr_events_time_, edm::service::getCPU(), edm::service::getTime(), cmsHarvester::index, edm::StreamContext::streamID(), and edm::StreamID::value().

Referenced by Timing().

                                                       {
       auto index = iStream.streamID().value();
       curr_events_time_[index] = getTime();
       curr_events_cpu_[index] = getCPU();
     }

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

private

Definition at line 216 of file Timing.cc.

References edm::service::getTime(), and edm::service::moduleTimeStack().

Referenced by Timing().

                                                                             {
       auto & modStack = moduleTimeStack();
       modStack.push_back(getTime());
     }