profiler.cpp
Go to the documentation of this file.
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 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 /* Author: Ioan Sucan */
36 
38 
40 {
41  static Profiler p(false, false);
42  return p;
43 }
44 
45 #if MOVEIT_ENABLE_PROFILING
46 
47 #include <console_bridge/console.h>
48 #include <vector>
49 #include <algorithm>
50 #include <sstream>
51 
53 {
54  lock_.lock();
55  if (!running_)
56  {
57  tinfo_.set();
58  running_ = true;
59  }
60  lock_.unlock();
61 }
62 
64 {
65  lock_.lock();
66  if (running_)
67  {
68  tinfo_.update();
69  running_ = false;
70  }
71  lock_.unlock();
72 }
73 
75 {
76  lock_.lock();
77  data_.clear();
78  tinfo_ = TimeInfo();
79  if (running_)
80  tinfo_.set();
81  lock_.unlock();
82 }
83 
84 void moveit::tools::Profiler::event(const std::string& name, const unsigned int times)
85 {
86  lock_.lock();
87  data_[boost::this_thread::get_id()].events[name] += times;
88  lock_.unlock();
89 }
90 
91 void moveit::tools::Profiler::average(const std::string& name, const double value)
92 {
93  lock_.lock();
94  AvgInfo& a = data_[boost::this_thread::get_id()].avg[name];
95  a.total += value;
96  a.totalSqr += value * value;
97  a.parts++;
98  lock_.unlock();
99 }
100 
101 void moveit::tools::Profiler::begin(const std::string& name)
102 {
103  lock_.lock();
104  data_[boost::this_thread::get_id()].time[name].set();
105  lock_.unlock();
106 }
107 
108 void moveit::tools::Profiler::end(const std::string& name)
109 {
110  lock_.lock();
111  data_[boost::this_thread::get_id()].time[name].update();
112  lock_.unlock();
113 }
114 
115 namespace
116 {
117 inline double to_seconds(const boost::posix_time::time_duration& d)
118 {
119  return (double)d.total_microseconds() / 1000000.0;
120 }
121 }
122 
123 void moveit::tools::Profiler::status(std::ostream& out, bool merge)
124 {
125  stop();
126  lock_.lock();
127  printOnDestroy_ = false;
128 
129  out << std::endl;
130  out << " *** Profiling statistics. Total counted time : " << to_seconds(tinfo_.total) << " seconds" << std::endl;
131 
132  if (merge)
133  {
134  PerThread combined;
135  for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin(); it != data_.end(); ++it)
136  {
137  for (std::map<std::string, unsigned long int>::const_iterator iev = it->second.events.begin();
138  iev != it->second.events.end(); ++iev)
139  combined.events[iev->first] += iev->second;
140  for (std::map<std::string, AvgInfo>::const_iterator iavg = it->second.avg.begin(); iavg != it->second.avg.end();
141  ++iavg)
142  {
143  combined.avg[iavg->first].total += iavg->second.total;
144  combined.avg[iavg->first].totalSqr += iavg->second.totalSqr;
145  combined.avg[iavg->first].parts += iavg->second.parts;
146  }
147  for (std::map<std::string, TimeInfo>::const_iterator itm = it->second.time.begin(); itm != it->second.time.end();
148  ++itm)
149  {
150  TimeInfo& tc = combined.time[itm->first];
151  tc.total = tc.total + itm->second.total;
152  tc.parts = tc.parts + itm->second.parts;
153  if (tc.shortest > itm->second.shortest)
154  tc.shortest = itm->second.shortest;
155  if (tc.longest < itm->second.longest)
156  tc.longest = itm->second.longest;
157  }
158  }
159  printThreadInfo(out, combined);
160  }
161  else
162  for (std::map<boost::thread::id, PerThread>::const_iterator it = data_.begin(); it != data_.end(); ++it)
163  {
164  out << "Thread " << it->first << ":" << std::endl;
165  printThreadInfo(out, it->second);
166  }
167  lock_.unlock();
168 }
169 
171 {
172  std::stringstream ss;
173  ss << std::endl;
174  status(ss, true);
175  logInform(ss.str().c_str());
176 }
177 
179 namespace
180 {
181 struct dataIntVal
182 {
183  std::string name;
184  unsigned long int value;
185 };
186 
187 struct SortIntByValue
188 {
189  bool operator()(const dataIntVal& a, const dataIntVal& b) const
190  {
191  return a.value > b.value;
192  }
193 };
194 
195 struct dataDoubleVal
196 {
197  std::string name;
198  double value;
199 };
200 
201 struct SortDoubleByValue
202 {
203  bool operator()(const dataDoubleVal& a, const dataDoubleVal& b) const
204  {
205  return a.value > b.value;
206  }
207 };
208 }
210 
211 void moveit::tools::Profiler::printThreadInfo(std::ostream& out, const PerThread& data)
212 {
213  double total = to_seconds(tinfo_.total);
214 
215  std::vector<dataIntVal> events;
216  for (std::map<std::string, unsigned long int>::const_iterator iev = data.events.begin(); iev != data.events.end();
217  ++iev)
218  {
219  dataIntVal next = { iev->first, iev->second };
220  events.push_back(next);
221  }
222  std::sort(events.begin(), events.end(), SortIntByValue());
223  if (!events.empty())
224  out << "Events:" << std::endl;
225  for (unsigned int i = 0; i < events.size(); ++i)
226  out << events[i].name << ": " << events[i].value << std::endl;
227 
228  std::vector<dataDoubleVal> avg;
229  for (std::map<std::string, AvgInfo>::const_iterator ia = data.avg.begin(); ia != data.avg.end(); ++ia)
230  {
231  dataDoubleVal next = { ia->first, ia->second.total / (double)ia->second.parts };
232  avg.push_back(next);
233  }
234  std::sort(avg.begin(), avg.end(), SortDoubleByValue());
235  if (!avg.empty())
236  out << "Averages:" << std::endl;
237  for (unsigned int i = 0; i < avg.size(); ++i)
238  {
239  const AvgInfo& a = data.avg.find(avg[i].name)->second;
240  out << avg[i].name << ": " << avg[i].value << " (stddev = "
241  << sqrt(fabs(a.totalSqr - (double)a.parts * avg[i].value * avg[i].value) / ((double)a.parts - 1.)) << ")"
242  << std::endl;
243  }
244 
245  std::vector<dataDoubleVal> time;
246 
247  for (std::map<std::string, TimeInfo>::const_iterator itm = data.time.begin(); itm != data.time.end(); ++itm)
248  {
249  dataDoubleVal next = { itm->first, to_seconds(itm->second.total) };
250  time.push_back(next);
251  }
252 
253  std::sort(time.begin(), time.end(), SortDoubleByValue());
254  if (!time.empty())
255  out << "Blocks of time:" << std::endl;
256 
257  double unaccounted = total;
258  for (unsigned int i = 0; i < time.size(); ++i)
259  {
260  const TimeInfo& d = data.time.find(time[i].name)->second;
261 
262  double tS = to_seconds(d.shortest);
263  double tL = to_seconds(d.longest);
264  out << time[i].name << ": " << time[i].value << "s (" << (100.0 * time[i].value / total) << "%), [" << tS
265  << "s --> " << tL << " s], " << d.parts << " parts";
266  if (d.parts > 0)
267  {
268  double pavg = to_seconds(d.total) / (double)d.parts;
269  out << ", " << pavg << " s on average";
270  if (pavg < 1.0)
271  out << " (" << 1.0 / pavg << " /s)";
272  }
273  out << std::endl;
274  unaccounted -= time[i].value;
275  }
276  // if we do not appear to have counted time multiple times, print the unaccounted time too
277  if (unaccounted >= 0.0)
278  {
279  out << "Unaccounted time : " << unaccounted;
280  if (total > 0.0)
281  out << " (" << (100.0 * unaccounted / total) << " %)";
282  out << std::endl;
283  }
284 
285  out << std::endl;
286 }
287 
288 #endif
Information to be maintained for each thread.
Definition: profiler.h:294
d
static Profiler & Instance(void)
Return an instance of the class.
Definition: profiler.cpp:39
void begin(const std::string &name)
Begin counting time for a specific chunk of code.
std::map< std::string, TimeInfo > time
The amount of time spent in various places.
Definition: profiler.h:303
void start(void)
Start counting time.
double totalSqr
The sub of squares of the values to average.
Definition: profiler.h:287
unsigned long int parts
Number of times a chunk of time was added to this structure.
Definition: profiler.h:256
void console(void)
Print the status of the profiled code chunks and events to the console (using msg::Console) ...
void update(void)
Add the counted time to the total time.
Definition: profiler.h:268
void end(const std::string &name)
Stop counting time for a specific chunk of code.
std::map< std::string, unsigned long int > events
The stored events.
Definition: profiler.h:297
void printThreadInfo(std::ostream &out, const PerThread &data)
void stop(void)
Stop counting time.
INLINE Rall1d< T, V, S > sqrt(const Rall1d< T, V, S > &arg)
Information maintained about averaged values.
Definition: profiler.h:281
boost::posix_time::time_duration total
Total time counted.
Definition: profiler.h:247
boost::posix_time::time_duration shortest
The shortest counted time interval.
Definition: profiler.h:250
unsigned long int parts
Number of times a value was added to this structure.
Definition: profiler.h:290
boost::posix_time::time_duration longest
The longest counted time interval.
Definition: profiler.h:253
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...
void average(const std::string &name, const double value)
Maintain the average of a specific value.
std::map< std::string, AvgInfo > avg
The stored averages.
Definition: profiler.h:300
void set(void)
Begin counting time.
Definition: profiler.h:262
boost::mutex lock_
Definition: profiler.h:308
void clear(void)
Clear counted time and events.
void event(const std::string &name, const unsigned int times=1)
Count a specific event for a number of times.
std::map< boost::thread::id, PerThread > data_
Definition: profiler.h:309
Information about time spent in a section of the code.
Definition: profiler.h:239
double total
The sum of the values to average.
Definition: profiler.h:284


moveit_core
Author(s): Ioan Sucan , Sachin Chitta , Acorn Pooley
autogenerated on Mon Jan 15 2018 03:50:44