00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018
00019
00020
00021
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
00038 }
00039 #endif
00040
00041
00042
00043
00044
00045
00046
00047
00048
00049
00050
00051
00052
00053
00054
00055
00056
00057
00058
00059
00060
00061
00062
00063 const unsigned int TimeTracker::DEFAULT_CLASS = 0;
00064
00065
00066
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
00081
00082
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
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
00112
00113
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
00133
00134
00135
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
00150
00151
00152
00153
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
00168
00169
00170
00171
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
00189
00190
00191
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
00224
00225
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
00249
00250
00251
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
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
00421
00422
00423
00424
00425
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 }
00456