Fawkes API  Fawkes Development Version
tracker.cpp
00001 
00002 /***************************************************************************
00003  *  tracker.cpp - Implementation of time tracker
00004  *
00005  *  Created: Fri Jun 03 13:43:33 2005 (copied from RCSoft5 FireVision)
00006  *  Copyright  2005-2009  Tim Niemueller [www.niemueller.de]
00007  *
00008  ****************************************************************************/
00009 
00010 /*  This program is free software; you can redistribute it and/or modify
00011  *  it under the terms of the GNU General Public License as published by
00012  *  the Free Software Foundation; either version 2 of the License, or
00013  *  (at your option) any later version. A runtime exception applies to
00014  *  this software (see LICENSE.GPL_WRE file mentioned below for details).
00015  *
00016  *  This program is distributed in the hope that it will be useful,
00017  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
00018  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
00019  *  GNU Library General Public License for more details.
00020  *
00021  *  Read the full text in the LICENSE.GPL_WRE file in the doc directory.
00022  */
00023 
00024 #include <utils/time/tracker.h>
00025 #include <core/exceptions/software.h>
00026 #include <core/exceptions/system.h>
00027 
00028 #include <iostream>
00029 #include <cmath>
00030 #include <cstdlib>
00031 #include <cerrno>
00032 #include <cstdio>
00033 
00034 using namespace std;
00035 
00036 namespace fawkes {
00037 #if 0 /* just to make Emacs auto-indent happy */
00038 }
00039 #endif
00040 
00041 /** @class TimeTracker <utils/time/tracker.h>
00042  * Time tracking utility.
00043  * This class provides means to track time of different tasks in a process.
00044  * You can assign an arbitrary number of tracking classes per object (although
00045  * using a few classes is recommended for minimal influence of the measurement
00046  * on the measured process). You can then print out averages and (max) deviation
00047  * to get a feeling for the average performance and how flaky the runtimes are.
00048  *
00049  * The time tracker can also be operated without any class if you only want to
00050  * track a single process.
00051  *
00052  * You can either just ping classless or a specific class which will then take
00053  * the time difference between now and the last ping as the measured time. This
00054  * is useful to determine the call frequency of a given item.
00055  * If you want to benchmark sub-tasks you more likely want to start measuring at
00056  * a specific point in time and then stop it after the sub-task is done to measure
00057  * only this very task. This can be done by using pingStart() and pingEnd().
00058  *
00059  * @author Tim Niemueller
00060  */
00061 
00062 /** The default tracking class. Optionally added in the constructor. */
00063   const unsigned int TimeTracker::DEFAULT_CLASS = 0;
00064 
00065 /** Constructor.
00066  * @param add_default_class if true a default time class is added.
00067  */
00068 TimeTracker::TimeTracker(bool add_default_class)
00069 {
00070   __timelog = NULL;
00071   __write_cycle = 0;
00072   reset();
00073   if ( add_default_class ) {
00074     __class_times.push_back(vector<struct timeval *>());
00075     __class_names.push_back("Default");
00076   }
00077 }
00078 
00079 
00080 /** Constructor for file logging.
00081  * @param filename name of the file to write log data to. File is overwritten.
00082  * @param add_default_class if true a default time class is added.
00083  */
00084 TimeTracker::TimeTracker(const char *filename, bool add_default_class)
00085 {
00086   __write_cycle = 0;
00087   reset();
00088   if ( add_default_class ) {
00089     __class_times.push_back(vector<struct timeval *>());
00090     __class_names.push_back("Default");
00091   }
00092   __timelog = fopen(filename, "w");
00093   if (!__timelog) {
00094     throw CouldNotOpenFileException(filename, errno, "Failed to open time log");
00095   }
00096 }
00097 
00098 
00099 /** Destructor. */
00100 TimeTracker::~TimeTracker()
00101 {
00102   if (__timelog) {
00103     fclose(__timelog);
00104   }
00105   reset();
00106   __class_times.clear();
00107   __class_names.clear();
00108 }
00109 
00110 
00111 /** Reset times.
00112  * Reset tracker and set comment.
00113  * @param comment comment to set on tracker.
00114  */
00115 void
00116 TimeTracker::reset(std::string comment)
00117 {
00118   __tracker_comment = comment;
00119   for (vector<vector<struct timeval *> >::iterator i = __class_times.begin(); i != __class_times.end(); ++i) {
00120     for (vector<struct timeval *>::iterator j = i->begin(); j != i->end(); ++j) {
00121       free(*j);
00122     }
00123     i->clear();
00124   }
00125   __times.clear();
00126   __comments.clear();
00127   gettimeofday(&start_time, NULL);
00128   gettimeofday(&last_time, NULL);
00129 }
00130 
00131 
00132 /** Ping classless.
00133  * This takes the time difference between now and the last ping and adds this
00134  * to classless tracking.
00135  * @param comment optional ping comment.
00136  */
00137 void
00138 TimeTracker::ping(std::string comment)
00139 {
00140   timeval *t = (timeval *)malloc(sizeof(timeval));
00141   gettimeofday(t, NULL);
00142   __times.push_back(t);
00143   if (!comment.empty()) {
00144     __comments[ __times.size() - 1 ] = comment;
00145   }
00146 }
00147 
00148 
00149 /** Add a new class.
00150  * Adds a new class and gives the class ID.
00151  * @param name name of the class
00152  * @return new class ID which is used for pinging this specific
00153  * class.
00154  */
00155 unsigned int
00156 TimeTracker::add_class(std::string name)
00157 {
00158   if ( name == "" ) {
00159     throw Exception("TimeTracker::add_class(): Class name may not be empty");
00160   }
00161   __class_times.push_back(vector<struct timeval *>());
00162   __class_names.push_back(name);
00163   return __class_times.size() - 1;
00164 }
00165 
00166 
00167 /** Remove a class.
00168  * This marks the class as unused. It is not longer possible to add times to this
00169  * class but they will not be printed anymore. The space associated with this
00170  * class is freed.
00171  * @param cls ID of the class to remove
00172  */
00173 void
00174 TimeTracker::remove_class(unsigned int cls)
00175 {
00176   if ( cls < __class_names.size() ) {
00177     __class_names[cls] = "";
00178   } else {
00179     if ( __class_times.size() == 0 ) {
00180       throw Exception("No classes have been added, cannot delete class %u", cls);
00181     } else {
00182       throw OutOfBoundsException("Invalid class given", cls, 0, __class_times.size()-1);
00183     }
00184   }
00185 }
00186 
00187 
00188 /** Ping class.
00189  * This takes the time difference between now and the last ping and adds this
00190  * to class cls.
00191  * @param cls class ID to ping
00192  */
00193 void
00194 TimeTracker::ping(unsigned int cls)
00195 {
00196   timeval *t = (timeval *)malloc(sizeof(timeval));
00197   gettimeofday(t, NULL);
00198 
00199   long sec  = t->tv_sec - last_time.tv_sec;
00200   long usec = t->tv_usec - last_time.tv_usec;
00201   if (usec < 0) {
00202     sec -= 1;
00203     usec += 1000000;
00204   }
00205   last_time.tv_sec  = t->tv_sec;
00206   last_time.tv_usec = t->tv_usec;
00207 
00208   t->tv_sec  = sec;
00209   t->tv_usec = usec;
00210 
00211   if (cls < __class_times.size()) {
00212     __class_times[cls].push_back(t);
00213   } else {
00214     if ( __class_times.size() == 0 ) {
00215       throw Exception("No classes have been added, cannot track times");
00216     } else {
00217       throw OutOfBoundsException("Invalid class given", cls, 0, __class_times.size()-1);
00218     }
00219   }
00220 }
00221 
00222 
00223 /** Start of given class task.
00224  * Signal the start of the given class.
00225  * @param cls class ID
00226  */
00227 void
00228 TimeTracker::ping_start(unsigned int cls)
00229 {
00230   if (cls >= __class_times.size()) return;
00231 
00232   timeval *t = (timeval *)malloc(sizeof(timeval));
00233   gettimeofday(t, NULL);
00234 
00235   if (cls < __class_times.size()) {
00236     __class_times[cls].push_back(t);
00237   } else {
00238     if ( __class_times.size() == 0 ) {
00239       throw Exception("No classes have been added, cannot track times");
00240     } else {
00241       throw OutOfBoundsException("Invalid class given", cls, 0, __class_times.size()-1);
00242     }
00243   }
00244 
00245 }
00246 
00247 
00248 /** End of given class task.
00249  * This takes the time difference between now and the last pingStart() for the
00250  * class cls.
00251  * @param cls class ID to signal end of task
00252  */
00253 void
00254 TimeTracker::ping_end(unsigned int cls)
00255 {
00256   if (cls >= __class_times.size()) return;
00257 
00258   timeval t2;
00259   gettimeofday(&t2, NULL);
00260 
00261   timeval *t1 = __class_times[cls].back();
00262 
00263   long sec  = t2.tv_sec - t1->tv_sec;
00264   long usec = t2.tv_usec - t1->tv_usec;
00265 
00266   if (usec < 0) {
00267     sec  -= 1;
00268     usec += 1000000;
00269   }
00270 
00271   t1->tv_sec  = sec;
00272   t1->tv_usec = usec;
00273 
00274 }
00275 
00276 
00277 /** End of given class task without recording.
00278  * End the duration but do not take the time into the result measurements.
00279  * @param cls class ID to signal end of task
00280  */
00281 void
00282 TimeTracker::ping_abort(unsigned int cls)
00283 {
00284   if (cls >= __class_times.size()) return;
00285 
00286   free(__class_times[cls].back());
00287   __class_times[cls].pop_back();
00288 }
00289 
00290 
00291 void
00292 TimeTracker::average_and_deviation(vector<struct timeval *> &values,
00293                                    double &average_sec, double &average_ms,
00294                                    double &deviation_sec, double &deviation_ms)
00295 {
00296   vector<struct timeval * >::iterator tit;
00297 
00298   average_sec = average_ms = deviation_sec = deviation_ms = 0.f;
00299 
00300   for (tit = values.begin(); tit != values.end(); ++tit) {
00301     average_sec += float((*tit)->tv_sec);
00302     average_sec += (*tit)->tv_usec / 1000000.f;
00303   }
00304   average_sec /= values.size();
00305 
00306   for (tit = values.begin(); tit != values.end(); ++tit) {
00307     deviation_sec += fabs((*tit)->tv_sec + ((*tit)->tv_usec / 1000000.f) - average_sec);
00308   }
00309   deviation_sec /= values.size();
00310 
00311   average_ms   = average_sec   * 1000.f;
00312   deviation_ms = deviation_sec * 1000.f;
00313 }
00314 
00315 /** Print results to stdout. */
00316 void
00317 TimeTracker::print_to_stdout()
00318 {
00319 
00320   if ( ! __times.empty()) {
00321     unsigned int i = 0;
00322     unsigned int j = 0;
00323     long diff_sec_start = 0;
00324     long diff_usec_start = 0;
00325     long diff_sec_last = 0;
00326     long diff_usec_last = 0;
00327     float diff_msec_start = 0.0;
00328     float diff_msec_last = 0.0;
00329     time_t last_sec = start_time.tv_sec;
00330     suseconds_t last_usec = start_time.tv_usec;
00331     char time_string[26];
00332 
00333     ctime_r(&(start_time.tv_sec), time_string);
00334     for (j = 26; j > 0; --j) {
00335       if (time_string[j] == '\n') {
00336         time_string[j] = 0;
00337         break;
00338       }
00339     }
00340 
00341     cout << endl << "TimeTracker stats - individual times";
00342     if (__tracker_comment.empty()) {
00343       cout << " (" << __tracker_comment << ")";
00344     }
00345     cout << endl
00346          << "==================================================================" << endl
00347          << "Initialized: " << time_string << " (" << start_time.tv_sec << ")" << endl << endl;
00348 
00349     for (__time_it = __times.begin(); __time_it != __times.end(); ++__time_it) {
00350       char tmp[10];
00351       sprintf(tmp, "%3u.", i + 1);
00352       cout << tmp;
00353       if (__comments.count(i) > 0) {
00354         cout << "  (" << __comments[i] << ")";
00355       }
00356       cout << endl;
00357 
00358       diff_sec_start  = (*__time_it)->tv_sec  - start_time.tv_sec;
00359       diff_usec_start = (*__time_it)->tv_usec - start_time.tv_usec;
00360       if (diff_usec_start < 0) {
00361         diff_sec_start -= 1;
00362         diff_usec_start = 1000000 + diff_usec_start;
00363       }
00364       diff_msec_start = diff_usec_start / 1000.f;
00365 
00366       diff_sec_last  = (*__time_it)->tv_sec  - last_sec;
00367       diff_usec_last = (*__time_it)->tv_usec - last_usec;
00368       if (diff_usec_last < 0) {
00369         diff_sec_last -= 1;
00370         diff_usec_last = 1000000 + diff_usec_last;
00371       }
00372       diff_msec_last = diff_usec_last / 1000.f;
00373 
00374       last_sec  = (*__time_it)->tv_sec;
00375       last_usec = (*__time_it)->tv_usec;
00376 
00377       ctime_r(&(*__time_it)->tv_sec, time_string);
00378       for (j = 26; j > 0; --j) {
00379         if (time_string[j] == '\n') {
00380           time_string[j] = 0;
00381           break;
00382         }
00383       }
00384       cout << time_string << " (" << (*__time_it)->tv_sec << ")" << endl;
00385       cout << "Diff to start: " << diff_sec_start << " sec and " << diff_usec_start
00386            << " usec  (which are "
00387            << diff_msec_start << " msec)" << endl;
00388       cout << "Diff to last:  " << diff_sec_last  << " sec and " << diff_usec_last
00389            << " usec (which are "
00390            << diff_msec_last << " msec)" << endl << endl;
00391 
00392       i += 1;
00393     }
00394   }
00395 
00396   cout << endl << "TimeTracker stats - class times";
00397   if (!__tracker_comment.empty()) {
00398     cout << " (" << __tracker_comment << ")";
00399   }
00400   cout << endl
00401        << "==================================================================" << endl;
00402 
00403   vector<vector<struct timeval *> >::iterator it = __class_times.begin();
00404   vector<string>::iterator sit = __class_names.begin();
00405 
00406   double deviation = 0.f;
00407   double average = 0.f;
00408   double average_ms = 0.f;
00409   double deviation_ms = 0.f;
00410 
00411   for (; (it != __class_times.end()) && (sit != __class_names.end()); ++it, ++sit) {
00412     if (sit->empty()) continue;
00413 
00414     if (it->size() > 0) {
00415 
00416       average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
00417 
00418       cout << "Class '" <<  *sit << "'" << endl
00419            << "  avg=" << average << " (" << average_ms << " ms)" << endl
00420            << "  dev=" << deviation << " (" << deviation_ms << " ms)" << endl
00421            << "  res=" << it->size() << " results"
00422            << endl;
00423     } else {
00424       cout << "Class '" <<  *sit << "' has no results." << endl;
00425     }
00426 
00427   }
00428 
00429   cout << endl;
00430 
00431 }
00432 
00433 
00434 /** Print data to file suitable for gnuplot.
00435  * This will write the following data:
00436  * average sec, average ms, average summed sec, deviation sec, deviation ms
00437  * This data is generated for each class and concatenated into a single line
00438  * and written to the file. A running number will be prepended as the first
00439  * value. The data file is suitable as input for gnuplot.
00440  */
00441 void
00442 TimeTracker::print_to_file()
00443 {
00444   if ( ! __timelog)  throw Exception("Time log not opened, use other ctor");
00445 
00446   vector<vector<struct timeval *> >::iterator it = __class_times.begin();
00447   vector<string>::iterator sit = __class_names.begin();
00448 
00449   double deviation = 0.f;
00450   double average = 0.f;
00451   double average_ms = 0.f;
00452   double deviation_ms = 0.f;
00453   double avgsum = 0.f;
00454 
00455   fprintf(__timelog, "%u ", ++__write_cycle);
00456   for (; (it != __class_times.end()) && (sit != __class_names.end()); ++it, ++sit) {
00457     if (sit->empty()) continue;
00458 
00459     average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
00460 
00461     avgsum += average;
00462     fprintf(__timelog, "%lf %lf %lf %lf %lf ",
00463             average, average_ms, avgsum, deviation, deviation_ms);
00464   }
00465   fprintf(__timelog, "\n");
00466   fflush(__timelog);
00467 }
00468 
00469 } // end namespace fawkes
00470