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/util/Profiler.h"
00039
00040 ompl::Profiler& ompl::Profiler::Instance(void)
00041 {
00042 static Profiler p(true, true);
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::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::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::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::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::Profiler::begin(const std::string &name)
00093 {
00094 lock_.lock();
00095 data_[boost::this_thread::get_id()].time[name].set();
00096 lock_.unlock();
00097 }
00098
00099 void ompl::Profiler::end(const std::string &name)
00100 {
00101 lock_.lock();
00102 data_[boost::this_thread::get_id()].time[name].update();
00103 lock_.unlock();
00104 }
00105
00106 void ompl::Profiler::status(std::ostream &out, bool merge)
00107 {
00108 stop();
00109 lock_.lock();
00110 printOnDestroy_ = false;
00111
00112 out << std::endl;
00113 out << " *** Profiling statistics. Total counted time : " << time::seconds(tinfo_.total) << " seconds" << std::endl;
00114
00115 if (merge)
00116 {
00117 PerThread combined;
00118 for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
00119 {
00120 for (std::map<std::string, unsigned long int>::const_iterator iev = it->second.events.begin() ; iev != it->second.events.end(); ++iev)
00121 combined.events[iev->first] += iev->second;
00122 for (std::map<std::string, TimeInfo>::const_iterator itm = it->second.time.begin() ; itm != it->second.time.end(); ++itm)
00123 {
00124 TimeInfo &tc = combined.time[itm->first];
00125 tc.total = tc.total + itm->second.total;
00126 tc.parts = tc.parts + itm->second.parts;
00127 if (tc.shortest > itm->second.shortest)
00128 tc.shortest = itm->second.shortest;
00129 if (tc.longest < itm->second.longest)
00130 tc.longest = itm->second.longest;
00131 }
00132 }
00133 printThreadInfo(out, combined);
00134 }
00135 else
00136 for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
00137 {
00138 out << "Thread " << it->first << ":" << std::endl;
00139 printThreadInfo(out, it->second);
00140 }
00141 lock_.unlock();
00142 }
00143
00144 void ompl::Profiler::console(void)
00145 {
00146 static msg::Interface msg("Profiler");
00147
00148 std::stringstream ss;
00149 ss << std::endl;
00150 status(ss, true);
00151 msg.inform(ss.str());
00152 }
00153
00154 namespace ompl
00155 {
00156
00157 struct dEnv
00158 {
00159 std::string name;
00160 unsigned long int value;
00161 };
00162
00163 struct SortEnvByValue
00164 {
00165 bool operator()(const dEnv &a, const dEnv &b) const
00166 {
00167 return a.value > b.value;
00168 }
00169 };
00170
00171 struct dTm
00172 {
00173 std::string name;
00174 double value;
00175 };
00176
00177 struct SortTmByValue
00178 {
00179 bool operator()(const dTm &a, const dTm &b) const
00180 {
00181 return a.value > b.value;
00182 }
00183 };
00184 }
00185
00186 void ompl::Profiler::printThreadInfo(std::ostream &out, const PerThread &data)
00187 {
00188 double total = time::seconds(tinfo_.total);
00189
00190 std::vector<dEnv> events;
00191
00192 for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin() ; iev != data.events.end() ; ++iev)
00193 {
00194 dEnv next = {iev->first, iev->second};
00195 events.push_back(next);
00196 }
00197
00198 std::sort(events.begin(), events.end(), SortEnvByValue());
00199
00200 for (unsigned int i = 0 ; i < events.size() ; ++i)
00201 out << events[i].name << ": " << events[i].value << std::endl;
00202
00203 std::vector<dTm> time;
00204
00205 for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin() ; itm != data.time.end() ; ++itm)
00206 {
00207 dTm next = {itm->first, time::seconds(itm->second.total)};
00208 time.push_back(next);
00209 }
00210
00211 std::sort(time.begin(), time.end(), SortTmByValue());
00212
00213 double unaccounted = total;
00214 for (unsigned int i = 0 ; i < time.size() ; ++i)
00215 {
00216 const TimeInfo &d = data.time.find(time[i].name)->second;
00217
00218 double tS = time::seconds(d.shortest);
00219 double tL = time::seconds(d.longest);
00220 out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value/total) << "%), ["
00221 << tS << "s --> " << tL << " s], " << d.parts << " parts";
00222 if (d.parts > 0)
00223 out << ", " << (time::seconds(d.total) / (double)d.parts) << " s on average";
00224 out << std::endl;
00225 unaccounted -= time[i].value;
00226 }
00227 out << "Unaccounted time : " << unaccounted;
00228 if (total > 0.0)
00229 out << " (" << (100.0 * unaccounted / total) << " %)";
00230 out << std::endl;
00231
00232 out << std::endl;
00233 }
00234
00235 #endif