MRPT  1.9.9
CTimeLogger.cpp
Go to the documentation of this file.
1 /* +------------------------------------------------------------------------+
2  | Mobile Robot Programming Toolkit (MRPT) |
3  | https://www.mrpt.org/ |
4  | |
5  | Copyright (c) 2005-2019, Individual contributors, see AUTHORS file |
6  | See: https://www.mrpt.org/Authors - All rights reserved. |
7  | Released under BSD License. See: https://www.mrpt.org/License |
8  +------------------------------------------------------------------------+ */
9 
10 #include "system-precomp.h" // Precompiled headers
11 
12 #include <mrpt/core/bits_math.h>
14 #include <mrpt/system/datetime.h>
15 #include <mrpt/system/filesystem.h>
17 #include <algorithm>
18 #include <fstream>
19 #include <iostream>
20 
21 using namespace mrpt;
22 using namespace mrpt::system;
23 using namespace std;
24 
26 {
27  MyGlobalProfiler() : mrpt::system::CTimeLogger("MRPT_global_profiler") {}
28  ~MyGlobalProfiler() override
29  {
30  try
31  {
32  if (!m_data.empty())
33  {
34  const std::string sFil("mrpt-global-profiler.csv");
35  this->saveToCSVFile(sFil);
36  std::cout << "[MRPT global profiler] Write stats to: " << sFil
37  << std::endl;
38  }
39  }
40  catch (...)
41  {
42  }
43  }
44  MyGlobalProfiler(const MyGlobalProfiler&) = delete;
46  MyGlobalProfiler& operator=(const MyGlobalProfiler&) = delete;
47  MyGlobalProfiler& operator=(MyGlobalProfiler&&) = delete;
48 };
50 
51 namespace mrpt::system
52 {
54 void global_profiler_enter(const char* func_name) noexcept
55 {
56  global_profiler.enter(func_name);
57 }
58 void global_profiler_leave(const char* func_name) noexcept
59 {
60  global_profiler.leave(func_name);
61 }
62 } // namespace mrpt::system
63 
65  bool enabled, const std::string& name, const bool keep_whole_history)
66  : COutputLogger("CTimeLogger"),
67  m_tictac(),
68  m_enabled(enabled),
69  m_name(name),
70  m_keep_whole_history(keep_whole_history)
71 {
72  m_tictac.Tic();
73 }
74 
76 {
77  // Dump all stats:
78  if (!m_data.empty()) // If logging is disabled, do nothing...
79  dumpAllStats();
80 }
81 
83 {
84  if (deep_clear)
85  m_data.clear();
86  else
87  {
88  for (auto& e : m_data) e.second = TCallData();
89  }
90 }
91 
92 std::string aux_format_string_multilines(const std::string& s, const size_t len)
93 {
94  std::string ret;
95 
96  for (size_t p = 0; p < s.size(); p += len)
97  {
98  ret += rightPad(s.substr(p), len, true);
99  if (p + len < s.size()) ret += "\n";
100  }
101  return ret;
102 }
103 
104 void CTimeLogger::getStats(std::map<std::string, TCallStats>& out_stats) const
105 {
106  out_stats.clear();
107  for (const auto& e : m_data)
108  {
109  TCallStats& cs = out_stats[std::string(e.first)];
110  cs.min_t = e.second.min_t;
111  cs.max_t = e.second.max_t;
112  cs.total_t = e.second.mean_t;
113  cs.mean_t = e.second.n_calls ? e.second.mean_t / e.second.n_calls : 0;
114  cs.n_calls = e.second.n_calls;
115  cs.last_t = e.second.last_t;
116  }
117 }
118 
119 std::string CTimeLogger::getStatsAsText(const size_t column_width) const
120 {
121  using std::string;
122  using namespace std::string_literals;
123 
124  string stats_text;
125  string name_tmp = m_name.size() != 0 ? " "s + m_name + ": "s : " "s;
126  string mrpt_string = "MRPT CTimeLogger report "s;
127 
128  string top_header(name_tmp + mrpt_string);
129  // append dashes to the header to reach column_width
130  {
131  const auto space_to_fill = top_header.size() < column_width
132  ? (column_width - top_header.size()) / 2
133  : 2;
134  std::string dashes_half(space_to_fill, '-');
135  top_header = dashes_half + top_header + dashes_half;
136  if (dashes_half.size() % 2)
137  { // what if column_width-top_header.size() is odd?
138  top_header += '-';
139  }
140  }
141 
142  std::string middle_header(
143  " FUNCTION #CALLS MIN.T MEAN.T "
144  "MAX.T TOTAL ");
145  std::string bottom_header(column_width, '-');
146 
147  stats_text += top_header + "\n"s;
148  stats_text += middle_header + "\n"s;
149  stats_text += bottom_header + "\n"s;
150 
151  // for all the timed sections: sort by inserting into a std::map
152  using NameAndCallData = std::map<std::string_view, TCallData>;
153  NameAndCallData stat_strs;
154  for (const auto& i : m_data) stat_strs[i.first] = i.second;
155 
156  // format tree-like patterns like:
157  // ----------
158  // foobar
159  // foobar.a
160  // foobar.b
161  // ----------
162  // like:
163  // ----------
164  // foobar
165  // +-> a
166  // +-> b
167  // ----------
168  std::string last_parent;
169  for (const auto& i : stat_strs)
170  {
171  string line = string(i.first); // make a copy
172 
173  const auto dot_pos = line.find(".");
174  if (dot_pos == std::string::npos)
175  {
176  last_parent = line;
177  }
178  else
179  {
180  const auto parent_pos = line.find(last_parent);
181  if (parent_pos != std::string::npos)
182  {
183  line = "+-> "s + line.substr(dot_pos);
184  }
185  }
186 
187  const string sMinT = unitsFormat(i.second.min_t, 1, false);
188  const string sMaxT = unitsFormat(i.second.max_t, 1, false);
189  const string sTotalT = unitsFormat(i.second.mean_t, 1, false);
190  const string sMeanT = unitsFormat(
191  i.second.n_calls ? i.second.mean_t / i.second.n_calls : 0, 1,
192  false);
193 
194  stats_text += mrpt::format(
195  "%s %7u %6s%c %6s%c %6s%c %6s%c\n",
196  aux_format_string_multilines(line, 39).c_str(),
197  static_cast<unsigned int>(i.second.n_calls), sMinT.c_str(),
198  i.second.has_time_units ? 's' : ' ', sMeanT.c_str(),
199  i.second.has_time_units ? 's' : ' ', sMaxT.c_str(),
200  i.second.has_time_units ? 's' : ' ', sTotalT.c_str(),
201  i.second.has_time_units ? 's' : ' ');
202  }
203 
204  std::string footer(top_header);
205  stats_text += footer + "\n";
206 
207  return stats_text;
208 }
209 
210 void CTimeLogger::saveToCSVFile(const std::string& csv_file) const
211 {
212  std::string s;
213  s += "FUNCTION, #CALLS, LAST.T, MIN.T, MEAN.T, MAX.T, TOTAL.T [, "
214  "WHOLE_HISTORY]\n";
215  for (const auto& i : m_data)
216  {
217  s += format(
218  "\"%.*s\",%7u,%e,%e,%e,%e,%e", static_cast<int>(i.first.size()),
219  i.first.data(), static_cast<unsigned int>(i.second.n_calls),
220  i.second.last_t, i.second.min_t,
221  i.second.n_calls ? i.second.mean_t / i.second.n_calls : 0,
222  i.second.max_t, i.second.mean_t);
223 
224  if (i.second.whole_history)
225  {
226  const auto& wh = i.second.whole_history.value();
227  for (const double v : wh)
228  {
229  s += ", ";
230  s += std::to_string(v);
231  }
232  }
233  s += "\n";
234  }
235  std::ofstream(csv_file) << s;
236 }
237 
238 void CTimeLogger::saveToMFile(const std::string& file) const
239 {
240  using std::string;
241  using namespace std::string_literals;
242 
243  string s;
244  s += "function [s] = "s + mrpt::system::extractFileName(file) +
245  "()\n"
246  "s = struct();\n"
247  "s.whole = struct();\n\n"s;
248 
249  std::string s_names = "s.names={"s;
250  std::string s_counts = "s.count=["s;
251  std::string s_mins = "s.min=["s;
252  std::string s_maxs = "s.max=["s;
253  std::string s_means = "s.mean=["s;
254 
255  for (const auto& i : m_data)
256  {
257  s_names += "'"s + i.first + "',"s;
258  s_counts += std::to_string(i.second.n_calls) + ","s;
259  s_mins += mrpt::format("%e,", i.second.min_t);
260  s_maxs += mrpt::format("%e,", i.second.max_t);
261  s_means += mrpt::format("%e,", i.second.mean_t);
262 
263  if (i.second.whole_history)
264  {
265  string clean_name =
267  std::replace(clean_name.begin(), clean_name.end(), '.', '_');
268  std::replace(clean_name.begin(), clean_name.end(), '-', '_');
269  std::replace(clean_name.begin(), clean_name.end(), '+', '_');
270  std::replace(clean_name.begin(), clean_name.end(), '*', '_');
271 
272  s += "s.whole."s + clean_name + "=[";
273  const auto& wh = i.second.whole_history.value();
274  for (const double v : wh) s += mrpt::format("%e,", v);
275  s += "];\n";
276  }
277  }
278  s_names += "};\n"s;
279  s_counts += "];\n"s;
280  s_mins += "];\n"s;
281  s_maxs += "];\n"s;
282  s_means += "];\n"s;
283 
284  s += s_names;
285  s += s_counts;
286  s += s_mins;
287  s += s_maxs;
288  s += s_means;
289 
290  s += "\n"s;
291  std::ofstream(file) << s;
292 }
293 
294 void CTimeLogger::dumpAllStats(const size_t column_width) const
295 {
296  MRPT_LOG_INFO_STREAM("dumpAllStats:\n" << getStatsAsText(column_width));
297 }
298 
299 void CTimeLogger::do_enter(const std::string_view& func_name) noexcept
300 {
301  TCallData* d_ptr = m_data.find_or_alloc(std::string(func_name));
302  if (!d_ptr)
303  {
304  std::cerr << "[CTimeLogger::do_enter] Warning: skipping due to hash "
305  "collision.\n";
306  return;
307  }
308  auto& d = *d_ptr;
309  d.n_calls++;
310  d.open_calls.push(0); // Dummy value, it'll be written below
311  d.open_calls.top() = m_tictac.Tac(); // to avoid possible delays.
312 }
313 
314 double CTimeLogger::do_leave(const std::string_view& func_name) noexcept
315 {
316  const double tim = m_tictac.Tac();
317 
318  TCallData* d_ptr = m_data.find_or_alloc(std::string(func_name));
319  if (!d_ptr)
320  {
321  std::cerr << "[CTimeLogger::do_enter] Warning: skipping due to hash "
322  "collision.\n";
323  return .0;
324  }
325  auto& d = *d_ptr;
326 
327  if (!d.open_calls.empty())
328  {
329  const double At = tim - d.open_calls.top();
330  d.open_calls.pop();
331 
332  d.last_t = At;
333  d.mean_t += At;
334  if (d.n_calls == 1)
335  {
336  d.min_t = At;
337  d.max_t = At;
338  }
339  else
340  {
341  mrpt::keep_min(d.min_t, At);
342  mrpt::keep_max(d.max_t, At);
343  }
345  {
346  // Init the first time:
347  if (!d.whole_history)
348  d.whole_history = decltype(d.whole_history)::value_type();
349  // Append to history:
350  d.whole_history.value().push_back(At);
351  }
352  return At;
353  }
354  else
355  return 0; // This shouldn't happen!
356 }
357 
359  const std::string_view& event_name, const double value,
360  const bool is_time) noexcept
361 {
362  if (!m_enabled) return;
363  TCallData* d_ptr = m_data.find_or_alloc(std::string(event_name));
364  if (!d_ptr)
365  {
366  std::cerr << "[CTimeLogger::do_enter] Warning: skipping due to hash "
367  "collision.\n";
368  return;
369  }
370  auto& d = *d_ptr;
371 
372  d.has_time_units = is_time;
373  d.last_t = value;
374  d.mean_t += value;
375  if (++d.n_calls == 1)
376  {
377  d.min_t = value;
378  d.max_t = value;
379  }
380  else
381  {
382  mrpt::keep_min(d.min_t, value);
383  mrpt::keep_max(d.max_t, value);
384  }
386  {
387  // Init the first time:
388  if (!d.whole_history)
389  d.whole_history = decltype(d.whole_history)::value_type();
390  // Append to history:
391  d.whole_history.value().push_back(value);
392  }
393 }
394 
396 
397 double CTimeLogger::getMeanTime(const std::string& name) const
398 {
399  TDataMap::const_iterator it = m_data.find(name);
400  if (it == m_data.end())
401  return 0;
402  else
403  return it->second.n_calls ? it->second.mean_t / it->second.n_calls : 0;
404 }
405 double CTimeLogger::getLastTime(const std::string& name) const
406 {
407  TDataMap::const_iterator it = m_data.find(name);
408  if (it == m_data.end())
409  return 0;
410  else
411  return it->second.last_t;
412 }
413 
415  const CTimeLogger& logger, const std::string_view& section_name)
416  : m_logger(const_cast<CTimeLogger&>(logger)), m_section_name(section_name)
417 {
419 }
421 {
422  if (stopped_) return;
423  const auto leave = mrpt::Clock::now();
424  const double dt = mrpt::system::timeDifference(m_entry, leave);
425 
427  stopped_ = true;
428 }
429 
431 {
432  try
433  {
434  stop();
435  }
436  catch (const std::exception& e)
437  {
438  std::cerr << "[~CTimeLoggerEntry] Exception:\n"
440  }
441 }
442 
444 {
445  try
446  {
447  using namespace std::string_literals;
448  auto name = m_tm.getName() + ".m"s;
449  name = fileNameStripInvalidChars(name);
450 
451  m_tm.logStr(
452  LVL_INFO,
453  "[CTimeLoggerSaveAtDtor] Saving stats to: `"s + name + "`"s);
454  m_tm.saveToMFile(name);
455  }
456  catch (const std::exception& e)
457  {
458  std::cerr << "[~CTimeLoggerSaveAtDtor] Exception:\n"
460  }
461 }
double Tac() noexcept
Stops the stopwatch.
Definition: CTicTac.cpp:86
void keep_min(T &var, const K test_val)
If the second argument is below the first one, set the first argument to this lower value...
std::string to_string(T v)
Just like std::to_string(), but with an overloaded version for std::string arguments.
Definition: format.h:36
bool stopped_
void clear(bool deep_clear=false)
Resets all stats.
Definition: CTimeLogger.cpp:82
std::string std::string format(std::string_view fmt, ARGS &&... args)
Definition: format.h:26
void registerUserMeasure(const std::string_view &event_name, const double value, const bool is_time=false) noexcept
CTimeLogger & m_logger
mrpt::system::CTimeLogger & m_tm
void dumpAllStats(const size_t column_width=80) const
Dump all stats through the COutputLogger interface.
STL namespace.
std::string fileNameStripInvalidChars(const std::string &filename, const char replacement_to_invalid_chars='_')
Replace invalid filename chars by underscores (&#39;_&#39;) or any other user-given char. ...
Definition: filesystem.cpp:329
~MyGlobalProfiler() override
Definition: CTimeLogger.cpp:28
mrpt::system::CTimeLogger & global_profiler_getref() noexcept
Definition: CTimeLogger.cpp:53
double getLastTime(const std::string &name) const
Return the last execution time of the given "section", or 0 if it hasn&#39;t ever been called "enter" wit...
void getStats(std::map< std::string, TCallStats > &out_stats) const
Returns all the current stats as a map: section_name => stats.
static time_point now() noexcept
Returns the current time, with the highest resolution available.
Definition: Clock.cpp:46
void stop()
for correct use, see docs for CTimeLoggerEntry
std::string getStatsAsText(const size_t column_width=80) const
Dump all stats to a multi-line text string.
static MyGlobalProfiler global_profiler
Definition: CTimeLogger.cpp:49
std::stack< double, std::vector< double > > open_calls
void global_profiler_enter(const char *func_name) noexcept
Definition: CTimeLogger.cpp:54
void saveToMFile(const std::string &m_file) const
Dump all stats to a Matlab/Octave (.m) file.
Versatile class for consistent logging and management of output messages.
const std::string m_section_name
double do_leave(const std::string_view &func_name) noexcept
CTimeLogger(bool enabled=true, const std::string &name="", const bool keep_whole_history=false)
Definition: CTimeLogger.cpp:64
mrpt::Clock::time_point m_entry
void do_enter(const std::string_view &func_name) noexcept
double getMeanTime(const std::string &name) const
Return the mean execution time of the given "section", or 0 if it hasn&#39;t ever been called "enter" wit...
void keep_max(T &var, const K test_val)
If the second argument is above the first one, set the first argument to this higher value...
#define MRPT_LOG_INFO_STREAM(__CONTENTS)
void enter(const std::string_view &func_name) noexcept
Start of a named section.
void global_profiler_leave(const char *func_name) noexcept
Definition: CTimeLogger.cpp:58
This is the global namespace for all Mobile Robot Programming Toolkit (MRPT) libraries.
const std::string & getName() const noexcept
std::string unitsFormat(const double val, int nDecimalDigits=2, bool middle_space=true)
This function implements formatting with the appropriate SI metric unit prefix: 1e-12->&#39;p&#39;, 1e-9->&#39;n&#39;, 1e-6->&#39;u&#39;, 1e-3->&#39;m&#39;, 1->&#39;&#39;, 1e3->&#39;K&#39;, 1e6->&#39;M&#39;, 1e9->&#39;G&#39;, 1e12->&#39;T&#39;.
A versatile "profiler" that logs the time spent within each pair of calls to enter(X)-leave(X), among other stats.
void logStr(const VerbosityLevel level, std::string_view msg_str) const
Main method to add the specified message string to the logger.
void saveToCSVFile(const std::string &csv_file) const
Dump all stats to a Comma Separated Values (CSV) file.
void deep_clear(CONTAINER &c)
Deep clear for a std vector container.
Data of each call section: # of calls, minimum, maximum, average and overall execution time (in secon...
std::string aux_format_string_multilines(const std::string &s, const size_t len)
Definition: CTimeLogger.cpp:92
double leave(const std::string_view &func_name) noexcept
End of a named section.
std::string exception_to_str(const std::exception &e)
Builds a nice textual representation of a nested exception, which if generated using MRPT macros (THR...
Definition: exceptions.cpp:59
~CTimeLoggerEntry()
std::string rightPad(const std::string &str, const size_t total_len, bool truncate_if_larger=false)
Enlarge the string with spaces up to the given length.
double timeDifference(const mrpt::system::TTimeStamp t_first, const mrpt::system::TTimeStamp t_later)
Returns the time difference from t1 to t2 (positive if t2 is posterior to t1), in seconds...
Definition: datetime.h:123
void Tic() noexcept
Starts the stopwatch.
Definition: CTicTac.cpp:75
std::string extractFileName(const std::string &filePath)
Extract just the name (without extension) of a filename from a complete path plus name plus extension...
Definition: filesystem.cpp:62
CTimeLoggerEntry(const CTimeLogger &logger, const std::string_view &section_name)
~CTimeLogger() override
Destructor.
Definition: CTimeLogger.cpp:75



Page generated by Doxygen 1.8.14 for MRPT 1.9.9 Git: 7e629e01a Sat Dec 14 00:05:55 2019 +0100 at sáb dic 14 00:15:10 CET 2019