All Classes Namespaces Functions Variables Typedefs Enumerations Enumerator Friends

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