Go to the documentation of this file.00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018
00019
00020
00021
00022
00023
00024
00025
00026
00027
00028
00029
00030
00031
00032
00033
00034
00035
00036
00037 #include "moveit/profiler/profiler.h"
00038
00039 moveit::tools::Profiler& moveit::tools::Profiler::Instance(void)
00040 {
00041 static Profiler p(false, false);
00042 return p;
00043 }
00044
00045 #if MOVEIT_ENABLE_PROFILING
00046
00047 #include <console_bridge/console.h>
00048 #include <vector>
00049 #include <algorithm>
00050 #include <sstream>
00051
00052 void moveit::tools::Profiler::start(void)
00053 {
00054 lock_.lock();
00055 if (!running_)
00056 {
00057 tinfo_.set();
00058 running_ = true;
00059 }
00060 lock_.unlock();
00061 }
00062
00063 void moveit::tools::Profiler::stop(void)
00064 {
00065 lock_.lock();
00066 if (running_)
00067 {
00068 tinfo_.update();
00069 running_ = false;
00070 }
00071 lock_.unlock();
00072 }
00073
00074 void moveit::tools::Profiler::clear(void)
00075 {
00076 lock_.lock();
00077 data_.clear();
00078 tinfo_ = TimeInfo();
00079 if (running_)
00080 tinfo_.set();
00081 lock_.unlock();
00082 }
00083
00084 void moveit::tools::Profiler::event(const std::string &name, const unsigned int times)
00085 {
00086 lock_.lock();
00087 data_[boost::this_thread::get_id()].events[name] += times;
00088 lock_.unlock();
00089 }
00090
00091 void moveit::tools::Profiler::average(const std::string &name, const double value)
00092 {
00093 lock_.lock();
00094 AvgInfo &a = data_[boost::this_thread::get_id()].avg[name];
00095 a.total += value;
00096 a.totalSqr += value*value;
00097 a.parts++;
00098 lock_.unlock();
00099 }
00100
00101 void moveit::tools::Profiler::begin(const std::string &name)
00102 {
00103 lock_.lock();
00104 data_[boost::this_thread::get_id()].time[name].set();
00105 lock_.unlock();
00106 }
00107
00108 void moveit::tools::Profiler::end(const std::string &name)
00109 {
00110 lock_.lock();
00111 data_[boost::this_thread::get_id()].time[name].update();
00112 lock_.unlock();
00113 }
00114
00115 namespace
00116 {
00117
00118 inline double to_seconds(const boost::posix_time::time_duration &d)
00119 {
00120 return (double)d.total_microseconds() / 1000000.0;
00121 }
00122
00123 }
00124
00125 void moveit::tools::Profiler::status(std::ostream &out, bool merge)
00126 {
00127 stop();
00128 lock_.lock();
00129 printOnDestroy_ = false;
00130
00131 out << std::endl;
00132 out << " *** Profiling statistics. Total counted time : " << to_seconds(tinfo_.total) << " seconds" << std::endl;
00133
00134 if (merge)
00135 {
00136 PerThread combined;
00137 for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
00138 {
00139 for (std::map<std::string, unsigned long int>::const_iterator iev = it->second.events.begin() ; iev != it->second.events.end(); ++iev)
00140 combined.events[iev->first] += iev->second;
00141 for (std::map<std::string, AvgInfo>::const_iterator iavg = it->second.avg.begin() ; iavg != it->second.avg.end(); ++iavg)
00142 {
00143 combined.avg[iavg->first].total += iavg->second.total;
00144 combined.avg[iavg->first].totalSqr += iavg->second.totalSqr;
00145 combined.avg[iavg->first].parts += iavg->second.parts;
00146 }
00147 for (std::map<std::string, TimeInfo>::const_iterator itm = it->second.time.begin() ; itm != it->second.time.end(); ++itm)
00148 {
00149 TimeInfo &tc = combined.time[itm->first];
00150 tc.total = tc.total + itm->second.total;
00151 tc.parts = tc.parts + itm->second.parts;
00152 if (tc.shortest > itm->second.shortest)
00153 tc.shortest = itm->second.shortest;
00154 if (tc.longest < itm->second.longest)
00155 tc.longest = itm->second.longest;
00156 }
00157 }
00158 printThreadInfo(out, combined);
00159 }
00160 else
00161 for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
00162 {
00163 out << "Thread " << it->first << ":" << std::endl;
00164 printThreadInfo(out, it->second);
00165 }
00166 lock_.unlock();
00167 }
00168
00169 void moveit::tools::Profiler::console(void)
00170 {
00171 std::stringstream ss;
00172 ss << std::endl;
00173 status(ss, true);
00174 logInform(ss.str().c_str());
00175 }
00176
00178 namespace
00179 {
00180
00181 struct dataIntVal
00182 {
00183 std::string name;
00184 unsigned long int value;
00185 };
00186
00187 struct SortIntByValue
00188 {
00189 bool operator()(const dataIntVal &a, const dataIntVal &b) const
00190 {
00191 return a.value > b.value;
00192 }
00193 };
00194
00195 struct dataDoubleVal
00196 {
00197 std::string name;
00198 double value;
00199 };
00200
00201 struct SortDoubleByValue
00202 {
00203 bool operator()(const dataDoubleVal &a, const dataDoubleVal &b) const
00204 {
00205 return a.value > b.value;
00206 }
00207 };
00208 }
00210
00211 void moveit::tools::Profiler::printThreadInfo(std::ostream &out, const PerThread &data)
00212 {
00213 double total = to_seconds(tinfo_.total);
00214
00215 std::vector<dataIntVal> events;
00216 for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin() ; iev != data.events.end() ; ++iev)
00217 {
00218 dataIntVal next = {iev->first, iev->second};
00219 events.push_back(next);
00220 }
00221 std::sort(events.begin(), events.end(), SortIntByValue());
00222 if (!events.empty())
00223 out << "Events:" << std::endl;
00224 for (unsigned int i = 0 ; i < events.size() ; ++i)
00225 out << events[i].name << ": " << events[i].value << std::endl;
00226
00227 std::vector<dataDoubleVal> avg;
00228 for (std::map<std::string, AvgInfo>::const_iterator ia = data.avg.begin() ; ia != data.avg.end() ; ++ia)
00229 {
00230 dataDoubleVal next = {ia->first, ia->second.total / (double)ia->second.parts};
00231 avg.push_back(next);
00232 }
00233 std::sort(avg.begin(), avg.end(), SortDoubleByValue());
00234 if (!avg.empty())
00235 out << "Averages:" << std::endl;
00236 for (unsigned int i = 0 ; i < avg.size() ; ++i)
00237 {
00238 const AvgInfo &a = data.avg.find(avg[i].name)->second;
00239 out << avg[i].name << ": " << avg[i].value << " (stddev = " <<
00240 sqrt(fabs(a.totalSqr - (double)a.parts * avg[i].value * avg[i].value) / ((double)a.parts - 1.)) << ")" << std::endl;
00241 }
00242
00243 std::vector<dataDoubleVal> time;
00244
00245 for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin() ; itm != data.time.end() ; ++itm)
00246 {
00247 dataDoubleVal next = {itm->first, to_seconds(itm->second.total)};
00248 time.push_back(next);
00249 }
00250
00251 std::sort(time.begin(), time.end(), SortDoubleByValue());
00252 if (!time.empty())
00253 out << "Blocks of time:" << std::endl;
00254
00255 double unaccounted = total;
00256 for (unsigned int i = 0 ; i < time.size() ; ++i)
00257 {
00258 const TimeInfo &d = data.time.find(time[i].name)->second;
00259
00260 double tS = to_seconds(d.shortest);
00261 double tL = to_seconds(d.longest);
00262 out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value/total) << "%), ["
00263 << tS << "s --> " << tL << " s], " << d.parts << " parts";
00264 if (d.parts > 0)
00265 {
00266 double pavg = to_seconds(d.total) / (double)d.parts;
00267 out << ", " << pavg << " s on average";
00268 if (pavg < 1.0)
00269 out << " (" << 1.0/pavg << " /s)";
00270 }
00271 out << std::endl;
00272 unaccounted -= time[i].value;
00273 }
00274
00275 if (unaccounted >= 0.0)
00276 {
00277 out << "Unaccounted time : " << unaccounted;
00278 if (total > 0.0)
00279 out << " (" << (100.0 * unaccounted / total) << " %)";
00280 out << std::endl;
00281 }
00282
00283 out << std::endl;
00284 }
00285
00286 #endif