Fawkes API
Fawkes Development Version
|
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