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


moveit_core
Author(s): Ioan Sucan , Sachin Chitta , Acorn Pooley
autogenerated on Tue Nov 24 2020 03:26:40