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 
11 namespace 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 }
THROW_ARGOSEXCEPTION
#define THROW_ARGOSEXCEPTION(message)
This macro throws an ARGoS exception with the passed message.
Definition: argos_exception.h:111
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
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