00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00022
00023
00024 #include "icl_core_performance_monitor/PerformanceMonitor.h"
00025
00026 #include <stdlib.h>
00027 #include <algorithm>
00028 #include <sstream>
00029
00030 #include <icl_core/TimeSpan.h>
00031
00032 using namespace std;
00033
00034 namespace icl_core {
00035 namespace perf_mon{
00036
00037 string makeName(string prefix, string name)
00038 {
00039 return prefix + "::" + name;
00040 }
00041
00042 PerformanceMonitor* PerformanceMonitor::m_instance = NULL;
00043
00044 PerformanceMonitor::PerformanceMonitor()
00045 {
00046 m_enabled = true;
00047 m_print_stop = true;
00048 m_all_enabled = false;
00049 }
00050
00051 PerformanceMonitor::~PerformanceMonitor()
00052 {
00053
00054 }
00055
00056 PerformanceMonitor* PerformanceMonitor::getInstance()
00057 {
00058 if (m_instance == NULL)
00059 {
00060 m_instance = new PerformanceMonitor();
00061 }
00062 return m_instance;
00063 }
00064
00065 void PerformanceMonitor::initialize(const uint32_t num_names, const uint32_t num_events)
00066 {
00067 PerformanceMonitor* monitor = getInstance();
00068 monitor->m_data.clear();
00069 monitor->m_data_nontime.clear();
00070 monitor->m_buffer.resize(num_names);
00071 for (uint32_t i = 0; i < num_names; ++i)
00072 monitor->m_buffer[i].reserve(num_events);
00073
00074 monitor->enablePrefix("");
00075 }
00076
00077
00078 bool PerformanceMonitor::isEnabled(string prefix)
00079 {
00080 return (m_enabled && m_enabled_prefix.find(prefix) != m_enabled_prefix.end()) || m_all_enabled;
00081 }
00082
00083 void PerformanceMonitor::start(string timer_name)
00084 {
00085 if (getInstance()->m_enabled)
00086 {
00087 TimeStamp t = TimeStamp::now();
00088 getInstance()->m_timer[timer_name] = t;
00089 }
00090 }
00091
00092 double PerformanceMonitor::measurement(string timer_name, string description, string prefix,
00093 icl_core::logging::LogLevel level)
00094 {
00095 PerformanceMonitor* monitor = getInstance();
00096 if (monitor->isEnabled(prefix))
00097 {
00098 TimeStamp end = TimeStamp::now();
00099 TimeSpan d(end - monitor->m_timer[timer_name]);
00100 double double_ms = d.toNSec() / 1000000.0;
00101 monitor->addEvent(prefix, description, double_ms);
00102
00103 if (getInstance()->m_print_stop)
00104 {
00105 std::stringstream ss;
00106 ss << makeName(prefix, description) << ": " << double_ms << " ms";
00107 monitor->print(ss.str(), level);
00108 }
00109 return double_ms;
00110 }
00111 return 0;
00112 }
00113
00114 double PerformanceMonitor::startStop(string timer_name, string description, string prefix,
00115 logging::LogLevel level)
00116 {
00117
00118
00119
00120
00121
00122
00123
00124
00125 if (getInstance()->isEnabled(prefix))
00126 {
00127 PerformanceMonitor* monitor = getInstance();
00128 TimeStamp start = monitor->m_timer[timer_name];
00129 if (start != TimeStamp())
00130 {
00131 TimeStamp end = TimeStamp::now();
00132 TimeSpan d(end - start);
00133 double double_ms = d.toNSec() / 1000000.0;
00134 monitor->addEvent(prefix, description, double_ms);
00135 monitor->m_timer[timer_name] = end;
00136 if (getInstance()->m_print_stop)
00137 {
00138 std::stringstream ss;
00139 ss << makeName(prefix, description) << ": " << double_ms << " ms";
00140 monitor->print(ss.str(), level);
00141 }
00142 return double_ms;
00143 }
00144 else
00145 {
00146 PerformanceMonitor::start(timer_name);
00147 }
00148 }
00149 return 0;
00150 }
00151
00152 void PerformanceMonitor::addStaticData(string name, double data, string prefix)
00153 {
00154 if (getInstance()->isEnabled(prefix))
00155 {
00156 string tmp = makeName(prefix, name);
00157 getInstance()->m_static_data[tmp] = data;
00158 }
00159 }
00160
00161 void PerformanceMonitor::addData(string name, double data, string prefix)
00162 {
00163 if (getInstance()->isEnabled(prefix))
00164 {
00165 getInstance()->addEvent(prefix, name, data);
00166 }
00167 }
00168
00169 void PerformanceMonitor::addNonTimeData(string name, double data, string prefix)
00170 {
00171 if (getInstance()->isEnabled(prefix))
00172 {
00173 getInstance()->addNonTimeEvent(prefix, name, data);
00174 }
00175 }
00176
00177 void PerformanceMonitor::addEvent(string prefix, string name, double data)
00178 {
00179 if (getInstance()->isEnabled(prefix))
00180 {
00181 string tmp = makeName(prefix, name);
00182 if (m_data.find(tmp) == m_data.end())
00183 {
00184 m_data[tmp] = vector<double>();
00185 if (m_buffer.size() > 0)
00186 {
00187 m_data[tmp].swap(m_buffer.back());
00188 m_buffer.pop_back();
00189 }
00190 }
00191 m_data[tmp].push_back(data);
00192 }
00193 }
00194
00195 void PerformanceMonitor::addNonTimeEvent(string prefix, string name, double data)
00196 {
00197 if (getInstance()->isEnabled(prefix))
00198 {
00199 string tmp = makeName(prefix, name);
00200 if (m_data_nontime.find(tmp) == m_data_nontime.end())
00201 {
00202 m_data_nontime[tmp] = vector<double>();
00203 if (m_buffer.size() > 0)
00204 {
00205 m_data_nontime[tmp].swap(m_buffer.back());
00206 m_buffer.pop_back();
00207 }
00208 }
00209 m_data_nontime[tmp].push_back(data);
00210 }
00211 }
00212
00213
00214 void PerformanceMonitor::print(string message, logging::LogLevel level)
00215 {
00216 switch (level)
00217 {
00218 case ::icl_core::logging::eLL_DEBUG:
00219 {
00220 LOGGING_DEBUG(Performance, message << endl);
00221 break;
00222 }
00223 case ::icl_core::logging::eLL_INFO:
00224 {
00225 LOGGING_INFO(Performance, message << endl);
00226 break;
00227 }
00228 case ::icl_core::logging::eLL_TRACE:
00229 {
00230 LOGGING_TRACE(Performance, message << endl);
00231 break;
00232 }
00233 default:
00234 {
00235 LOGGING_INFO(Performance, message << endl);
00236 break;
00237 }
00238 }
00239 }
00240
00241 void PerformanceMonitor::createStatisticSummary(stringstream& ss, string prefix, string name)
00242 {
00243 string tmp = makeName(prefix, name);
00244 double median, min, max;
00245 getMedian(tmp, median, min, max);
00246
00247 ss << "Summary for " << tmp << "\n" <<
00248 "Called " << m_data[tmp].size() << " times\n" <<
00249 name << "_avg: " << getAverage(tmp) << " ms\n" <<
00250 name << "_median: " << median << " ms\n" <<
00251 name << "_min: " << min << " ms\n" <<
00252 name << "_max: " << max << " ms\n"<<
00253 "\n";
00254 }
00255
00256 void PerformanceMonitor::createStatisticSummaryNonTime(stringstream& ss, string prefix, string name)
00257 {
00258 string tmp = makeName(prefix, name);
00259 double median, min, max;
00260 getMedianNonTime(tmp, median, min, max);
00261
00262 ss << "Summary for " << tmp << "\n" <<
00263 "num entries: " << m_data_nontime[tmp].size() << "\n" <<
00264 name << "_avg: " << getAverageNonTime(tmp) << "\n" <<
00265 name << "_median: " << median << "\n" <<
00266 name << "_min: " << min << "\n" <<
00267 name << "_max: " << max << "\n"<<
00268 "\n";
00269 }
00270
00271 void PerformanceMonitor::printSummary(string prefix, string name,
00272 icl_core::logging::LogLevel level)
00273 {
00274 PerformanceMonitor* monitor = getInstance();
00275
00276 std::stringstream ss;
00277 monitor->createStatisticSummary(ss, prefix, name);
00278 monitor->print(ss.str(), level);
00279 }
00280
00281 void PerformanceMonitor::enablePrefix(string prefix)
00282 {
00283 PerformanceMonitor* monitor = getInstance();
00284
00285 if (monitor->m_enabled_prefix.find(prefix) == monitor->m_enabled_prefix.end())
00286 {
00287 monitor->m_enabled_prefix[prefix] = true;
00288 }
00289 }
00290
00291 void PerformanceMonitor::enableAll(const bool& enabled)
00292 {
00293 getInstance()->m_all_enabled = enabled;
00294 }
00295
00296 void PerformanceMonitor::disablePrefix(string prefix)
00297 {
00298 PerformanceMonitor* monitor = getInstance();
00299
00300 if (monitor->m_enabled_prefix.find(prefix) != monitor->m_enabled_prefix.end())
00301 {
00302 monitor->m_enabled_prefix.erase(prefix);
00303 }
00304 }
00305
00306 void PerformanceMonitor::printSummaryAll(icl_core::logging::LogLevel level)
00307 {
00308 PerformanceMonitor* monitor = getInstance();
00309
00310 for (map<string, bool>::iterator it=monitor->m_enabled_prefix.begin();
00311 it != monitor->m_enabled_prefix.end(); ++it)
00312 {
00313 printSummaryFromPrefix(it->first, level);
00314 }
00315 }
00316
00317 void PerformanceMonitor::printSummaryFromPrefix(string prefix, icl_core::logging::LogLevel level)
00318 {
00319 PerformanceMonitor* monitor = getInstance();
00320 bool first = true;
00321 std::stringstream ss;
00322 ss << "\n########## Begin of Summary for prefix " << prefix << " ##########\n";
00323 for (map<string, double>::iterator it = monitor->m_static_data.begin(); it != monitor->m_static_data.end(); it++)
00324 {
00325 size_t prefix_end = it->first.find("::");
00326 std::string prefix_tmp = it->first.substr(0, prefix_end);
00327
00328 if (prefix == prefix_tmp)
00329 {
00330 if (first)
00331 {
00332 ss << "#### Static data: ####\n";
00333 first = false;
00334 }
00335 ss << it->first.substr(prefix_end+2) << ": " << it->second << "\n";
00336 }
00337 }
00338
00339 first = true;
00340 for (map<string, vector<double> >::iterator it = monitor->m_data.begin(); it != monitor->m_data.end(); it++)
00341 {
00342 size_t prefix_end = it->first.find("::");
00343 std::string prefix_tmp = it->first.substr(0, prefix_end);
00344
00345 if (prefix == prefix_tmp)
00346 {
00347 if (first)
00348 {
00349 ss << "#### Time data: ####\n";
00350 first = false;
00351 }
00352 string name = it->first.substr(prefix_end+2);
00353 monitor->createStatisticSummary(ss, prefix, name);
00354 }
00355 }
00356
00357 first = true;
00358 for (map<string, vector<double> >::iterator it = monitor->m_data_nontime.begin(); it != monitor->m_data_nontime.end(); it++)
00359 {
00360 size_t prefix_end = it->first.find("::");
00361 std::string prefix_tmp = it->first.substr(0, prefix_end);
00362
00363 if (prefix == prefix_tmp)
00364 {
00365 if (first)
00366 {
00367 ss << "#### Non-time data: ####\n";
00368 first = false;
00369 }
00370 string name = it->first.substr(prefix_end+2);
00371 monitor->createStatisticSummaryNonTime(ss, prefix, name);
00372 }
00373 }
00374 monitor->print(ss.str(), level);
00375 }
00376
00377 double PerformanceMonitor::getAverage(string name)
00378 {
00379 double avg=0;
00380 vector<double>* tmp = &m_data[name];
00381 int n = (int) m_data[name].size();
00382 for (int i = 0; i < n; ++i)
00383 avg = avg + tmp->at(i);
00384 avg = avg / n;
00385 return avg;
00386 }
00387
00388 double PerformanceMonitor::getAverageNonTime(string name)
00389 {
00390 double avg=0;
00391 vector<double>* tmp = &m_data_nontime[name];
00392 int n = (int) m_data_nontime[name].size();
00393 for (int i = 0; i < n; ++i)
00394 avg = avg + tmp->at(i);
00395 avg = avg / n;
00396 return avg;
00397 }
00398
00399 void PerformanceMonitor::getMedian(string name, double& median, double& min, double& max)
00400 {
00401 vector<double> tmp = m_data[name];
00402 sort(tmp.begin(), tmp.end());
00403 median = tmp[tmp.size() / 2];
00404 min = tmp[0];
00405 max = tmp[tmp.size() - 1];
00406 }
00407
00408 void PerformanceMonitor::getMedianNonTime(string name, double& median, double& min, double& max)
00409 {
00410 vector<double> tmp = m_data_nontime[name];
00411 sort(tmp.begin(), tmp.end());
00412 if (tmp.size() > 0)
00413 median = tmp[tmp.size() / 2];
00414 min = tmp[0];
00415 max = tmp[tmp.size() - 1];
00416 }
00417
00418 }
00419 }
00420