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 
37 #include "ompl/tools/debug/Profiler.h"
38 #include <cmath>
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_[std::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_[std::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_[std::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_[std::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<std::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();
131  iev != it->second.events.end(); ++iev)
132  combined.events[iev->first] += iev->second;
133  for (std::map<std::string, AvgInfo>::const_iterator iavg = it->second.avg.begin();
134  iavg != it->second.avg.end(); ++iavg)
135  {
136  combined.avg[iavg->first].total += iavg->second.total;
137  combined.avg[iavg->first].totalSqr += iavg->second.totalSqr;
138  combined.avg[iavg->first].parts += iavg->second.parts;
139  }
140  for (std::map<std::string, TimeInfo>::const_iterator itm = it->second.time.begin();
141  itm != it->second.time.end(); ++itm)
142  {
143  TimeInfo &tc = combined.time[itm->first];
144  tc.total = tc.total + itm->second.total;
145  tc.parts = tc.parts + itm->second.parts;
146  if (tc.shortest > itm->second.shortest)
147  tc.shortest = itm->second.shortest;
148  if (tc.longest < itm->second.longest)
149  tc.longest = itm->second.longest;
150  }
151  }
152  printThreadInfo(out, combined);
153  }
154  else
155  for (std::map<std::thread::id, PerThread>::const_iterator it = data_.begin(); it != data_.end(); ++it)
156  {
157  out << "Thread " << it->first << ":" << std::endl;
158  printThreadInfo(out, it->second);
159  }
160  lock_.unlock();
161 }
162 
164 {
165  std::stringstream ss;
166  ss << std::endl;
167  status(ss, true);
168  OMPL_INFORM(ss.str().c_str());
169 }
170 
172 namespace ompl
173 {
174  struct dataIntVal
175  {
176  std::string name;
177  unsigned long int value;
178  };
179 
180  struct SortIntByValue
181  {
182  bool operator()(const dataIntVal &a, const dataIntVal &b) const
183  {
184  return a.value > b.value;
185  }
186  };
187 
188  struct dataDoubleVal
189  {
190  std::string name;
191  double value;
192  };
193 
194  struct SortDoubleByValue
195  {
196  bool operator()(const dataDoubleVal &a, const dataDoubleVal &b) const
197  {
198  return a.value > b.value;
199  }
200  };
201 }
203 
204 void ompl::tools::Profiler::printThreadInfo(std::ostream &out, const PerThread &data)
205 {
206  double total = time::seconds(tinfo_.total);
207 
208  std::vector<dataIntVal> events;
209  for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin(); iev != data.events.end();
210  ++iev)
211  {
212  dataIntVal next = {iev->first, iev->second};
213  events.push_back(next);
214  }
215  std::sort(events.begin(), events.end(), SortIntByValue());
216  if (!events.empty())
217  out << "Events:" << std::endl;
218  for (unsigned int i = 0; i < events.size(); ++i)
219  out << events[i].name << ": " << events[i].value << std::endl;
220 
221  std::vector<dataDoubleVal> avg;
222  for (std::map<std::string, AvgInfo>::const_iterator ia = data.avg.begin(); ia != data.avg.end(); ++ia)
223  {
224  dataDoubleVal next = {ia->first, ia->second.total / (double)ia->second.parts};
225  avg.push_back(next);
226  }
227  std::sort(avg.begin(), avg.end(), SortDoubleByValue());
228  if (!avg.empty())
229  out << "Averages:" << std::endl;
230  for (unsigned int i = 0; i < avg.size(); ++i)
231  {
232  const AvgInfo &a = data.avg.find(avg[i].name)->second;
233  out << avg[i].name << ": " << avg[i].value << " (stddev = "
234  << std::sqrt(std::abs(a.totalSqr - (double)a.parts * avg[i].value * avg[i].value) / ((double)a.parts - 1.))
235  << ")" << std::endl;
236  }
237 
238  std::vector<dataDoubleVal> time;
239 
240  for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin(); itm != data.time.end(); ++itm)
241  {
242  dataDoubleVal next = {itm->first, time::seconds(itm->second.total)};
243  time.push_back(next);
244  }
245 
246  std::sort(time.begin(), time.end(), SortDoubleByValue());
247  if (!time.empty())
248  out << "Blocks of time:" << std::endl;
249 
250  double unaccounted = total;
251  for (unsigned int i = 0; i < time.size(); ++i)
252  {
253  const TimeInfo &d = data.time.find(time[i].name)->second;
254 
255  double tS = time::seconds(d.shortest);
256  double tL = time::seconds(d.longest);
257  out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value / total) << "%), [" << tS
258  << "s --> " << tL << " s], " << d.parts << " parts";
259  if (d.parts > 0)
260  out << ", " << (time::seconds(d.total) / (double)d.parts) << " s on average";
261  out << std::endl;
262  unaccounted -= time[i].value;
263  }
264  // if we do not appear to have counted time multiple times, print the unaccounted time too
265  if (unaccounted >= 0.0)
266  {
267  out << "Unaccounted time : " << unaccounted;
268  if (total > 0.0)
269  out << " (" << (100.0 * unaccounted / total) << " %)";
270  out << std::endl;
271  }
272 
273  out << std::endl;
274 }
275 
276 #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:76
Main namespace. Contains everything in this library.
Definition: AppBase.h:21
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:72
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