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