All Classes Namespaces Functions Variables Typedefs Enumerations Enumerator Friends
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  logInform(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