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 void
00278 TimeTracker::average_and_deviation(vector<struct timeval *> &values,
00279                                    double &average_sec, double &average_ms,
00280                                    double &deviation_sec, double &deviation_ms)
00281 {
00282   vector<struct timeval * >::iterator tit;
00283 
00284   average_sec = average_ms = deviation_sec = deviation_ms = 0.f;
00285 
00286   for (tit = values.begin(); tit != values.end(); ++tit) {
00287     average_sec += float((*tit)->tv_sec);
00288     average_sec += (*tit)->tv_usec / 1000000.f;
00289   }
00290   average_sec /= values.size();
00291 
00292   for (tit = values.begin(); tit != values.end(); ++tit) {
00293     deviation_sec += fabs((*tit)->tv_sec + ((*tit)->tv_usec / 1000000.f) - average_sec);
00294   }
00295   deviation_sec /= values.size();
00296 
00297   average_ms   = average_sec   * 1000.f;
00298   deviation_ms = deviation_sec * 1000.f;
00299 }
00300 
00301 /** Print results to stdout. */
00302 void
00303 TimeTracker::print_to_stdout()
00304 {
00305 
00306   if ( ! __times.empty()) {
00307     unsigned int i = 0;
00308     unsigned int j = 0;
00309     long diff_sec_start = 0;
00310     long diff_usec_start = 0;
00311     long diff_sec_last = 0;
00312     long diff_usec_last = 0;
00313     float diff_msec_start = 0.0;
00314     float diff_msec_last = 0.0;
00315     time_t last_sec = start_time.tv_sec;
00316     suseconds_t last_usec = start_time.tv_usec;
00317     char time_string[26];
00318 
00319     ctime_r(&(start_time.tv_sec), time_string);
00320     for (j = 26; j > 0; --j) {
00321       if (time_string[j] == '\n') {
00322         time_string[j] = 0;
00323         break;
00324       }
00325     }
00326 
00327     cout << endl << "TimeTracker stats - individual times";
00328     if (__tracker_comment.empty()) {
00329       cout << " (" << __tracker_comment << ")";
00330     }
00331     cout << endl
00332          << "==================================================================" << endl
00333          << "Initialized: " << time_string << " (" << start_time.tv_sec << ")" << endl << endl;
00334 
00335     for (__time_it = __times.begin(); __time_it != __times.end(); ++__time_it) {
00336       char tmp[10];
00337       sprintf(tmp, "%3u.", i + 1);
00338       cout << tmp;
00339       if (__comments.count(i) > 0) {
00340         cout << "  (" << __comments[i] << ")";
00341       }
00342       cout << endl;
00343 
00344       diff_sec_start  = (*__time_it)->tv_sec  - start_time.tv_sec;
00345       diff_usec_start = (*__time_it)->tv_usec - start_time.tv_usec;
00346       if (diff_usec_start < 0) {
00347         diff_sec_start -= 1;
00348         diff_usec_start = 1000000 + diff_usec_start;
00349       }
00350       diff_msec_start = diff_usec_start / 1000.f;
00351 
00352       diff_sec_last  = (*__time_it)->tv_sec  - last_sec;
00353       diff_usec_last = (*__time_it)->tv_usec - last_usec;
00354       if (diff_usec_last < 0) {
00355         diff_sec_last -= 1;
00356         diff_usec_last = 1000000 + diff_usec_last;
00357       }
00358       diff_msec_last = diff_usec_last / 1000.f;
00359 
00360       last_sec  = (*__time_it)->tv_sec;
00361       last_usec = (*__time_it)->tv_usec;
00362 
00363       ctime_r(&(*__time_it)->tv_sec, time_string);
00364       for (j = 26; j > 0; --j) {
00365         if (time_string[j] == '\n') {
00366           time_string[j] = 0;
00367           break;
00368         }
00369       }
00370       cout << time_string << " (" << (*__time_it)->tv_sec << ")" << endl;
00371       cout << "Diff to start: " << diff_sec_start << " sec and " << diff_usec_start
00372            << " usec  (which are "
00373            << diff_msec_start << " msec)" << endl;
00374       cout << "Diff to last:  " << diff_sec_last  << " sec and " << diff_usec_last
00375            << " usec (which are "
00376            << diff_msec_last << " msec)" << endl << endl;
00377 
00378       i += 1;
00379     }
00380   }
00381 
00382   cout << endl << "TimeTracker stats - class times";
00383   if (!__tracker_comment.empty()) {
00384     cout << " (" << __tracker_comment << ")";
00385   }
00386   cout << endl
00387        << "==================================================================" << endl;
00388 
00389   vector<vector<struct timeval *> >::iterator it = __class_times.begin();
00390   vector<string>::iterator sit = __class_names.begin();
00391 
00392   double deviation = 0.f;
00393   double average = 0.f;
00394   double average_ms = 0.f;
00395   double deviation_ms = 0.f;
00396 
00397   for (; (it != __class_times.end()) && (sit != __class_names.end()); ++it, ++sit) {
00398     if (sit->empty()) continue;
00399 
00400     if (it->size() > 0) {
00401 
00402       average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
00403 
00404       cout << "Class '" <<  *sit << "'" << endl
00405            << "  avg=" << average << " (" << average_ms << " ms)" << endl
00406            << "  dev=" << deviation << " (" << deviation_ms << " ms)" << endl
00407            << "  res=" << it->size() << " results"
00408            << endl;
00409     } else {
00410       cout << "Class '" <<  *sit << "' has no results." << endl;
00411     }
00412 
00413   }
00414 
00415   cout << endl;
00416 
00417 }
00418 
00419 
00420 /** Print data to file suitable for gnuplot.
00421  * This will write the following data:
00422  * average sec, average ms, average summed sec, deviation sec, deviation ms
00423  * This data is generated for each class and concatenated into a single line
00424  * and written to the file. A running number will be prepended as the first
00425  * value. The data file is suitable as input for gnuplot.
00426  */
00427 void
00428 TimeTracker::print_to_file()
00429 {
00430   if ( ! __timelog)  throw Exception("Time log not opened, use other ctor");
00431 
00432   vector<vector<struct timeval *> >::iterator it = __class_times.begin();
00433   vector<string>::iterator sit = __class_names.begin();
00434 
00435   double deviation = 0.f;
00436   double average = 0.f;
00437   double average_ms = 0.f;
00438   double deviation_ms = 0.f;
00439   double avgsum = 0.f;
00440 
00441   fprintf(__timelog, "%u ", ++__write_cycle);
00442   for (; (it != __class_times.end()) && (sit != __class_names.end()); ++it, ++sit) {
00443     if (sit->empty()) continue;
00444 
00445     average_and_deviation(*it, average, average_ms, deviation, deviation_ms);
00446 
00447     avgsum += average;
00448     fprintf(__timelog, "%lf %lf %lf %lf %lf ",
00449             average, average_ms, avgsum, deviation, deviation_ms);
00450   }
00451   fprintf(__timelog, "\n");
00452   fflush(__timelog);
00453 }
00454 
00455 } // end namespace fawkes
00456 

Generated on 1 Mar 2011 for Fawkes API by  doxygen 1.6.1