Profiler.cpp
1 /*********************************************************************
2 * Software License Agreement (BSD License)
3 *
4 * Copyright (c) 2008, Willow Garage, Inc.
5 * All rights reserved.
6 *
7 * Redistribution and use in source and binary forms, with or without
8 * modification, are permitted provided that the following conditions
9 * are met:
10 *
11 * * Redistributions of source code must retain the above copyright
12 * notice, this list of conditions and the following disclaimer.
13 * * Redistributions in binary form must reproduce the above
14 * copyright notice, this list of conditions and the following
15 * disclaimer in the documentation and/or other materials provided
16 * with the distribution.
17 * * Neither the name of the Willow Garage nor the names of its
18 * contributors may be used to endorse or promote products derived
19 * from this software without specific prior written permission.
20 *
21 * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
22 * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
23 * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
24 * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
25 * COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
26 * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
27 * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
28 * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER
29 * CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
30 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN
31 * ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
32 * POSSIBILITY OF SUCH DAMAGE.
33 *********************************************************************/
34 
35 
38 #include "ompl/tools/debug/Profiler.h"
39 
41 {
42  static Profiler p(true, false);
43  return p;
44 }
45 
46 #if ENABLE_PROFILING
47 
48 #include "ompl/util/Console.h"
49 #include <vector>
50 #include <algorithm>
51 #include <sstream>
52 
54 {
55  lock_.lock();
56  if (!running_)
57  {
58  tinfo_.set();
59  running_ = true;
60  }
61  lock_.unlock();
62 }
63 
65 {
66  lock_.lock();
67  if (running_)
68  {
69  tinfo_.update();
70  running_ = false;
71  }
72  lock_.unlock();
73 }
74 
76 {
77  lock_.lock();
78  data_.clear();
79  tinfo_ = TimeInfo();
80  if (running_)
81  tinfo_.set();
82  lock_.unlock();
83 }
84 
85 void ompl::tools::Profiler::event(const std::string &name, const unsigned int times)
86 {
87  lock_.lock();
88  data_[boost::this_thread::get_id()].events[name] += times;
89  lock_.unlock();
90 }
91 
92 void ompl::tools::Profiler::average(const std::string &name, const double value)
93 {
94  lock_.lock();
95  AvgInfo &a = data_[boost::this_thread::get_id()].avg[name];
96  a.total += value;
97  a.totalSqr += value*value;
98  a.parts++;
99  lock_.unlock();
100 }
101 
102 void ompl::tools::Profiler::begin(const std::string &name)
103 {
104  lock_.lock();
105  data_[boost::this_thread::get_id()].time[name].set();
106  lock_.unlock();
107 }
108 
109 void ompl::tools::Profiler::end(const std::string &name)
110 {
111  lock_.lock();
112  data_[boost::this_thread::get_id()].time[name].update();
113  lock_.unlock();
114 }
115 
116 void ompl::tools::Profiler::status(std::ostream &out, bool merge)
117 {
118  stop();
119  lock_.lock();
120  printOnDestroy_ = false;
121 
122  out << std::endl;
123  out << " *** Profiling statistics. Total counted time : " << time::seconds(tinfo_.total) << " seconds" << std::endl;
124 
125  if (merge)
126  {
127  PerThread combined;
128  for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
129  {
130  for (std::map<std::string, unsigned long int>::const_iterator iev = it->second.events.begin() ; iev != it->second.events.end(); ++iev)
131  combined.events[iev->first] += iev->second;
132  for (std::map<std::string, AvgInfo>::const_iterator iavg = it->second.avg.begin() ; iavg != it->second.avg.end(); ++iavg)
133  {
134  combined.avg[iavg->first].total += iavg->second.total;
135  combined.avg[iavg->first].totalSqr += iavg->second.totalSqr;
136  combined.avg[iavg->first].parts += iavg->second.parts;
137  }
138  for (std::map<std::string, TimeInfo>::const_iterator itm = it->second.time.begin() ; itm != it->second.time.end(); ++itm)
139  {
140  TimeInfo &tc = combined.time[itm->first];
141  tc.total = tc.total + itm->second.total;
142  tc.parts = tc.parts + itm->second.parts;
143  if (tc.shortest > itm->second.shortest)
144  tc.shortest = itm->second.shortest;
145  if (tc.longest < itm->second.longest)
146  tc.longest = itm->second.longest;
147  }
148  }
149  printThreadInfo(out, combined);
150  }
151  else
152  for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin() ; it != data_.end() ; ++it)
153  {
154  out << "Thread " << it->first << ":" << std::endl;
155  printThreadInfo(out, it->second);
156  }
157  lock_.unlock();
158 }
159 
161 {
162  std::stringstream ss;
163  ss << std::endl;
164  status(ss, true);
165  OMPL_INFORM(ss.str().c_str());
166 }
167 
169 namespace ompl
170 {
171 
172  struct dataIntVal
173  {
174  std::string name;
175  unsigned long int value;
176  };
177 
178  struct SortIntByValue
179  {
180  bool operator()(const dataIntVal &a, const dataIntVal &b) const
181  {
182  return a.value > b.value;
183  }
184  };
185 
186  struct dataDoubleVal
187  {
188  std::string name;
189  double value;
190  };
191 
192  struct SortDoubleByValue
193  {
194  bool operator()(const dataDoubleVal &a, const dataDoubleVal &b) const
195  {
196  return a.value > b.value;
197  }
198  };
199 }
201 
202 void ompl::tools::Profiler::printThreadInfo(std::ostream &out, const PerThread &data)
203 {
204  double total = time::seconds(tinfo_.total);
205 
206  std::vector<dataIntVal> events;
207  for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin() ; iev != data.events.end() ; ++iev)
208  {
209  dataIntVal next = {iev->first, iev->second};
210  events.push_back(next);
211  }
212  std::sort(events.begin(), events.end(), SortIntByValue());
213  if (!events.empty())
214  out << "Events:" << std::endl;
215  for (unsigned int i = 0 ; i < events.size() ; ++i)
216  out << events[i].name << ": " << events[i].value << std::endl;
217 
218  std::vector<dataDoubleVal> avg;
219  for (std::map<std::string, AvgInfo>::const_iterator ia = data.avg.begin() ; ia != data.avg.end() ; ++ia)
220  {
221  dataDoubleVal next = {ia->first, ia->second.total / (double)ia->second.parts};
222  avg.push_back(next);
223  }
224  std::sort(avg.begin(), avg.end(), SortDoubleByValue());
225  if (!avg.empty())
226  out << "Averages:" << std::endl;
227  for (unsigned int i = 0 ; i < avg.size() ; ++i)
228  {
229  const AvgInfo &a = data.avg.find(avg[i].name)->second;
230  out << avg[i].name << ": " << avg[i].value << " (stddev = " <<
231  sqrt(fabs(a.totalSqr - (double)a.parts * avg[i].value * avg[i].value) / ((double)a.parts - 1.)) << ")" << std::endl;
232  }
233 
234  std::vector<dataDoubleVal> time;
235 
236  for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin() ; itm != data.time.end() ; ++itm)
237  {
238  dataDoubleVal next = {itm->first, time::seconds(itm->second.total)};
239  time.push_back(next);
240  }
241 
242  std::sort(time.begin(), time.end(), SortDoubleByValue());
243  if (!time.empty())
244  out << "Blocks of time:" << std::endl;
245 
246  double unaccounted = total;
247  for (unsigned int i = 0 ; i < time.size() ; ++i)
248  {
249  const TimeInfo &d = data.time.find(time[i].name)->second;
250 
251  double tS = time::seconds(d.shortest);
252  double tL = time::seconds(d.longest);
253  out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value/total) << "%), ["
254  << tS << "s --> " << tL << " s], " << d.parts << " parts";
255  if (d.parts > 0)
256  out << ", " << (time::seconds(d.total) / (double)d.parts) << " s on average";
257  out << std::endl;
258  unaccounted -= time[i].value;
259  }
260  // if we do not appear to have counted time multiple times, print the unaccounted time too
261  if (unaccounted >= 0.0)
262  {
263  out << "Unaccounted time : " << unaccounted;
264  if (total > 0.0)
265  out << " (" << (100.0 * unaccounted / total) << " %)";
266  out << std::endl;
267  }
268 
269  out << std::endl;
270 }
271 
272 #endif
void stop()
Stop counting time.
void begin(const std::string &name)
Begin counting time for a specific chunk of code.
void start()
Start counting time.
void end(const std::string &name)
Stop counting time for a specific chunk of code.
void status(std::ostream &out=std::cout, bool merge=true)
Print the status of the profiled code chunks and events. Optionally, computation done by different th...
duration seconds(double sec)
Return the time duration representing a given number of seconds.
Definition: Time.h:62
Main namespace. Contains everything in this library.
Definition: Cost.h:42
void event(const std::string &name, const unsigned int times=1)
Count a specific event for a number of times.
This is a simple thread-safe tool for counting time spent in various chunks of code. This is different from external profiling tools in that it allows the user to count time spent in various bits of code (sub-function granularity) or count how many times certain pieces of code are executed.
Definition: Profiler.h:77
void console()
Print the status of the profiled code chunks and events to the console (using msg::Console) ...
void clear()
Clear counted time and events.
static Profiler & Instance()
Return an instance of the class.
Definition: Profiler.cpp:40
void average(const std::string &name, const double value)
Maintain the average of a specific value.
#define OMPL_INFORM(fmt,...)
Log a formatted information string.
Definition: Console.h:68