Loading...
Searching...
No Matches
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
85void 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
92void 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
102void 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
109void 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
116void 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
172namespace 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
204void 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
This is a simple thread-safe tool for counting time spent in various chunks of code....
Definition Profiler.h:73
void console()
Print the status of the profiled code chunks and events to the console (using msg::Console)
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 begin(const std::string &name)
Begin counting time for a specific chunk of code.
void clear()
Clear counted time and events.
void start()
Start counting time.
void average(const std::string &name, const double value)
Maintain the average of a specific value.
void stop()
Stop counting time.
void end(const std::string &name)
Stop 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.
#define OMPL_INFORM(fmt,...)
Log a formatted information string.
Definition Console.h:68
duration seconds(double sec)
Return the time duration representing a given number of seconds.
Definition Time.h:64
Main namespace. Contains everything in this library.