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
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Friends Defines