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
34using namespace std;
35
36namespace 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. */
60const unsigned int TimeTracker::DEFAULT_CLASS = 0;
61
62/** Constructor.
63 * @param add_default_class if true a default time class is added.
64 */
65TimeTracker::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 */
80TimeTracker::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. */
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 */
109void
110TimeTracker::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 */
131void
132TimeTracker::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 */
148unsigned int
149TimeTracker::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 */
165void
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 */
184void
185TimeTracker::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 */
217void
218TimeTracker::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 */
242void
243TimeTracker::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 */
269void
270TimeTracker::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
279void
280TimeTracker::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. */
306void
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 */
425void
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 */
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
File could not be opened.
Definition: system.h:53
Base class for exceptions in Fawkes.
Definition: exception.h:36
Index out of bounds.
Definition: software.h:86
~ScopedClassItemTracker()
Destructor.
Definition: tracker.cpp:471
ScopedClassItemTracker(TimeTracker &tt, unsigned int cls)
Constructor.
Definition: tracker.cpp:464
Time tracking utility.
Definition: tracker.h:37
void print_to_stdout()
Print results to stdout.
Definition: tracker.cpp:307
void print_to_file()
Print data to file suitable for gnuplot.
Definition: tracker.cpp:426
TimeTracker(const char *filename, bool add_default_class=false)
Constructor for file logging.
Definition: tracker.cpp:80
unsigned int add_class(std::string name)
Add a new class.
Definition: tracker.cpp:149
void reset(std::string comment="")
Reset times.
Definition: tracker.cpp:110
void ping_end(unsigned int cls)
End of given class task.
Definition: tracker.cpp:243
void remove_class(unsigned int cls)
Remove a class.
Definition: tracker.cpp:166
void ping(unsigned int cls)
Ping class.
Definition: tracker.cpp:185
void ping_abort(unsigned int cls)
End of given class task without recording.
Definition: tracker.cpp:270
void ping_start(unsigned int cls)
Start of given class task.
Definition: tracker.cpp:218
~TimeTracker()
Destructor.
Definition: tracker.cpp:95
static const unsigned int DEFAULT_CLASS
The default tracking class.
Definition: tracker.h:39
Fawkes library namespace.