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


moveit_core
Author(s): Ioan Sucan , Sachin Chitta , Acorn Pooley
autogenerated on Sat Sep 15 2018 02:51:06