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 end(const std::string &name)
Stop counting time for a specific chunk of code.
void start()
Start counting time.
#define OMPL_INFORM(fmt,...)
Log a formatted information string.
Definition: Console.h:68
This is a simple thread-safe tool for counting time spent in various chunks of code....
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.
void average(const std::string &name, const double value)
Maintain the average of a specific value.
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...
static Profiler & Instance()
Return an instance of the class.
Definition: Profiler.cpp:40
void stop()
Stop counting time.
duration seconds(double sec)
Return the time duration representing a given number of seconds.
Definition: Time.h:128
Main namespace. Contains everything in this library.
Definition: AppBase.h:21
void begin(const std::string &name)
Begin counting time for a specific chunk of code.
void event(const std::string &name, const unsigned int times=1)
Count a specific event for a number of times.