14 #include "boost/format.hpp" 17 #include "cetlib/HorizontalRule.h" 18 #include "cetlib/sqlite/Connection.h" 19 #include "cetlib/sqlite/Ntuple.h" 20 #include "cetlib/sqlite/helpers.h" 21 #include "cetlib/sqlite/statistics.h" 26 #include "tbb/concurrent_unordered_map.h" 41 using chrono::steady_clock;
47 using ConcurrentKey = std::pair<ScheduleID, std::string>;
48 struct ConcurrentKeyHasher {
50 operator()(ConcurrentKey
const& key)
const 52 static std::hash<ScheduleID> schedule_hasher{};
53 static std::hash<std::string> string_hasher{};
55 return schedule_hasher(key.first) ^ string_hasher(key.second);
60 key(ScheduleID
const sid)
62 return ConcurrentKey{sid, {}};
65 key(ModuleContext
const& mc)
67 return ConcurrentKey{mc.scheduleID(), mc.moduleLabel()};
70 auto now = bind(&steady_clock::now);
73 explicit Statistics() =
default;
75 explicit Statistics(
string const& p,
84 , min{sqlite::min(db, table, column)}
86 , max{sqlite::max(db, table, column)}
87 , median{sqlite::median(db, table, column)}
88 , rms{sqlite::rms(db, table, column)}
89 ,
n{sqlite::nrows(db, table)}
104 operator<<(ostream& os, Statistics
const& info)
106 string label{info.path};
107 if (!info.mod_label.empty()) {
108 label +=
':' + info.mod_label;
110 if (!info.mod_type.empty()) {
111 label +=
':' + info.mod_type;
113 os << label <<
" " << boost::format(
" %=12g ") % info.min
114 << boost::format(
" %=12g ") % info.mean
115 << boost::format(
" %=12g ") % info.max
116 << boost::format(
" %=12g ") % info.median
117 << boost::format(
" %=12g ") % info.rms
118 << boost::format(
" %=10d ") % info.n;
126 static constexpr
bool service_handle_allowed{
false};
145 template <
unsigned SIZE>
148 cet::sqlite::Ntuple<uint32_t, uint32_t, uint32_t, string, double>;
150 cet::sqlite::Ntuple<uint32_t, uint32_t, uint32_t, double>;
152 Ntuple<uint32_t, uint32_t, uint32_t, string, string, string, double>;
161 void recordTime(
ModuleContext const& mc,
string const& suffix);
162 void logToDestination_(Statistics
const&
evt,
163 vector<Statistics>
const& modules);
164 bool anyTableFull_()
const;
166 tbb::concurrent_unordered_map<ConcurrentKey,
171 unique_ptr<cet::sqlite::Connection>
const db_;
173 string sourceType_{};
183 : printSummary_{config().printSummary()}
185 ->
get(config().dbOutput().filename())}
209 areg.sPostSourceConstruction.watch(
this,
220 areg.sPostModule.watch(
221 [
this](
auto const& mc) { this->
recordTime(mc,
""s); });
223 areg.sPostWriteEvent.watch(
224 [
this](
auto const& mc) { this->
recordTime(mc,
"(write)"s); });
237 query_result<size_t> rEvents;
239 query_result<size_t> rModules;
241 auto const nEventRows = unique_value(rEvents);
242 auto const nModuleRows = unique_value(rModules);
243 if ((nEventRows == 0) && (nModuleRows == 0)) {
247 if (nEventRows == 0 && nModuleRows != 0) {
249 "Malformed TimeTracker database. The TimeEvent table is empty, but\n" 250 "the TimeModule table is not. This can happen if an exception has\n" 251 "been thrown from a module while processing the first event. Any\n" 252 "saved database file is suspect and should not be used."};
260 string const fullEventTime_ddl =
261 "CREATE TABLE temp.fullEventTime AS " 262 "SELECT Run,Subrun,Event,SUM(Time) AS FullEventTime FROM (" 263 " SELECT Run,Subrun,Event,Time FROM TimeEvent" 265 " SELECT Run,Subrun,Event,Time FROM TimeModule WHERE ModuleType " 268 " SELECT Run,Subrun,Event,Time FROM TimeSource" 269 ") GROUP BY Run,Subrun,Event";
271 exec(*
db_, fullEventTime_ddl);
272 Statistics
const evtStats{
273 "Full event",
"",
"", *
db_,
"temp.fullEventTime",
"FullEventTime"};
274 drop_table(*
db_,
"temp.fullEventTime");
275 query_result<string, string, string>
r;
276 r << select_distinct(
"Path",
"ModuleLabel",
"ModuleType")
278 vector<Statistics> modStats;
279 modStats.emplace_back(
280 "source",
sourceType_ +
"(read)",
"", *
db_,
"TimeSource",
"Time");
281 for (
auto const& row : r) {
282 auto const& [path, mod_label, mod_type] = row;
283 create_table_as(
"temp.tmpModTable",
285 .from(*
db_,
"TimeModule")
286 .where(
"Path='"s + path +
"'"s +
" AND ModuleLabel='"s +
287 mod_label +
"'"s +
" AND ModuleType='"s +
289 modStats.emplace_back(
290 path, mod_label, mod_type, *
db_,
"temp.tmpModTable",
"Time");
291 drop_table(*
db_,
"temp.tmpModTable");
294 ostringstream msgOss;
295 HorizontalRule
const rule{40};
298 <<
"The SQLite database connected to the TimeTracker exceeded the " 299 "available resources.\n" 300 <<
"No timing information summary is available.\n" 301 <<
"The database will contain an incomplete record of this job's " 302 "timing information.\n";
321 d.eventStart = now();
329 auto const t = chrono::duration<double>{now() -
d.eventStart}.count();
331 d.eventID.run(),
d.eventID.subRun(),
d.eventID.event(),
sourceType_, t);
339 assert(
d.eventID ==
e.id());
340 d.eventStart = now();
346 auto const&
d =
data_[key(sc.
id())];
347 auto const t = chrono::duration<double>{now() -
d.eventStart}.count();
349 d.eventID.run(),
d.eventID.subRun(),
d.eventID.event(), t);
356 data_[key(mc)].moduleStart = now();
362 auto const&
d =
data_[key(mc)];
363 auto const t = chrono::duration<double>{now() -
d.moduleStart}.count();
375 vector<Statistics>
const& modules)
378 auto identifier_size = [](Statistics
const& s) {
379 return s.path.size() + s.mod_label.size() + s.mod_type.size() +
382 cet::for_all(modules, [&identifier_size, &width](
auto const& mod) {
383 width = max(width, identifier_size(mod));
385 ostringstream msgOss;
386 HorizontalRule
const rule{width + 4 + 5 * 14 + 12};
389 << std::setw(width + 2) <<
std::left <<
"TimeTracker printout (sec)" 390 << boost::format(
" %=12s ") %
"Min" 391 << boost::format(
" %=12s ") %
"Avg" 392 << boost::format(
" %=12s ") %
"Max" 393 << boost::format(
" %=12s ") %
"Median" 394 << boost::format(
" %=12s ") %
"RMS" 395 << boost::format(
" %=10s ") %
"nEvts" <<
'\n';
396 msgOss << rule(
'=') <<
'\n';
398 msgOss <<
"[ No processed events ]\n";
402 msgOss << setw(width) << evt <<
'\n' << rule(
'-') <<
'\n';
403 for (
auto const& mod : modules) {
404 msgOss << setw(width) << mod <<
'\n';
void logToDestination_(Statistics const &evt, vector< Statistics > const &modules)
timeEvent_t timeEventTable_
void preEventReading(ScheduleContext)
tbb::concurrent_unordered_map< ConcurrentKey, PerScheduleData, ConcurrentKeyHasher > data_
auto const & pathName() const
cet::sqlite::Ntuple< uint32_t, uint32_t, uint32_t, string, double > timeSource_t
void preEventProcessing(Event const &, ScheduleContext)
name_array< 4u > const timeEventColumnNames_
cet::sqlite::Ntuple< uint32_t, uint32_t, uint32_t, double > timeEvent_t
void postEventProcessing(Event const &, ScheduleContext)
void postSourceConstruction(ModuleDescription const &)
cet::sqlite::name_array< SIZE > name_array
std::string const & moduleName() const
auto const & moduleName() const
void postEventReading(Event const &, ScheduleContext)
timeModule_t timeModuleTable_
#define DECLARE_ART_SERVICE(svc, scope)
unique_ptr< cet::sqlite::Connection > const db_
name_array< 7u > const timeModuleColumnNames_
timeSource_t timeSourceTable_
steady_clock::time_point moduleStart
void recordTime(ModuleContext const &mc, string const &suffix)
name_array< 5u > const timeSourceColumnNames_
Stream & operator<<(Stream &&out, CallInfo_t const &info)
Helper operator to insert a call information in a stream with default options.
#define DEFINE_ART_SERVICE(svc)
constexpr auto const & left(const_AssnsIter< L, R, D, Dir > const &a, const_AssnsIter< L, R, D, Dir > const &b)
double mean(const std::vector< short > &wf, size_t start, size_t nsample)
void startTime(ModuleContext const &mc)
bool anyTableFull_() const
auto const & moduleLabel() const
static constexpr EventID invalidEvent() noexcept
steady_clock::time_point eventStart
MaybeLogger_< ELseverityLevel::ELsev_severe, true > LogAbsolute
bool const overwriteContents_
cet::sqlite::Ntuple< uint32_t, uint32_t, uint32_t, string, string, string, double > timeModule_t