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 std::stringstream ss;
00163 ss << std::endl;
00164 status(ss, true);
00165 logInform(ss.str().c_str());
00166 }
00167
00169 namespace ompl
00170 {
00171
00172 struct dataIntVal
00173 {
00174 std::string name;
00175 unsigned long int value;
00176 };
00177
00178 struct SortIntByValue
00179 {
00180 bool operator()(const dataIntVal &a, const dataIntVal &b) const
00181 {
00182 return a.value > b.value;
00183 }
00184 };
00185
00186 struct dataDoubleVal
00187 {
00188 std::string name;
00189 double value;
00190 };
00191
00192 struct SortDoubleByValue
00193 {
00194 bool operator()(const dataDoubleVal &a, const dataDoubleVal &b) const
00195 {
00196 return a.value > b.value;
00197 }
00198 };
00199 }
00201
00202 void ompl::tools::Profiler::printThreadInfo(std::ostream &out, const PerThread &data)
00203 {
00204 double total = time::seconds(tinfo_.total);
00205
00206 std::vector<dataIntVal> events;
00207 for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin() ; iev != data.events.end() ; ++iev)
00208 {
00209 dataIntVal next = {iev->first, iev->second};
00210 events.push_back(next);
00211 }
00212 std::sort(events.begin(), events.end(), SortIntByValue());
00213 if (!events.empty())
00214 out << "Events:" << std::endl;
00215 for (unsigned int i = 0 ; i < events.size() ; ++i)
00216 out << events[i].name << ": " << events[i].value << std::endl;
00217
00218 std::vector<dataDoubleVal> avg;
00219 for (std::map<std::string, AvgInfo>::const_iterator ia = data.avg.begin() ; ia != data.avg.end() ; ++ia)
00220 {
00221 dataDoubleVal next = {ia->first, ia->second.total / (double)ia->second.parts};
00222 avg.push_back(next);
00223 }
00224 std::sort(avg.begin(), avg.end(), SortDoubleByValue());
00225 if (!avg.empty())
00226 out << "Averages:" << std::endl;
00227 for (unsigned int i = 0 ; i < avg.size() ; ++i)
00228 {
00229 const AvgInfo &a = data.avg.find(avg[i].name)->second;
00230 out << avg[i].name << ": " << avg[i].value << " (stddev = " <<
00231 sqrt(fabs(a.totalSqr - (double)a.parts * avg[i].value * avg[i].value) / ((double)a.parts - 1.)) << ")" << std::endl;
00232 }
00233
00234 std::vector<dataDoubleVal> time;
00235
00236 for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin() ; itm != data.time.end() ; ++itm)
00237 {
00238 dataDoubleVal next = {itm->first, time::seconds(itm->second.total)};
00239 time.push_back(next);
00240 }
00241
00242 std::sort(time.begin(), time.end(), SortDoubleByValue());
00243 if (!time.empty())
00244 out << "Blocks of time:" << std::endl;
00245
00246 double unaccounted = total;
00247 for (unsigned int i = 0 ; i < time.size() ; ++i)
00248 {
00249 const TimeInfo &d = data.time.find(time[i].name)->second;
00250
00251 double tS = time::seconds(d.shortest);
00252 double tL = time::seconds(d.longest);
00253 out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value/total) << "%), ["
00254 << tS << "s --> " << tL << " s], " << d.parts << " parts";
00255 if (d.parts > 0)
00256 out << ", " << (time::seconds(d.total) / (double)d.parts) << " s on average";
00257 out << std::endl;
00258 unaccounted -= time[i].value;
00259 }
00260
00261 if (unaccounted >= 0.0)
00262 {
00263 out << "Unaccounted time : " << unaccounted;
00264 if (total > 0.0)
00265 out << " (" << (100.0 * unaccounted / total) << " %)";
00266 out << std::endl;
00267 }
00268
00269 out << std::endl;
00270 }
00271
00272 #endif