Fawkes API  Fawkes Development Version
tracker.cpp
1 
2 /***************************************************************************
3  * tracker.cpp - Implementation of time tracker
4  *
5  * Created: Fri Jun 03 13:43:33 2005 (copied from RCSoft5 FireVision)
6  * Copyright 2005-2009 Tim Niemueller [www.niemueller.de]
7  *
8  ****************************************************************************/
9 
10 /* This program is free software; you can redistribute it and/or modify
11  * it under the terms of the GNU General Public License as published by
12  * the Free Software Foundation; either version 2 of the License, or
13  * (at your option) any later version. A runtime exception applies to
14  * this software (see LICENSE.GPL_WRE file mentioned below for details).
15  *
16  * This program is distributed in the hope that it will be useful,
17  * but WITHOUT ANY WARRANTY; without even the implied warranty of
18  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
19  * GNU Library General Public License for more details.
20  *
21  * Read the full text in the LICENSE.GPL_WRE file in the doc directory.
22  */
23 
24 #include <core/exceptions/software.h>
25 #include <core/exceptions/system.h>
26 #include <utils/time/tracker.h>
27 
28 #include <cerrno>
29 #include <cmath>
30 #include <cstdio>
31 #include <cstdlib>
32 #include <iostream>
33 
34 using namespace std;
35 
36 namespace fawkes {
37 
38 /** @class TimeTracker <utils/time/tracker.h>
39  * Time tracking utility.
40  * This class provides means to track time of different tasks in a process.
41  * You can assign an arbitrary number of tracking classes per object (although
42  * using a few classes is recommended for minimal influence of the measurement
43  * on the measured process). You can then print out averages and (max) deviation
44  * to get a feeling for the average performance and how flaky the runtimes are.
45  *
46  * The time tracker can also be operated without any class if you only want to
47  * track a single process.
48  *
49  * You can either just ping classless or a specific class which will then take
50  * the time difference between now and the last ping as the measured time. This
51  * is useful to determine the call frequency of a given item.
52  * If you want to benchmark sub-tasks you more likely want to start measuring at
53  * a specific point in time and then stop it after the sub-task is done to measure
54  * only this very task. This can be done by using pingStart() and pingEnd().
55  *
56  * @author Tim Niemueller
57  */
58 
59 /** The default tracking class. Optionally added in the constructor. */
60 const unsigned int TimeTracker::DEFAULT_CLASS = 0;
61 
62 /** Constructor.
63  * @param add_default_class if true a default time class is added.
64  */
65 TimeTracker::TimeTracker(bool add_default_class)
66 {
67  timelog_ = NULL;
68  write_cycle_ = 0;
69  reset();
70  if (add_default_class) {
71  class_times_.push_back(vector<struct timeval *>());
72  class_names_.push_back("Default");
73  }
74 }
75 
76 /** Constructor for file logging.
77  * @param filename name of the file to write log data to. File is overwritten.
78  * @param add_default_class if true a default time class is added.
79  */
80 TimeTracker::TimeTracker(const char *filename, bool add_default_class)
81 {
82  write_cycle_ = 0;
83  reset();
84  if (add_default_class) {
85  class_times_.push_back(vector<struct timeval *>());
86  class_names_.push_back("Default");
87  }
88  timelog_ = fopen(filename, "w");
89  if (!timelog_) {
90  throw CouldNotOpenFileException(filename, errno, "Failed to open time log");
91  }
92 }
93 
94 /** Destructor. */
95 TimeTracker::~TimeTracker()
96 {
97  if (timelog_) {
98  fclose(timelog_);
99  }
100  reset();
101  class_times_.clear();
102  class_names_.clear();
103 }
104 
105 /** Reset times.
106  * Reset tracker and set comment.
107  * @param comment comment to set on tracker.
108  */
109 void
110 TimeTracker::reset(std::string comment)
111 {
112  tracker_comment_ = comment;
113  for (vector<vector<struct timeval *>>::iterator i = class_times_.begin(); i != class_times_.end();
114  ++i) {
115  for (vector<struct timeval *>::iterator j = i->begin(); j != i->end(); ++j) {
116  free(*j);
117  }
118  i->clear();
119  }
120  times_.clear();
121  comments_.clear();
122  gettimeofday(&start_time, NULL);
123  gettimeofday(&last_time, NULL);
124 }
125 
126 /** Ping classless.
127  * This takes the time difference between now and the last ping and adds this
128  * to classless tracking.
129  * @param comment optional ping comment.
130  */
131 void
132 TimeTracker::ping(std::string comment)
133 {
134  timeval *t = (timeval *)malloc(sizeof(timeval));
135  gettimeofday(t, NULL);
136  times_.push_back(t);
137  if (!comment.empty()) {
138  comments_[times_.size() - 1] = comment;
139  }
140 }
141 
142 /** Add a new class.
143  * Adds a new class and gives the class ID.
144  * @param name name of the class
145  * @return new class ID which is used for pinging this specific
146  * class.
147  */
148 unsigned int
149 TimeTracker::add_class(std::string name)
150 {
151  if (name == "") {
152  throw Exception("TimeTracker::add_class(): Class name may not be empty");
153  }
154  class_times_.push_back(vector<struct timeval *>());
155  class_names_.push_back(name);
156  return class_times_.size() - 1;
157 }
158 
159 /** Remove a class.
160  * This marks the class as unused. It is not longer possible to add times to this
161  * class but they will not be printed anymore. The space associated with this
162  * class is freed.
163  * @param cls ID of the class to remove
164  */
165 void
166 TimeTracker::remove_class(unsigned int cls)
167 {
168  if (cls < class_names_.size()) {
169  class_names_[cls] = "";
170  } else {
171  if (class_times_.size() == 0) {
172  throw Exception("No classes have been added, cannot delete class %u", cls);
173  } else {
174  throw OutOfBoundsException("Invalid class given", cls, 0, class_times_.size() - 1);
175  }
176  }
177 }
178 
179 /** Ping class.
180  * This takes the time difference between now and the last ping and adds this
181  * to class cls.
182  * @param cls class ID to ping
183  */
184 void
185 TimeTracker::ping(unsigned int cls)
186 {
187  timeval *t = (timeval *)malloc(sizeof(timeval));
188  gettimeofday(t, NULL);
189 
190  long sec = t->tv_sec - last_time.tv_sec;
191  long usec = t->tv_usec - last_time.tv_usec;
192  if (usec < 0) {
193  sec -= 1;
194  usec += 1000000;
195  }
196  last_time.tv_sec = t->tv_sec;
197  last_time.tv_usec = t->tv_usec;
198 
199  t->tv_sec = sec;
200  t->tv_usec = usec;
201 
202  if (cls < class_times_.size()) {
203  class_times_[cls].push_back(t);
204  } else {
205  if (class_times_.size() == 0) {
206  throw Exception("No classes have been added, cannot track times");
207  } else {
208  throw OutOfBoundsException("Invalid class given", cls, 0, class_times_.size() - 1);
209  }
210  }
211 }
212 
213 /** Start of given class task.
214  * Signal the start of the given class.
215  * @param cls class ID
216  */
217 void
218 TimeTracker::ping_start(unsigned int cls)
219 {
220  if (cls >= class_times_.size())
221  return;
222 
223  timeval *t = (timeval *)malloc(sizeof(timeval));
224  gettimeofday(t, NULL);
225 
226  if (cls < class_times_.size()) {
227  class_times_[cls].push_back(t);
228  } else {
229  if (class_times_.size() == 0) {
230  throw Exception("No classes have been added, cannot track times");
231  } else {
232  throw OutOfBoundsException("Invalid class given", cls, 0, class_times_.size() - 1);
233  }
234  }
235 }
236 
237 /** End of given class task.
238  * This takes the time difference between now and the last pingStart() for the
239  * class cls.
240  * @param cls class ID to signal end of task
241  */
242 void
243 TimeTracker::ping_end(unsigned int cls)
244 {
245  if (cls >= class_times_.size())
246  return;
247 
248  timeval t2;
249  gettimeofday(&t2, NULL);
250 
251  timeval *t1 = class_times_[cls].back();
252 
253  long sec = t2.tv_sec - t1->tv_sec;
254  long usec = t2.tv_usec - t1->tv_usec;
255 
256  if (usec < 0) {
257  sec -= 1;
258  usec += 1000000;
259  }
260 
261  t1->tv_sec = sec;
262  t1->tv_usec = usec;
263 }
264 
265 /** End of given class task without recording.
266  * End the duration but do not take the time into the result measurements.
267  * @param cls class ID to signal end of task
268  */
269 void
270 TimeTracker::ping_abort(unsigned int cls)
271 {
272  if (cls >= class_times_.size())
273  return;
274 
275  free(class_times_[cls].back());
276  class_times_[cls].pop_back();
277 }
278 
279 void
280 TimeTracker::average_and_deviation(vector<struct timeval *> &values,
281  double & average_sec,
282  double & average_ms,
283  double & deviation_sec,
284  double & deviation_ms)
285 {
286  vector<struct timeval *>::iterator tit;
287 
288  average_sec = average_ms = deviation_sec = deviation_ms = 0.f;
289 
290  for (tit = values.begin(); tit != values.end(); ++tit) {
291  average_sec += float((*tit)->tv_sec);
292  average_sec += (*tit)->tv_usec / 1000000.f;
293  }
294  average_sec /= values.size();
295 
296  for (tit = values.begin(); tit != values.end(); ++tit) {
297  deviation_sec += fabs((*tit)->tv_sec + ((*tit)->tv_usec / 1000000.f) - average_sec);
298  }
299  deviation_sec /= values.size();
300 
301  average_ms = average_sec * 1000.f;
302  deviation_ms = deviation_sec * 1000.f;
303 }
304 
305 /** Print results to stdout. */
306 void
307 TimeTracker::print_to_stdout()
308 {
309  if (!times_.empty()) {
310  unsigned int i = 0;
311  unsigned int j = 0;
312  long diff_sec_start = 0;
313  long diff_usec_start = 0;
314  long diff_sec_last = 0;
315  long diff_usec_last = 0;
316  float diff_msec_start = 0.0;
317  float diff_msec_last = 0.0;
318  time_t last_sec = start_time.tv_sec;
319  suseconds_t last_usec = start_time.tv_usec;
320  char time_string[26];
321 
322  ctime_r(&(start_time.tv_sec), time_string);
323  for (j = 26; j > 0; --j) {
324  if (time_string[j] == '\n') {
325  time_string[j] = 0;
326  break;
327  }
328  }
329 
330  cout << endl << "TimeTracker stats - individual times";
331  if (tracker_comment_.empty()) {
332  cout << " (" << tracker_comment_ << ")";
333  }
334  cout << endl
335  << "==================================================================" << endl
336  << "Initialized: " << time_string << " (" << start_time.tv_sec << ")" << endl
337  << endl;
338 
339  for (time_it_ = times_.begin(); time_it_ != times_.end(); ++time_it_) {
340  char tmp[10];
341  sprintf(tmp, "%3u.", i + 1);
342  cout << tmp;
343  if (comments_.count(i) > 0) {
344  cout << " (" << comments_[i] << ")";
345  }
346  cout << endl;
347 
348  diff_sec_start = (*time_it_)->tv_sec - start_time.tv_sec;
349  diff_usec_start = (*time_it_)->tv_usec - start_time.tv_usec;
350  if (diff_usec_start < 0) {
351  diff_sec_start -= 1;
352  diff_usec_start = 1000000 + diff_usec_start;
353  }
354  diff_msec_start = diff_usec_start / 1000.f;
355 
356  diff_sec_last = (*time_it_)->tv_sec - last_sec;
357  diff_usec_last = (*time_it_)->tv_usec - last_usec;
358  if (diff_usec_last < 0) {
359  diff_sec_last -= 1;
360  diff_usec_last = 1000000 + diff_usec_last;
361  }
362  diff_msec_last = diff_usec_last / 1000.f;
363 
364  last_sec = (*time_it_)->tv_sec;
365  last_usec = (*time_it_)->tv_usec;
366 
367  ctime_r(&(*time_it_)->tv_sec, time_string);
368  for (j = 26; j > 0; --j) {
369  if (time_string[j] == '\n') {
370  time_string[j] = 0;
371  break;
372  }
373  }
374  cout << time_string << " (" << (*time_it_)->tv_sec << ")" << endl;
375  cout << "Diff to start: " << diff_sec_start << " sec and " << diff_usec_start
376  << " usec (which are " << diff_msec_start << " msec)" << endl;
377  cout << "Diff to last: " << diff_sec_last << " sec and " << diff_usec_last
378  << " usec (which are " << diff_msec_last << " msec)" << endl
379  << endl;
380 
381  i += 1;
382  }
383  }
384 
385  cout << endl << "TimeTracker stats - class times";
386  if (!tracker_comment_.empty()) {
387  cout << " (" << tracker_comment_ << ")";
388  }
389  cout << endl << "==================================================================" << endl;
390 
391  vector<vector<struct timeval *>>::iterator it = class_times_.begin();
392  vector<string>::iterator sit = class_names_.begin();
393 
394  double deviation = 0.f;
395  double average = 0.f;
396  double average_ms = 0.f;
397  double deviation_ms = 0.f;
398 
399  for (; (it != class_times_.end()) && (sit != class_names_.end()); ++it, ++sit) {
400  if (sit->empty())
401  continue;
402 
403  if (it->size() > 0) {
404  average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
405 
406  cout << "Class '" << *sit << "'" << endl
407  << " avg=" << average << " (" << average_ms << " ms)" << endl
408  << " dev=" << deviation << " (" << deviation_ms << " ms)" << endl
409  << " res=" << it->size() << " results" << endl;
410  } else {
411  cout << "Class '" << *sit << "' has no results." << endl;
412  }
413  }
414 
415  cout << endl;
416 }
417 
418 /** Print data to file suitable for gnuplot.
419  * This will write the following data:
420  * average sec, average ms, average summed sec, deviation sec, deviation ms
421  * This data is generated for each class and concatenated into a single line
422  * and written to the file. A running number will be prepended as the first
423  * value. The data file is suitable as input for gnuplot.
424  */
425 void
426 TimeTracker::print_to_file()
427 {
428  if (!timelog_)
429  throw Exception("Time log not opened, use other ctor");
430 
431  vector<vector<struct timeval *>>::iterator it = class_times_.begin();
432  vector<string>::iterator sit = class_names_.begin();
433 
434  double deviation = 0.f;
435  double average = 0.f;
436  double average_ms = 0.f;
437  double deviation_ms = 0.f;
438  double avgsum = 0.f;
439 
440  fprintf(timelog_, "%u ", ++write_cycle_);
441  for (; (it != class_times_.end()) && (sit != class_names_.end()); ++it, ++sit) {
442  if (sit->empty())
443  continue;
444 
445  average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
446 
447  avgsum += average;
448  fprintf(timelog_, "%lf %lf %lf %lf %lf ", average, average_ms, avgsum, deviation, deviation_ms);
449  }
450  fprintf(timelog_, "\n");
451  fflush(timelog_);
452 }
453 
454 /** @class ScopedClassItemTracker "utils/time/tracker.h"
455  * Scoped time tracking for specific item.
456  * @author Victor Matare
457  */
458 
459 /** Constructor.
460  * Starts time tracking for given class on given time tracker.
461  * @param tt time tracker
462  * @param cls class ID
463  */
464 ScopedClassItemTracker::ScopedClassItemTracker(TimeTracker &tt, unsigned int cls)
465 : tt_(tt), cls_(cls)
466 {
467  tt_.ping_start(cls_);
468 }
469 
470 /** Destructor. */
472 {
473  tt_.ping_end(cls_);
474 }
475 
476 } // end namespace fawkes
fawkes::TimeTracker::ping_start
void ping_start(unsigned int cls)
Start of given class task.
Definition: tracker.cpp:218
fawkes::OutOfBoundsException
Index out of bounds.
Definition: software.h:86
fawkes::CouldNotOpenFileException
File could not be opened.
Definition: system.h:53
fawkes
Fawkes library namespace.
fawkes::ScopedClassItemTracker::~ScopedClassItemTracker
~ScopedClassItemTracker()
Destructor.
Definition: tracker.cpp:471
fawkes::TimeTracker
Time tracking utility.
Definition: tracker.h:37
fawkes::TimeTracker::ping_end
void ping_end(unsigned int cls)
End of given class task.
Definition: tracker.cpp:243
fawkes::Exception
Base class for exceptions in Fawkes.
Definition: exception.h:36