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


moveit_core
Author(s): Ioan Sucan , Sachin Chitta , Acorn Pooley
autogenerated on Thu Aug 27 2015 13:58:53