CMS 3D CMS Logo

List of all members | 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

Public Member Functions

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

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_time_
 
double curr_job_cpu_
 
double curr_job_time_
 
std::atomic< double > last_run_cpu_
 
std::atomic< double > last_run_time_
 
std::vector< double > max_events_time_
 
std::vector< double > min_events_time_
 
unsigned int nStreams_
 
unsigned int nThreads_
 
bool report_summary_
 
std::vector< double > sum_events_time_
 
bool summary_only_
 
std::atomic< unsigned long > total_event_count_
 

Detailed Description

Definition at line 36 of file Timing.cc.

Constructor & Destructor Documentation

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

Definition at line 129 of file Timing.cc.

References edm::signalslot::Signal< T >::connect(), curr_events_time_, edm::service::getCPU(), edm::service::getTime(), last_run_cpu_, last_run_time_, max_events_time_, edm::service::SystemBounds::maxNumberOfStreams(), edm::service::SystemBounds::maxNumberOfThreads(), min_events_time_, nStreams_, nThreads_, postBeginJob(), postEndJob(), postEvent(), edm::ActivityRegistry::postGlobalEndRunSignal_, postModule(), edm::ActivityRegistry::preallocateSignal_, preEvent(), preModule(), sum_events_time_, summary_only_, edm::ActivityRegistry::watchPostBeginJob(), edm::ActivityRegistry::watchPostEndJob(), edm::ActivityRegistry::watchPostEvent(), edm::ActivityRegistry::watchPostModuleEvent(), edm::ActivityRegistry::watchPreEvent(), and edm::ActivityRegistry::watchPreModuleEvent().

129  :
130  curr_job_time_(0.),
131  curr_job_cpu_(0.),
132  last_run_time_(0.0),
133  last_run_cpu_(0.0),
135  summary_only_(iPS.getUntrackedParameter<bool>("summaryOnly")),
136  report_summary_(iPS.getUntrackedParameter<bool>("useJobReport")),
139  total_event_count_(0) {
140  iRegistry.watchPostBeginJob(this, &Timing::postBeginJob);
141  iRegistry.watchPostEndJob(this, &Timing::postEndJob);
142 
143  iRegistry.watchPreEvent(this, &Timing::preEvent);
144  iRegistry.watchPostEvent(this, &Timing::postEvent);
145 
146  if(not summary_only_) {
147  iRegistry.watchPreModuleEvent(this, &Timing::preModule);
148  iRegistry.watchPostModuleEvent(this, &Timing::postModule);
149  }
150 
151  iRegistry.preallocateSignal_.connect([this](service::SystemBounds const& iBounds){
152  nStreams_ = iBounds.maxNumberOfStreams();
153  nThreads_ = iBounds.maxNumberOfThreads();
154  curr_events_time_.resize(nStreams_,0.);
155  sum_events_time_.resize(nStreams_,0.);
156  max_events_time_.resize(nStreams_,0.);
157  min_events_time_.resize(nStreams_,1.E6);
158 
159  });
160 
161  iRegistry.postGlobalEndRunSignal_.connect([this](edm::GlobalContext const&) {
163  last_run_cpu_ = getCPU();
164  });
165  }
std::vector< double > sum_events_time_
Definition: Timing.cc:71
double curr_job_time_
Definition: Timing.cc:57
std::atomic< double > last_run_cpu_
Definition: Timing.cc:61
std::vector< double > max_events_time_
Definition: Timing.cc:69
std::vector< double > curr_events_time_
Definition: Timing.cc:62
static double getCPU()
Definition: Timing.cc:102
void postEvent(StreamContext const &)
Definition: Timing.cc:273
double curr_job_cpu_
Definition: Timing.cc:58
unsigned int nThreads_
Definition: Timing.cc:74
unsigned int nStreams_
Definition: Timing.cc:73
std::atomic< double > last_run_time_
Definition: Timing.cc:60
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:72
static double getTime()
Definition: Timing.cc:95
void postModule(StreamContext const &, ModuleCallingContext const &)
Definition: Timing.cc:297
void preEvent(StreamContext const &)
Definition: Timing.cc:268
void preModule(StreamContext const &, ModuleCallingContext const &)
Definition: Timing.cc:292
std::vector< double > min_events_time_
Definition: Timing.cc:70
edm::service::Timing::~Timing ( )

Definition at line 167 of file Timing.cc.

167  {
168  }

Member Function Documentation

