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