ompl/tools/debug/src/Profiler.cpp
00001 /********************************************************************* 00002 * Software License Agreement (BSD License) 00003 * 00004 * Copyright (c) 2008, Willow Garage, Inc. 00005 * All rights reserved. 00006 * 00007 * Redistribution and use in source and binary forms, with or without 00008 * modification, are permitted provided that the following conditions 00009 * are met: 00010 * 00011 * * Redistributions of source code must retain the above copyright 00012 * notice, this list of conditions and the following disclaimer. 00013 * * Redistributions in binary form must reproduce the above 00014 * copyright notice, this list of conditions and the following 00015 * disclaimer in the documentation and/or other materials provided 00016 * with the distribution. 00017 * * Neither the name of the Willow Garage nor the names of its 00018 * contributors may be used to endorse or promote products derived 00019 * from this software without specific prior written permission. 00020 * 00021 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 00022 * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 00023 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS 00024 * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE 00025 * COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, 00026 * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, 00027 * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; 00028 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER 00029 * CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT 00030 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN 00031 * ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE 00032 * POSSIBILITY OF SUCH DAMAGE. 00033 *********************************************************************/ 00034 00035 00038 #include "ompl/tools/debug/Profiler.h" 00039 00040 ompl::tools::Profiler& ompl::tools::Profiler::Instance() 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() 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() 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() 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() 00161 { 00162 std::stringstream ss; 00163 ss << std::endl; 00164 status(ss, true); 00165 OMPL_INFORM(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 // if we do not appear to have counted time multiple times, print the unaccounted time too 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