TimeTracker_service.cc
Go to the documentation of this file.
1 // ======================================================================
2 //
3 // TimeTracker
4 //
5 // ======================================================================
6 
14 #include "boost/format.hpp"
18 #include "cetlib/HorizontalRule.h"
20 #include "cetlib/sqlite/Ntuple.h"
21 #include "cetlib/sqlite/helpers.h"
23 #include "fhiclcpp/types/Atom.h"
24 #include "fhiclcpp/types/Name.h"
25 #include "fhiclcpp/types/Table.h"
27 
28 #include <algorithm>
29 #include <chrono>
30 #include <iomanip>
31 #include <sstream>
32 #include <string>
33 #include <vector>
34 
35 using namespace cet;
36 using std::setw;
37 using std::string;
38 using std::chrono::steady_clock;
39 
40 namespace {
41 
42  // 'using' declaration won't work because 'now' is a member function
43  auto now = std::bind(&steady_clock::now);
44 
45  struct Statistics {
46 
47  explicit Statistics() = default;
48 
49  explicit Statistics(string const& p,
50  string const& label,
51  string const& type,
52  sqlite3* const db,
53  string const& table,
54  string const& column)
55  : path{p}
56  , mod_label{label}
57  , mod_type{type}
58  , min{sqlite::min(db, table, column)}
59  , mean{sqlite::mean(db, table, column)}
60  , max{sqlite::max(db, table, column)}
61  , median{sqlite::median(db, table, column)}
62  , rms{sqlite::rms(db, table, column)}
63  , n{sqlite::nrows(db, table)}
64  {}
65 
66  string path{};
67  string mod_label{};
68  string mod_type{};
69  double min{-1.};
70  double mean{-1.};
71  double max{-1.};
72  double median{-1.};
73  double rms{-1.};
74  unsigned n{0u};
75  };
76 
77  std::ostream&
78  operator<<(std::ostream& os, Statistics const& info)
79  {
80  string label{info.path};
81  if (!info.mod_label.empty()) {
82  label += ':' + info.mod_label;
83  }
84  if (!info.mod_type.empty()) {
85  label += ':' + info.mod_type;
86  }
87  os << label << " " << boost::format(" %=12g ") % info.min
88  << boost::format(" %=12g ") % info.mean
89  << boost::format(" %=12g ") % info.max
90  << boost::format(" %=12g ") % info.median
91  << boost::format(" %=12g ") % info.rms
92  << boost::format(" %=10d ") % info.n;
93  return os;
94  }
95 }
96 
97 namespace art {
98  class TimeTracker;
99 }
100 
101 // =======================================================================
103 public:
104  struct Config {
105  fhicl::Atom<bool> printSummary{fhicl::Name{"printSummary"}, true};
106 
107  struct DBoutput {
110  };
111  fhicl::Table<DBoutput> dbOutput{fhicl::Name{"dbOutput"}};
112  };
113 
116 
117 private:
118  void prePathProcessing(string const&);
119  void postSourceConstruction(ModuleDescription const&);
120  void postEndJob();
121 
122  void preEventReading();
123  void postEventReading(Event const&);
124 
125  void preEventProcessing(Event const&);
126  void postEventProcessing(Event const&);
127 
128  void startTime(ModuleDescription const&);
129  void recordTime(ModuleDescription const& md, string const& suffix);
130 
131  void logToDatabase_(Statistics const& evt,
132  std::vector<Statistics> const& modules);
133  void logToDestination_(Statistics const& evt,
134  std::vector<Statistics> const& modules);
135 
137  string pathName; // This member will need to be rethought once we decide to
138  // process paths in parallel per event.
140  steady_clock::time_point eventStart;
141  steady_clock::time_point moduleStart;
142  };
143  std::vector<PerScheduleData> data_;
144 
148  string sourceType_{};
149 
150  template <unsigned SIZE>
155 
156  using timeSource_t =
159  using timeModule_t = cet::sqlite::
160  Ntuple<uint32_t, uint32_t, uint32_t, string, string, string, double>;
161 
165 }; // art::TimeTracker
166 
167 //=================================================================
168 // Implementation below
169 
171  ActivityRegistry& iRegistry)
172  : printSummary_{config().printSummary()}
174  config().dbOutput().filename())}
175  , overwriteContents_{config().dbOutput().overwrite()} // table headers
176  , timeSourceTuple_{{"Run", "SubRun", "Event", "Source", "Time"}}
177  , timeEventTuple_{{"Run", "SubRun", "Event", "Time"}}
178  , timeModuleTuple_{{"Run",
179  "SubRun",
180  "Event",
181  "Path",
182  "ModuleLabel",
183  "ModuleType",
184  "Time"}} // tables
186  , timeEventTable_{db_, "TimeEvent", timeEventTuple_, overwriteContents_}
187  , timeModuleTable_{db_, "TimeModule", timeModuleTuple_, overwriteContents_}
188 {
189  // MT-TODO: Placeholder until we are multi-threaded
190  unsigned const nSchedules{1u};
191  data_.resize(nSchedules);
192 
193  iRegistry.sPostSourceConstruction.watch(this,
195  iRegistry.sPreProcessPath.watch(this, &TimeTracker::prePathProcessing);
196  iRegistry.sPostEndJob.watch(this, &TimeTracker::postEndJob);
197 
198  // Event reading
199  iRegistry.sPreSourceEvent.watch(this, &TimeTracker::preEventReading);
200  iRegistry.sPostSourceEvent.watch(this, &TimeTracker::postEventReading);
201 
202  // Event execution
203  iRegistry.sPreProcessEvent.watch(this, &TimeTracker::preEventProcessing);
204  iRegistry.sPostProcessEvent.watch(this, &TimeTracker::postEventProcessing);
205 
206  // Module execution
207  iRegistry.sPreModule.watch(this, &TimeTracker::startTime);
208  iRegistry.sPostModule.watch(
209  [this](auto const& md) { this->recordTime(md, ""s); });
210  iRegistry.sPreWriteEvent.watch(this, &TimeTracker::startTime);
211  iRegistry.sPostWriteEvent.watch(
212  [this](auto const& md) { this->recordTime(md, "(write)"s); });
213 }
214 
215 //======================================================================
216 void
217 art::TimeTracker::prePathProcessing(string const& pathname)
218 {
219  // MT-TODO: Placeholder until we're multi-threaded
220  auto const sid = ScheduleID::first().id();
221  data_[sid].pathName = pathname;
222 }
223 
224 //======================================================================
225 void
227 {
231 
232  if (!printSummary_)
233  return;
234 
235  using namespace cet::sqlite;
237  rEvents << select("count(*)").from(db_, timeEventTable_.name());
238 
239  query_result<std::size_t> rModules;
240  rModules << select("count(*)").from(db_, timeModuleTable_.name());
241 
242  auto const nEventRows = unique_value(rEvents);
243  auto const nModuleRows = unique_value(rModules);
244 
245  if (nEventRows == 0 && nModuleRows == 0) {
246  logToDestination_(Statistics{}, std::vector<Statistics>{});
247  return;
248  }
249 
250  if (nEventRows == 0 && nModuleRows != 0) {
251  std::string const errMsg{
252  "Malformed TimeTracker database. The TimeEvent table is empty, but\n"
253  "the TimeModule table is not. This can happen if an exception has\n"
254  "been thrown from a module while processing the first event. Any saved\n"
255  "database file is suspect and should not be used."};
256  mf::LogAbsolute("TimeTracker") << errMsg;
257  return;
258  }
259 
260  using namespace std;
261  // Gather statistics for full Event
262  // -- Unfortunately, this is not a simple query since the (e.g.)
263  // 'RootOutput(write)' times and the source time are not
264  // recorded in the TimeEvent rows. They must be added in.
265 
266  string const fullEventTime_ddl =
267  "CREATE TABLE temp.fullEventTime AS "
268  "SELECT Run,Subrun,Event,SUM(Time) AS FullEventTime FROM ("
269  " SELECT Run,Subrun,Event,Time FROM TimeEvent"
270  " UNION"
271  " SELECT Run,Subrun,Event,Time FROM TimeModule WHERE ModuleType LIKE "
272  "'%(write)'"
273  " UNION"
274  " SELECT Run,Subrun,Event,Time FROM TimeSource"
275  ") GROUP BY Run,Subrun,Event";
276 
277  using namespace cet::sqlite;
278  exec(db_, fullEventTime_ddl);
279  Statistics const evtStats{
280  "Full event", "", "", db_, "temp.fullEventTime", "FullEventTime"};
281  drop_table(db_, "temp.fullEventTime");
282 
284  r << select_distinct("Path", "ModuleLabel", "ModuleType")
285  .from(db_, timeModuleTable_.name());
286 
287  std::vector<Statistics> modStats;
288  modStats.emplace_back(
289  "source", sourceType_ + "(read)", "", db_, "TimeSource", "Time");
290 
291  for (auto const& row : r) {
292  string path, mod_label, mod_type;
293  tie(path, mod_label, mod_type) = row;
294  create_table_as("temp.tmpModTable",
295  select("*")
296  .from(db_, "TimeModule")
297  .where("Path='"s + path + "'"s + " AND ModuleLabel='"s +
298  mod_label + "'"s + " AND ModuleType='"s +
299  mod_type + "'"s));
300  modStats.emplace_back(
301  path, mod_label, mod_type, db_, "temp.tmpModTable", "Time");
302  drop_table(db_, "temp.tmpModTable");
303  }
304 
305  logToDestination_(evtStats, modStats);
306 }
307 
308 //======================================================================
309 void
311 {
312  sourceType_ = md.moduleName();
313 }
314 
315 //======================================================================
316 void
318 {
319  // MT-TODO: Placeholder until we're multi-threaded
320  auto const sid = ScheduleID::first().id();
321  auto& d = data_[sid];
322  d.eventID = EventID::invalidEvent();
323  d.eventStart = now();
324 }
325 
326 void
328 {
329  // MT-TODO: Placeholder until we're multi-threaded
330  auto const sid = ScheduleID::first().id();
331  auto& d = data_[sid];
332  d.eventID = e.id();
333  auto const t = std::chrono::duration<double>{now() - d.eventStart}.count();
335  d.eventID.run(), d.eventID.subRun(), d.eventID.event(), sourceType_, t);
336 }
337 
338 //======================================================================
339 void
341 {
342  // MT-TODO: Placeholder until we're multi-threaded
343  auto const sid = ScheduleID::first().id();
344  auto& d = data_[sid];
345  assert(d.eventID == e.id());
346  d.eventStart = now();
347 }
348 
349 void
351 {
352  // MT-TODO: Placeholder until we're multi-threaded
353  auto const sid = ScheduleID::first().id();
354  auto const& d = data_[sid];
355  auto const t = std::chrono::duration<double>{now() - d.eventStart}.count();
357  d.eventID.run(), d.eventID.subRun(), d.eventID.event(), t);
358 }
359 
360 //======================================================================
361 void
363 {
364  // MT-TODO: Placeholder until we're multi-threaded
365  auto const sid = ScheduleID::first().id();
366  auto& d = data_[sid];
367  d.moduleStart = now();
368 }
369 
370 void
372  string const& suffix)
373 {
374  // MT-TODO: Placeholder until we're multi-threaded
375  auto const sid = ScheduleID::first().id();
376  auto const& d = data_[sid];
377  auto const t = std::chrono::duration<double>{now() - d.moduleStart}.count();
378  timeModuleTable_.insert(d.eventID.run(),
379  d.eventID.subRun(),
380  d.eventID.event(),
381  d.pathName,
382  desc.moduleLabel(),
383  desc.moduleName() + suffix,
384  t);
385 }
386 
387 //======================================================================
388 void
390  std::vector<Statistics> const& modules)
391 {
392  std::size_t width{30};
393  auto identifier_size = [](Statistics const& s) {
394  return s.path.size() + s.mod_label.size() + s.mod_type.size() +
395  2; // Don't forget the two ':'s.
396  };
397  cet::for_all(modules, [&identifier_size, &width](auto const& mod) {
398  width = std::max(width, identifier_size(mod));
399  });
400 
401  std::ostringstream msgOss;
402  HorizontalRule const rule{width + 4 + 5 * 14 + 12};
403  msgOss << '\n'
404  << rule('=') << '\n'
405  << std::setw(width + 2) << std::left << "TimeTracker printout (sec)"
406  << boost::format(" %=12s ") % "Min" << boost::format(" %=12s ") % "Avg"
407  << boost::format(" %=12s ") % "Max"
408  << boost::format(" %=12s ") % "Median"
409  << boost::format(" %=12s ") % "RMS"
410  << boost::format(" %=10s ") % "nEvts"
411  << "\n";
412 
413  msgOss << rule('=') << '\n';
414 
415  if (evt.n == 0u) {
416  msgOss << "[ No processed events ]\n";
417  } else {
418  // N.B. setw(width) applies to the first field in
419  // ostream& art::operator<<(ostream&, Statistics const&).
420  msgOss << setw(width) << evt << '\n' << rule('-') << '\n';
421  for (auto const& mod : modules) {
422  msgOss << setw(width) << mod << '\n';
423  }
424  }
425 
426  msgOss << rule('=');
427  mf::LogAbsolute("TimeTracker") << msgOss.str();
428 }
429 
430 //===========================================================
void insert(Args const ...)
Definition: Ntuple.h:237
T max(const caf::Proxy< T > &a, T b)
const XML_Char XML_Encoding * info
Definition: expat.h:530
name_array< 5u > timeSourceTuple_
void startTime(ModuleDescription const &)
T unique_value(query_result< T > const &r)
Definition: query_result.h:101
double rms(sqlite3 *db, std::string const &table_name, std::string const &column_name)
TimeTracker(ServiceTable< Config > const &, ActivityRegistry &)
void logToDestination_(Statistics const &evt, std::vector< Statistics > const &modules)
T * get() const
Definition: ServiceHandle.h:70
std::ostream & operator<<(std::ostream &, map_vector_key const &)
Definition: map_vector.h:330
std::vector< PerScheduleData > data_
static constexpr EventID invalidEvent()
Definition: EventID.h:202
#define DEFINE_ART_SERVICE(svc)
Definition: ServiceMacros.h:93
const char * p
Definition: xmltok.h:285
auto select_distinct(T const &...t)
Definition: select.h:163
void prePathProcessing(string const &)
constexpr id_type id() const
Definition: ScheduleID.h:70
static ScheduleID first()
Definition: ScheduleID.h:82
#define DECLARE_ART_SERVICE(svc, scope)
Definition: ServiceMacros.h:91
Definition: config.py:1
string filename
Definition: shutoffs.py:106
std::string const & name() const
Definition: Ntuple.h:143
void postSourceConstruction(ModuleDescription const &)
name_array< 4u > timeEventTuple_
const char * label
name_array< 7u > timeModuleTuple_
void create_table_as(std::string const &tablename, SelectStmt const &stmt)
Definition: create_table.h:165
cet::sqlite::name_array< SIZE > name_array
const XML_Char * s
Definition: expat.h:262
static const char *const errMsg[]
Definition: Error.h:69
timeModule_t timeModuleTable_
std::string const & moduleName() const
int evt
Float_t d
Definition: plot.C:236
cet::sqlite::Connection db_
std::string format(const int32_t &value, const int &ndigits=8)
Definition: HexUtils.cpp:14
double median(TH1D *h)
Definition: absCal.cxx:524
timeSource_t timeSourceTable_
auto select(T const &...t)
Definition: select.h:155
steady_clock::time_point moduleStart
std::string const & moduleLabel() const
static float min(const float a, const float b, const float c)
Definition: absgeo.cxx:45
const std::string path
Definition: plot_BEN.C:43
void drop_table(sqlite3 *db, std::string const &tablename)
void recordTime(ModuleDescription const &md, string const &suffix)
constexpr auto const & left(const_AssnsIter< L, R, D, Dir > const &a, const_AssnsIter< L, R, D, Dir > const &b)
Definition: AssnsIter.h:104
::xsd::cxx::tree::string< char, simple_type > string
Definition: Database.h:154
T min(sqlite3 *const db, std::string const &table_name, std::string const &column_name)
Definition: statistics.h:57
void postEventReading(Event const &)
std::array< std::string, N > name_array
Definition: column.h:42
auto for_all(FwdCont &, Func)
assert(nhit_max >=nhit_nbins)
TRandom3 r(0)
void postEventProcessing(Event const &)
Service to store calibration data products (CDP) in the SQLite3 metadatabase of a file...
Definition: FillParentInfo.h:8
void preEventProcessing(Event const &)
unsigned nrows(sqlite3 *db, std::string const &tablename)
Float_t e
Definition: plot.C:35
T max(sqlite3 *const db, std::string const &table_name, std::string const &column_name)
Definition: statistics.h:68
void exec(sqlite3 *db, std::string const &ddl)
double mean(sqlite3 *db, std::string const &table_name, std::string const &column_name)
MaybeLogger_< ELseverityLevel::ELsev_severe, true > LogAbsolute
EventID id() const
Definition: Event.h:56
double median(sqlite3 *db, std::string const &table_name, std::string const &column_name)