ARGoS 3
A parallel, multi-engine simulator for swarm robotics
profiler.cpp
Go to the documentation of this file.
1
7#include "profiler.h"
8#include <argos3/core/utility/logging/argos_log.h>
9#include <argos3/core/utility/configuration/argos_configuration.h>
10
11namespace argos {
12
13 /****************************************/
14 /****************************************/
15
16 static double TV2Sec(const ::timeval& t_timeval) {
17 return
18 static_cast<double>(t_timeval.tv_sec) +
19 static_cast<double>(t_timeval.tv_usec) * 0.000001;
20 }
21
22 /****************************************/
23 /****************************************/
24
25 static double CPUUsage(const ::rusage& t_rusage,
26 double f_elapsed_time) {
27 return 100.0 *
28 (TV2Sec(t_rusage.ru_utime) +
29 TV2Sec(t_rusage.ru_stime)) /
30 f_elapsed_time;
31 }
32
33 /****************************************/
34 /****************************************/
35
36#define DUMP_RUSAGE_FIELD_HUMAN_READABLE(MSG, FIELD) c_os << MSG ": " << t_resources.ru_ ## FIELD << std::endl;
37 void DumpResourceUsageHumanReadable(std::ostream& c_os,
38 const ::rusage& t_resources) {
39 double fUserTime = TV2Sec(t_resources.ru_utime);
40 c_os << "User time: " << fUserTime << std::endl;
41 double fSysTime = TV2Sec(t_resources.ru_stime);
42 c_os << "System time: " << fSysTime << std::endl;
43 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Maximum resident set size", maxrss);
44 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Integral shared memory size", ixrss);
45 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Integral unshared data size", idrss);
46 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Integral unshared stack size", isrss);
47 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Page reclaims", minflt);
48 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Page faults", majflt);
49 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Swaps", nswap);
50 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Block input operations", inblock);
51 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Block output operations", oublock);
52 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Messages sent", msgsnd);
53 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Messages received", msgrcv);
54 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Signals received", nsignals);
55 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Voluntary context switches", nvcsw);
56 DUMP_RUSAGE_FIELD_HUMAN_READABLE("Involuntary context switches", nivcsw);
57 }
58
59 /****************************************/
60 /****************************************/
61
62#define DUMP_RUSAGE_FIELD_TABLE_ROW(FIELD) c_os << " " << t_resources.ru_ ## FIELD;
63 void DumpResourceUsageAsTableRow(std::ostream& c_os,
64 const ::rusage& t_resources) {
65 double fUserTime = TV2Sec(t_resources.ru_utime);
66 c_os << fUserTime;
67 double fSysTime = TV2Sec(t_resources.ru_stime);
68 c_os << " " << fSysTime;
69 DUMP_RUSAGE_FIELD_TABLE_ROW(maxrss);
70 DUMP_RUSAGE_FIELD_TABLE_ROW(ixrss);
71 DUMP_RUSAGE_FIELD_TABLE_ROW(idrss);
72 DUMP_RUSAGE_FIELD_TABLE_ROW(isrss);
73 DUMP_RUSAGE_FIELD_TABLE_ROW(minflt);
74 DUMP_RUSAGE_FIELD_TABLE_ROW(majflt);
75 DUMP_RUSAGE_FIELD_TABLE_ROW(nswap);
76 DUMP_RUSAGE_FIELD_TABLE_ROW(inblock);
77 DUMP_RUSAGE_FIELD_TABLE_ROW(oublock);
78 DUMP_RUSAGE_FIELD_TABLE_ROW(msgsnd);
79 DUMP_RUSAGE_FIELD_TABLE_ROW(msgrcv);
80 DUMP_RUSAGE_FIELD_TABLE_ROW(nsignals);
81 DUMP_RUSAGE_FIELD_TABLE_ROW(nvcsw);
82 DUMP_RUSAGE_FIELD_TABLE_ROW(nivcsw);
83 }
84
85 /****************************************/
86 /****************************************/
87
88#define DIFF_RUSAGE_FIELD(FIELD) tResult.ru_ ## FIELD = t_resource1.ru_ ## FIELD - t_resource2.ru_ ## FIELD;
89 ::rusage operator-(const ::rusage& t_resource1,
90 const ::rusage& t_resource2) {
91 ::rusage tResult;
92 DIFF_RUSAGE_FIELD(utime.tv_sec);
93 DIFF_RUSAGE_FIELD(utime.tv_usec);
94 DIFF_RUSAGE_FIELD(stime.tv_sec);
95 DIFF_RUSAGE_FIELD(stime.tv_usec);
96 DIFF_RUSAGE_FIELD(maxrss);
97 DIFF_RUSAGE_FIELD(ixrss);
98 DIFF_RUSAGE_FIELD(idrss);
99 DIFF_RUSAGE_FIELD(isrss);
100 DIFF_RUSAGE_FIELD(minflt);
101 DIFF_RUSAGE_FIELD(majflt);
102 DIFF_RUSAGE_FIELD(nswap);
103 DIFF_RUSAGE_FIELD(inblock);
104 DIFF_RUSAGE_FIELD(oublock);
105 DIFF_RUSAGE_FIELD(msgsnd);
106 DIFF_RUSAGE_FIELD(msgrcv);
107 DIFF_RUSAGE_FIELD(nsignals);
108 DIFF_RUSAGE_FIELD(nvcsw);
109 DIFF_RUSAGE_FIELD(nivcsw);
110 return tResult;
111 }
112
113 /****************************************/
114 /****************************************/
115
116 CProfiler::CProfiler(const std::string& str_file_name,
117 bool b_trunc) {
118 if(b_trunc) {
119 m_cOutFile.open(str_file_name.c_str(),
120 std::ios::trunc | std::ios::out);
121 }
122 else {
123 m_cOutFile.open(str_file_name.c_str(),
124 std::ios::app | std::ios::out);
125 }
126 LOG << "[INFO] Opened file \"" << str_file_name << "\" for profiling." << std::endl;
127 int nError = pthread_mutex_init(&m_tThreadResourceUsageMutex, nullptr);
128 if(nError) {
129 THROW_ARGOSEXCEPTION("Error creating thread profiler mutex " << ::strerror(nError));
130 }
131 }
132
133 /****************************************/
134 /****************************************/
135
136 CProfiler::~CProfiler() {
137 m_cOutFile.close();
138 pthread_mutex_destroy(&m_tThreadResourceUsageMutex);
139 }
140
141 /****************************************/
142 /****************************************/
143
144 void CProfiler::Start() {
145 StartWallClock();
146 StartCPUProfiler();
147 }
148
149 /****************************************/
150 /****************************************/
151
152 void CProfiler::Stop() {
153 StopCPUProfiler();
154 StopWallClock();
155 }
156
157 /****************************************/
158 /****************************************/
159
160 void CProfiler::Flush(bool b_human_readable) {
161 if(b_human_readable) {
162 FlushHumanReadable();
163 }
164 else {
165 FlushAsTable();
166 }
167 }
168
169 /****************************************/
170 /****************************************/
171
172 void CProfiler::CollectThreadResourceUsage() {
173 pthread_mutex_lock(&m_tThreadResourceUsageMutex);
174 ::rusage tResourceUsage;
175#ifdef __APPLE__
176 /* FIXME: This is badly broken, but I don't know how to obtain
177 the equivalent of RUSAGE_THREAD on MacOS. --tc */
178 getrusage(RUSAGE_SELF, &tResourceUsage);
179#else
180 ::getrusage(::RUSAGE_THREAD, &tResourceUsage);
181#endif
182 m_vecThreadResourceUsage.push_back(tResourceUsage);
183 pthread_mutex_unlock(&m_tThreadResourceUsageMutex);
184 }
185
186 /****************************************/
187 /****************************************/
188
189 void CProfiler::FlushHumanReadable() {
190 m_cOutFile << "[profiled portion overall]" << std::endl << std::endl;
191 double fStartTime = TV2Sec(m_tWallClockStart);
192 double fEndTime = TV2Sec(m_tWallClockEnd);
193 double fElapsedTime = fEndTime - fStartTime;
194 m_cOutFile << "Wall clock time: " << fElapsedTime << std::endl;
195 ::rusage tDiffResourceUsage = m_tResourceUsageEnd - m_tResourceUsageStart;
196 m_cOutFile << "CPU usage: " << CPUUsage(tDiffResourceUsage, fElapsedTime) << "%" << std::endl;
197 DumpResourceUsageHumanReadable(m_cOutFile, tDiffResourceUsage);
198 m_cOutFile << std::endl << "[profiled portion start]" << std::endl << std::endl;
199 DumpResourceUsageHumanReadable(m_cOutFile, m_tResourceUsageStart);
200 m_cOutFile << std::endl << "[profiled portion end]" << std::endl << std::endl;
201 DumpResourceUsageHumanReadable(m_cOutFile, m_tResourceUsageEnd);
202 m_cOutFile << std::endl << "[process overall]" << std::endl << std::endl;
203 ::rusage tResourceUsage;
204#ifdef __APPLE__
205 getrusage(RUSAGE_SELF, &tResourceUsage);
206#else
207 ::getrusage(::RUSAGE_SELF, &tResourceUsage);
208#endif
209 DumpResourceUsageHumanReadable(m_cOutFile, tResourceUsage);
210 if(! m_vecThreadResourceUsage.empty()) {
211 for(size_t i = 0; i < m_vecThreadResourceUsage.size(); ++i) {
212 m_cOutFile << std::endl << "[thread #" << i << " overall]" << std::endl << std::endl;
213 m_cOutFile << "CPU usage: " << CPUUsage(m_vecThreadResourceUsage[i], fElapsedTime) << "%" << std::endl;
214 DumpResourceUsageHumanReadable(m_cOutFile, m_vecThreadResourceUsage[i]);
215 }
216 }
217 }
218
219 /****************************************/
220 /****************************************/
221
222 void CProfiler::FlushAsTable() {
223 double fStartTime = TV2Sec(m_tWallClockStart);
224 double fEndTime = TV2Sec(m_tWallClockEnd);
225 double fElapsedTime = fEndTime - fStartTime;
226 ::rusage tDiffResourceUsage = m_tResourceUsageEnd - m_tResourceUsageStart;
227 m_cOutFile << "ProfPortion " << fElapsedTime << " "
228 << CPUUsage(tDiffResourceUsage, fElapsedTime) << " ";
229 DumpResourceUsageAsTableRow(m_cOutFile, tDiffResourceUsage);
230 m_cOutFile << std::endl << "PortionStart 0 0 ";
231 DumpResourceUsageAsTableRow(m_cOutFile, m_tResourceUsageStart);
232 m_cOutFile << std::endl << "PortionEnd 0 0 ";
233 DumpResourceUsageAsTableRow(m_cOutFile, m_tResourceUsageEnd);
234 m_cOutFile << std::endl << "Overall 0 0 ";
235 ::rusage tResourceUsage;
236#ifdef __APPLE__
237 getrusage(RUSAGE_SELF, &tResourceUsage);
238#else
239 ::getrusage(::RUSAGE_SELF, &tResourceUsage);
240#endif
241 DumpResourceUsageAsTableRow(m_cOutFile, tResourceUsage);
242 if(! m_vecThreadResourceUsage.empty()) {
243 for(size_t i = 0; i < m_vecThreadResourceUsage.size(); ++i) {
244 m_cOutFile << std::endl << "thread_" << i << " 0 "
245 << CPUUsage(m_vecThreadResourceUsage[i], fElapsedTime) << " ";
246 DumpResourceUsageAsTableRow(m_cOutFile, m_vecThreadResourceUsage[i]);
247 }
248 }
249 m_cOutFile << std::endl;
250 }
251
252 /****************************************/
253 /****************************************/
254
255 void CProfiler::StartWallClock() {
256 ::gettimeofday(&m_tWallClockStart, nullptr);
257 }
258
259 /****************************************/
260 /****************************************/
261
262 void CProfiler::StopWallClock() {
263 ::gettimeofday(&m_tWallClockEnd, nullptr);
264 }
265
266 /****************************************/
267 /****************************************/
268
269 void CProfiler::StartCPUProfiler() {
270#ifdef __APPLE__
271 getrusage(RUSAGE_SELF, &m_tResourceUsageStart);
272#else
273 ::getrusage(::RUSAGE_SELF, &m_tResourceUsageStart);
274#endif
275 }
276
277 /****************************************/
278 /****************************************/
279
280 void CProfiler::StopCPUProfiler() {
281#ifdef __APPLE__
282 getrusage(RUSAGE_SELF, &m_tResourceUsageEnd);
283#else
284 ::getrusage(::RUSAGE_SELF, &m_tResourceUsageEnd);
285#endif
286 }
287
288 /****************************************/
289 /****************************************/
290
291}
DUMP_RUSAGE_FIELD_TABLE_ROW
#define DUMP_RUSAGE_FIELD_TABLE_ROW(FIELD)
Definition profiler.cpp:62
DUMP_RUSAGE_FIELD_HUMAN_READABLE
#define DUMP_RUSAGE_FIELD_HUMAN_READABLE(MSG, FIELD)
Definition profiler.cpp:36
DIFF_RUSAGE_FIELD
#define DIFF_RUSAGE_FIELD(FIELD)
Definition profiler.cpp:88
THROW_ARGOSEXCEPTION
#define THROW_ARGOSEXCEPTION(message)
This macro throws an ARGoS exception with the passed message.
Definition argos_exception.h:111
argos
The namespace containing all the ARGoS related code.
Definition ci_actuator.h:12
argos::DumpResourceUsageAsTableRow
void DumpResourceUsageAsTableRow(std::ostream &c_os, const ::rusage &t_resources)
Definition profiler.cpp:63
argos::LOG
CARGoSLog LOG(std::cout, SLogColor(ARGOS_LOG_ATTRIBUTE_BRIGHT, ARGOS_LOG_COLOR_GREEN))
Definition argos_log.h:179
argos::operator-
::rusage operator-(const ::rusage &t_resource1, const ::rusage &t_resource2)
Definition profiler.cpp:89
argos::DumpResourceUsageHumanReadable
void DumpResourceUsageHumanReadable(std::ostream &c_os, const ::rusage &t_resources)
Definition profiler.cpp:37
argos::CProfiler::CollectThreadResourceUsage
void CollectThreadResourceUsage()
Definition profiler.cpp:172
argos::CProfiler::Flush
void Flush(bool b_human_readable)
Definition profiler.cpp:160
argos::CProfiler::CProfiler
CProfiler(const std::string &str_file_name, bool b_trunc=true)
Definition profiler.cpp:116