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 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