void edm::service::Timing::addToCPUTime ( StreamID  id,
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 170 of file Timing.cc.

References curr_job_cpu_.

170  {
171  //For accounting purposes we effectively can say we started earlier
172  curr_job_cpu_ -= iTime;
173  }
double curr_job_cpu_
Definition: Timing.cc:58
void edm::service::Timing::fillDescriptions ( edm::ConfigurationDescriptions descriptions)
static

Definition at line 179 of file Timing.cc.

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

179  {
181  desc.addUntracked<bool>("summaryOnly", false)->setComment(
182  "If 'true' do not report timing for each event");
183  desc.addUntracked<bool>("useJobReport", true)->setComment(
184  "If 'true' write summary information to JobReport");
185  descriptions.add("Timing", desc);
186  descriptions.setComment(
187  "This service reports the time it takes to run each module in a job.");
188  }
void setComment(std::string const &value)
void add(std::string const &label, ParameterSetDescription const &psetDescription)
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 175 of file Timing.cc.

References edm::service::getCPU().

175  {
176  return getCPU();
177  }
static double getCPU()
Definition: Timing.cc:102
void edm::service::Timing::postBeginJob ( )
private

Definition at line 190 of file Timing.cc.

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

Referenced by Timing().

190  {
192  curr_job_cpu_ = getCPU();
193 
194  if(not summary_only_) {
195  LogImportant("TimeReport")
196  << "TimeReport> Report activated" << "\n"
197  << "TimeReport> Report columns headings for events: "
198  << "eventnum runnum timetaken\n"
199  << "TimeReport> Report columns headings for modules: "
200  << "eventnum runnum modulelabel modulename timetakeni\n"
201  << "TimeReport> JobTime=" << curr_job_time_ << " JobCPU=" << curr_job_cpu_ << "\n";
202  }
203  }
double curr_job_time_
Definition: Timing.cc:57
static double getCPU()
Definition: Timing.cc:102
double curr_job_cpu_
Definition: Timing.cc:58
static double getTime()
Definition: Timing.cc:95
void edm::service::Timing::postEndJob ( )
private

Definition at line 205 of file Timing.cc.

References curr_job_cpu_, curr_job_time_, edm::service::d2str(), edm::service::getCPU(), edm::service::getTime(), last_run_cpu_, last_run_time_, max_events_time_, min_events_time_, nStreams_, nThreads_, report_summary_, sum_events_time_, lumiQTWidget::t, total_event_count_, and edm::service::ui2str().

Referenced by Timing().

205  {
206  double total_job_time = getTime() - curr_job_time_;
207 
208  double total_job_cpu = getCPU() - curr_job_cpu_;
209 
210  double min_event_time = *(std::min_element(min_events_time_.begin(),
211  min_events_time_.end()));
212  double max_event_time = *(std::max_element(max_events_time_.begin(),
213  max_events_time_.end()));
214 
215  auto total_loop_time = last_run_time_ - curr_job_time_;
216  auto total_loop_cpu = last_run_cpu_ - curr_job_cpu_;
217 
218  if(last_run_time_ == 0.0) {
219  total_loop_time = 0.0;
220  total_loop_cpu = 0.0;
221  }
222 
223  double sum_all_events_time = 0;
224  for(auto t : sum_events_time_) { sum_all_events_time += t; }
225 
226  double average_event_time = 0.0;
227  if(total_event_count_ != 0) {
228  average_event_time = sum_all_events_time / total_event_count_;
229  }
230 
231  double event_throughput = 0.0;
232  if(total_loop_time != 0.0) {
233  event_throughput = total_event_count_ / total_loop_time;
234  }
235 
236  LogImportant("TimeReport")
237  << "TimeReport> Time report complete in "
238  << total_job_time << " seconds"
239  << "\n"
240  << " Time Summary: \n"
241  << " - Min event: " << min_event_time << "\n"
242  << " - Max event: " << max_event_time << "\n"
243  << " - Avg event: " << average_event_time << "\n"
244  << " - Total loop: " <<total_loop_time <<"\n"
245  << " - Total job: " << total_job_time << "\n"
246  << " Event Throughput: "<< event_throughput <<" ev/s\n"
247  << " CPU Summary: \n"
248  << " - Total loop: " << total_loop_cpu << "\n"
249  << " - Total job: " << total_job_cpu << "\n";
250 
251  if(report_summary_) {
252  Service<JobReport> reportSvc;
253  std::map<std::string, std::string> reportData;
254 
255  reportData.insert(std::make_pair("MinEventTime", d2str(min_event_time)));
256  reportData.insert(std::make_pair("MaxEventTime", d2str(max_event_time)));
257  reportData.insert(std::make_pair("AvgEventTime", d2str(average_event_time)));
258  reportData.insert(std::make_pair("EventThroughput", d2str(event_throughput)));
259  reportData.insert(std::make_pair("TotalJobTime", d2str(total_job_time)));
260  reportData.insert(std::make_pair("TotalJobCPU", d2str(total_job_cpu)));
261  reportData.insert(std::make_pair("TotalLoopCPU", d2str(total_loop_cpu)));
262  reportData.insert(std::make_pair("NumberOfStreams",ui2str(nStreams_)));
263  reportData.insert(std::make_pair("NumberOfThreads",ui2str(nThreads_)));
264  reportSvc->reportPerformanceSummary("Timing", reportData);
265  }
266  }
std::vector< double > sum_events_time_
Definition: Timing.cc:71
double curr_job_time_
Definition: Timing.cc:57
std::atomic< double > last_run_cpu_
Definition: Timing.cc:61
std::vector< double > max_events_time_
Definition: Timing.cc:69
static double getCPU()
Definition: Timing.cc:102
double curr_job_cpu_
Definition: Timing.cc:58
unsigned int nThreads_
Definition: Timing.cc:74
unsigned int nStreams_
Definition: Timing.cc:73
std::atomic< double > last_run_time_
Definition: Timing.cc:60
static std::string ui2str(unsigned int i)
Definition: Timing.cc:88
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:72
static std::string d2str(double d)
static double getTime()
Definition: Timing.cc:95
std::vector< double > min_events_time_
Definition: Timing.cc:70
void edm::service::Timing::postEvent ( StreamContext const &  iStream)
private

Definition at line 273 of file Timing.cc.

References curr_events_time_, edm::StreamContext::eventID(), edm::service::getTime(), diffTreeTool::index, max_events_time_, min_events_time_, edm::StreamContext::streamID(), sum_events_time_, summary_only_, total_event_count_, and edm::StreamID::value().

Referenced by Timing().

273  {
274  auto index = iStream.streamID().value();
275 
276  double curr_event_time = getTime() - curr_events_time_[index];
277  sum_events_time_[index] +=curr_event_time;
278 
279  if(not summary_only_) {
280  auto const & eventID = iStream.eventID();
281  LogPrint("TimeEvent")
282  << "TimeEvent> "
283  << eventID.event() << " "
284  << eventID.run() << " "
285  << curr_event_time ;
286  }
287  if(curr_event_time > max_events_time_[index]) max_events_time_[index] = curr_event_time;
288  if(curr_event_time < min_events_time_[index]) min_events_time_[index] = curr_event_time;
290  }
std::vector< double > sum_events_time_
Definition: Timing.cc:71
std::vector< double > max_events_time_
Definition: Timing.cc:69
std::vector< double > curr_events_time_
Definition: Timing.cc:62
std::atomic< unsigned long > total_event_count_
Definition: Timing.cc:72
static double getTime()
Definition: Timing.cc:95
std::vector< double > min_events_time_
Definition: Timing.cc:70
void edm::service::Timing::postModule ( StreamContext const &  iStream,
ModuleCallingContext const &  iModule 
)
private

Definition at line 297 of file Timing.cc.

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

Referenced by Timing().

297  {
298  //LogInfo("TimeModule")
299  auto& modStack = moduleTimeStack();
300  assert(modStack.size() > 0);
301  double curr_module_time = modStack.back();
302  modStack.pop_back();
303  double t = getTime() - curr_module_time;
304  //move waiting module start times forward to account
305  // for the fact that they were paused while this module ran
306  for(auto& waitingModuleStartTime : modStack) {
307  waitingModuleStartTime +=t;
308  }
309  auto const & eventID = iStream.eventID();
310  auto const & desc = *(iModule.moduleDescription());
311 
312  LogPrint("TimeModule") << "TimeModule> "
313  << eventID.event() << " "
314  << eventID.run() << " "
315  << desc.moduleLabel() << " "
316  << desc.moduleName() << " "
317  << t;
318  }
static std::vector< double > & moduleTimeStack()
Definition: Timing.cc:124
static double getTime()
Definition: Timing.cc:95
void edm::service::Timing::preEvent ( StreamContext const &  iStream)
private

Definition at line 268 of file Timing.cc.

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

Referenced by Timing().

268  {
269  auto index = iStream.streamID().value();
271  }
std::vector< double > curr_events_time_
Definition: Timing.cc:62
static double getTime()
Definition: Timing.cc:95
void edm::service::Timing::preModule ( StreamContext const &  ,
ModuleCallingContext const &   
)
private

Definition at line 292 of file Timing.cc.

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

Referenced by Timing().

292  {
293  auto & modStack = moduleTimeStack();
294  modStack.push_back(getTime());
295  }
static std::vector< double > & moduleTimeStack()
Definition: Timing.cc:124
static double getTime()
Definition: Timing.cc:95

Member Data Documentation

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

Definition at line 62 of file Timing.cc.

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

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

Definition at line 58 of file Timing.cc.

Referenced by addToCPUTime(), postBeginJob(), and postEndJob().

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

Definition at line 57 of file Timing.cc.

Referenced by postBeginJob(), and postEndJob().

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

Definition at line 61 of file Timing.cc.

Referenced by postEndJob(), and Timing().

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

Definition at line 60 of file Timing.cc.

Referenced by postEndJob(), and Timing().

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

Definition at line 69 of file Timing.cc.

Referenced by postEndJob(), postEvent(), and Timing().

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

Definition at line 70 of file Timing.cc.

Referenced by postEndJob(), postEvent(), and Timing().

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

Definition at line 73 of file Timing.cc.

Referenced by postEndJob(), and Timing().

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

Definition at line 74 of file Timing.cc.

Referenced by postEndJob(), and Timing().

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

Definition at line 64 of file Timing.cc.

Referenced by postEndJob().

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

Definition at line 71 of file Timing.cc.

Referenced by postEndJob(), postEvent(), and Timing().

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

Definition at line 63 of file Timing.cc.

Referenced by postBeginJob(), postEvent(), and Timing().

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

Definition at line 72 of file Timing.cc.

Referenced by postEndJob(), and postEvent().