perf_log.C
Go to the documentation of this file.
1 // The libMesh Finite Element Library.
2 // Copyright (C) 2002-2014 Benjamin S. Kirk, John W. Peterson, Roy H. Stogner
3 
4 // This library is free software; you can redistribute it and/or
5 // modify it under the terms of the GNU Lesser General Public
6 // License as published by the Free Software Foundation; either
7 // version 2.1 of the License, or (at your option) any later version.
8 
9 // This library is distributed in the hope that it will be useful,
10 // but WITHOUT ANY WARRANTY; without even the implied warranty of
11 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
12 // Lesser General Public License for more details.
13 
14 // You should have received a copy of the GNU Lesser General Public
15 // License along with this library; if not, write to the Free Software
16 // Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
17 
18 
19 
20 // C++ includes
21 #include <iostream>
22 #include <iomanip>
23 #include <ctime>
24 #include <unistd.h>
25 #include <sys/utsname.h>
26 #include <sys/types.h>
27 #include <pwd.h>
28 #include <vector>
29 #include <sstream>
30 
31 // Local includes
32 #include "libmesh/perf_log.h"
33 #include "libmesh/timestamp.h"
34 
35 namespace libMesh
36 {
37 
38 
39 // ------------------------------------------------------------
40 // PerfLog class member funcions
41 
42 bool PerfLog::called = false;
43 
44 
45 PerfLog::PerfLog(const std::string& ln,
46  const bool le) :
47  label_name(ln),
48  log_events(le),
49  total_time(0.)
50 {
51  gettimeofday (&tstart, NULL);
52 
53  if (log_events)
54  this->clear();
55 }
56 
57 
58 
60 {
61  if (log_events)
62  this->print_log();
63 }
64 
65 
66 
68 {
69  if (log_events)
70  {
71  // check that all events are closed
72  for (std::map<std::pair<std::string,std::string>, PerfData>::iterator
73  pos = log.begin(); pos != log.end(); ++pos)
74  if (pos->second.open)
75  {
77  << "ERROR clearning performance log for class "
78  << label_name << std::endl
79  << "event " << pos->first.second << " is still being monitored!"
80  << std::endl;
81 
82  libmesh_error();
83  }
84 
85 
86  gettimeofday (&tstart, NULL);
87 
88  log.clear();
89 
90  while (!log_stack.empty())
91  log_stack.pop();
92  }
93 }
94 
95 
96 std::string PerfLog::get_info_header() const
97 {
98  std::ostringstream oss;
99 
100  if (log_events)
101  {
102  std::string date = Utility::get_timestamp();
103 
104  // Get system information
105  struct utsname sysInfo;
106  uname(&sysInfo);
107 
108  // Get user information
109  //
110  // Some systems, for example Crays, actually have getpwuid on the head-node
111  // but (if I understand correctly) a dynamically-linked glibc is not available
112  // on the backend, which is running a reduced operating system like Compute
113  // Node Linux. Thus functions like getpwuid cannot be called. This makes
114  // automatically testing for the existence of getpwuid on the login node
115  // difficult. The configure test would work on the login node but will fail
116  // on the backend. Hence we have added a configure flag, --disable-getpwuid,
117  // to manually turn this off.
118 #ifdef LIBMESH_HAVE_GETPWUID
119  struct passwd* p = getpwuid(getuid());
120 #endif
121  oss << "\n";
122 
123  // Construct string stream objects for each of the outputs
124  std::ostringstream
125  pid_stream,
126  nprocs_stream,
127  time_stream,
128  os_stream,
129  host_stream,
130  osrel_stream,
131  osver_stream,
132  machine_stream,
133  user_stream;
134 
135 
136  // Put pointers to these streams in a vector
137  std::vector<std::ostringstream*> v;
138  v.push_back(&pid_stream);
139  v.push_back(&nprocs_stream);
140  v.push_back(&time_stream);
141  v.push_back(&os_stream);
142  v.push_back(&host_stream);
143  v.push_back(&osrel_stream);
144  v.push_back(&osver_stream);
145  v.push_back(&machine_stream);
146  v.push_back(&user_stream);
147 
148  // Fill string stream objects
149  if (libMesh::n_processors() > 1)
150  {
151  pid_stream << "| Processor id: " << libMesh::processor_id();
152  nprocs_stream << "| Num Processors: " << libMesh::n_processors();
153  }
154 
155  time_stream << "| Time: " << date ;
156  os_stream << "| OS: " << sysInfo.sysname ;
157  host_stream << "| HostName: " << sysInfo.nodename ;
158  osrel_stream << "| OS Release: " << sysInfo.release ;
159  osver_stream << "| OS Version: " << sysInfo.version ;
160  machine_stream << "| Machine: " << sysInfo.machine ;
161  user_stream << "| Username: ";
162 #ifdef LIBMESH_HAVE_GETPWUID
163  if (p && p->pw_name)
164  user_stream << p->pw_name;
165  else
166 #endif
167  user_stream << "Unknown";
168 
169  // Parse the LIBMESH_CONFIGURE_INFO string literal before using it in PerfLog output
170  std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
171  std::vector<std::string> parsed_libmesh_configure_info;
172  this->split_on_whitespace(libmesh_configure_info,
173  parsed_libmesh_configure_info);
174 
175  // There should always be at at least one entry in
176  // parsed_libmesh_configure_info, even if the user just ran
177  // ../configure.
178  libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
179 
180  // Find the longest string in all the streams
181  unsigned int max_length = 0;
182  for (unsigned int i=0; i<v.size(); ++i)
183  if (v[i]->str().size() > max_length)
184  max_length = libmesh_cast_int<unsigned int>
185  (v[i]->str().size());
186 
187  // Find the longest string in the parsed_libmesh_configure_info
188  for (unsigned i=0; i<parsed_libmesh_configure_info.size(); ++i)
189  if (parsed_libmesh_configure_info[i].size() > max_length)
190  max_length = libmesh_cast_int<unsigned int>
191  (parsed_libmesh_configure_info[i].size());
192 
193  // Print dashed line for the header
194  oss << ' '
195  << std::string(max_length+1, '-')
196  << '\n';
197 
198  // Loop over all the strings and add end formatting
199  for (unsigned int i=0; i<v.size(); ++i)
200  {
201  if (v[i]->str().size())
202  oss << v[i]->str()
203  << std::setw(max_length + 4 - v[i]->str().size())
204  << std::right
205  << "|\n";
206  }
207 
208  // Print out configuration header plus first parsed string. The
209  // magic number 18 below accounts for the length of the word
210  // 'Configuration'.
211  oss << "| Configuration: "
212  << parsed_libmesh_configure_info[0]
213  << std::setw(max_length + 4 - parsed_libmesh_configure_info[0].size() - 18)
214  << std::right
215  << "|\n";
216 
217  // Loop over the parsed_libmesh_configure_info and add end formatting. The magic
218  // number 3 below accounts for the leading 'pipe' character and indentation
219  for (unsigned i=1; i<parsed_libmesh_configure_info.size(); ++i)
220  {
221  oss << "| "
222  << parsed_libmesh_configure_info[i]
223  << std::setw(max_length + 4 - parsed_libmesh_configure_info[i].size() - 3)
224  << std::right
225  << "|\n";
226  }
227 
228 
229  // Print dashed line
230  oss << ' '
231  << std::string(max_length+1, '-')
232  << '\n';
233  }
234 
235  return oss.str();
236 }
237 
238 
239 
240 
241 std::string PerfLog::get_perf_info() const
242 {
243  std::ostringstream oss;
244 
245  if (log_events && !log.empty())
246  {
247  // Stop timing for this event.
248  struct timeval tstop;
249 
250  gettimeofday (&tstop, NULL);
251 
252  const double elapsed_time = (static_cast<double>(tstop.tv_sec - tstart.tv_sec) +
253  static_cast<double>(tstop.tv_usec - tstart.tv_usec)*1.e-6);
254 
255  // Figure out the formatting required based on the event names
256  // Unsigned ints for each of the column widths
257  unsigned int event_col_width = 30;
258  const unsigned int ncalls_col_width = 11;
259  const unsigned int tot_time_col_width = 12;
260  const unsigned int avg_time_col_width = 12;
261  const unsigned int tot_time_incl_sub_col_width = 12;
262  const unsigned int avg_time_incl_sub_col_width = 12;
263  const unsigned int pct_active_col_width = 9;
264  const unsigned int pct_active_incl_sub_col_width = 9;
265 
266  // Iterator to be used to loop over the map of timed events
267  std::map<std::pair<std::string,std::string>, PerfData>::const_iterator pos;
268 
269  // Reset the event column width based on the longest event name plus
270  // a possible 2-character indentation, plus a space.
271  for (pos = log.begin(); pos != log.end(); ++pos)
272  if (pos->first.second.size()+3 > event_col_width)
273  event_col_width = libmesh_cast_int<unsigned int>
274  (pos->first.second.size()+3);
275 
276  // Set the total width of the column
277  const unsigned int total_col_width =
278  event_col_width +
279  ncalls_col_width +
280  tot_time_col_width +
281  avg_time_col_width +
282  tot_time_incl_sub_col_width +
283  avg_time_incl_sub_col_width +
284  pct_active_col_width+
285  pct_active_incl_sub_col_width+1;
286 
287  // Print dashed line
288  oss << ' '
289  << std::string(total_col_width, '-')
290  << '\n';
291 
292  {
293  // Construct temporary message string
294  std::ostringstream temp;
295  temp << "| " << label_name << " Performance: Alive time=" << elapsed_time
296  << ", Active time=" << total_time;
297 
298  // Get the size of the temporary string
299  const unsigned int temp_size = libmesh_cast_int<unsigned int>
300  (temp.str().size());
301 
302  // Send the temporary message to the output
303  oss << temp.str();
304 
305  // If this string is longer than the previously computed total
306  // column width, skip the additional formatting... this shouldn't
307  // happen often, hopefully. Add two additional characters for a
308  // space and a "|" character at the end.
309  if (temp_size < total_col_width+2)
310  oss << std::setw(total_col_width - temp_size + 2)
311  << std::right
312  << "|";
313 
314  oss << '\n';
315  }
316 
317  // Print dashed line
318  oss << ' '
319  << std::string(total_col_width, '-')
320  << '\n';
321 
322 
323  // Write out the header for the events listing
324  oss << "| "
325  << std::setw(event_col_width)
326  << std::left
327  << "Event"
328  << std::setw(ncalls_col_width)
329  << std::left
330  << "nCalls"
331  << std::setw(tot_time_col_width)
332  << std::left
333  << "Total Time"
334  << std::setw(avg_time_col_width)
335  << std::left
336  << "Avg Time"
337  << std::setw(tot_time_incl_sub_col_width)
338  << std::left
339  << "Total Time"
340  << std::setw(avg_time_incl_sub_col_width)
341  << std::left
342  << "Avg Time"
343  << std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
344  << std::left
345  << "% of Active Time"
346  << "|\n"
347  << "| "
348  << std::setw(event_col_width)
349  << std::left
350  << ""
351  << std::setw(ncalls_col_width)
352  << std::left
353  << ""
354  << std::setw(tot_time_col_width)
355  << std::left
356  << "w/o Sub"
357  << std::setw(avg_time_col_width)
358  << std::left
359  << "w/o Sub"
360  << std::setw(tot_time_incl_sub_col_width)
361  << std::left
362  << "With Sub"
363  << std::setw(avg_time_incl_sub_col_width)
364  << std::left
365  << "With Sub"
366  << std::setw(pct_active_col_width)
367  << std::left
368  << "w/o S"
369  << std::setw(pct_active_incl_sub_col_width)
370  << std::left
371  << "With S"
372  << "|\n|"
373  << std::string(total_col_width, '-')
374  << "|\n|"
375  << std::string(total_col_width, ' ')
376  << "|\n";
377 
378  unsigned int summed_function_calls = 0;
379  double summed_total_time = 0;
380  double summed_percentage = 0;
381 
382  std::string last_header("");
383 
384  for (pos = log.begin(); pos != log.end(); ++pos)
385  {
386  const PerfData& perf_data = pos->second;
387 
388  // Only print the event if the count is non-zero.
389  if (perf_data.count != 0)
390  {
391  const unsigned int perf_count = perf_data.count;
392  const double perf_time = perf_data.tot_time;
393  const double perf_avg_time = perf_time / static_cast<double>(perf_count);
394  const double perf_time_incl_sub = perf_data.tot_time_incl_sub;
395  const double perf_avg_time_incl_sub = perf_time_incl_sub / static_cast<double>(perf_count);
396  const double perf_percent = (total_time != 0.) ? perf_time / total_time * 100. : 0.;
397  const double perf_percent_incl_sub = (total_time != 0.) ? perf_time_incl_sub / total_time * 100. : 0.;
398 
399  summed_function_calls += perf_count;
400  summed_total_time += perf_time;
401  summed_percentage += perf_percent;
402 
403  // Print the event name
404  if (pos->first.first == "")
405  oss << "| "
406  << std::setw(event_col_width)
407  << std::left
408  << pos->first.second;
409 
410  else
411  {
412  if (last_header != pos->first.first)
413  {
414  last_header = pos->first.first;
415 
416  // print blank line followed by header name
417  // (account for additional space before the
418  // header)
419  oss << "|"
420  << std::string(total_col_width, ' ')
421  << "|\n| "
422  << std::setw(total_col_width-1)
423  << std::left
424  << pos->first.first
425  << "|\n";
426  }
427 
428  oss << "| "
429  << std::setw(event_col_width-2)
430  << std::left
431  << pos->first.second;
432  }
433 
434 
435  // Print the number of calls to the event.
436  oss << std::setw(ncalls_col_width)
437  << perf_count;
438 
439  // Save the original stream flags
440  std::ios_base::fmtflags out_flags = oss.flags();
441 
442  // Print the total time spent in the event
443  oss << std::fixed
444  << std::setprecision(4)
445  << std::setw(tot_time_col_width)
446  << std::left
447  << perf_time;
448 
449 
450  // Print the average time per function call
451  oss << std::fixed
452  << std::setprecision(6)
453  << std::setw(avg_time_col_width)
454  << std::left
455  << perf_avg_time;
456 
457  // Print the total time spent in the event incl. sub-events
458  oss << std::fixed
459  << std::setprecision(4)
460  << std::setw(tot_time_incl_sub_col_width)
461  << std::left
462  << perf_time_incl_sub;
463 
464  // Print the average time per function call incl. sub-events
465  oss << std::fixed
466  << std::setprecision(6)
467  << std::setw(avg_time_incl_sub_col_width)
468  << std::left
469  << perf_avg_time_incl_sub;
470 
471  // Print the percentage of the time spent in the event
472  oss << std::fixed
473  << std::setprecision(2)
474  << std::setw(pct_active_col_width)
475  << std::left
476  << perf_percent;
477 
478  // Print the percentage of the time spent in the event incl. sub-events
479  oss << std::fixed
480  << std::setprecision(2)
481  << std::setw(pct_active_incl_sub_col_width)
482  << std::left
483  << perf_percent_incl_sub;
484 
485  // Reset the stream flags
486  oss.flags(out_flags);
487 
488  oss << "|\n";
489  }
490  }
491 
492  oss << ' '
493  << std::string(total_col_width, '-')
494  << "\n| "
495  << std::setw(event_col_width)
496  << std::left
497  << "Totals:";
498 
499  // Print the total number of logged function calls
500  // For routines which are called many times, summed_function_calls may
501  // exceed 7 digits. If this happens use, scientific notation.
502  if (summed_function_calls < 9999999)
503  oss << std::setw(ncalls_col_width)
504  << summed_function_calls;
505 
506  else
507  {
508  // Save the original stream flags
509  std::ios_base::fmtflags out_flags = oss.flags();
510 
511  oss << std::scientific
512  << std::setprecision(3)
513  << std::setw(ncalls_col_width)
514  << std::left
515  << static_cast<Real>(summed_function_calls);
516 
517  // Reset the stream flags
518  oss.flags(out_flags);
519  }
520 
521  // Print the total time spent in logged function calls. Don't bother saving/restoring
522  // the flags here since we are almost done with this stream anyway...
523  oss << std::fixed
524  << std::setprecision(4)
525  << std::setw(tot_time_col_width)
526  << std::left
527  << summed_total_time;
528 
529  // Null, the average time doesn't make sense as a total
530  oss << std::setw(avg_time_col_width) << "";
531 
532  // Same for times that include sub-events
533  oss << std::setw(tot_time_incl_sub_col_width)
534  << ""
535  << std::setw(avg_time_incl_sub_col_width)
536  << "";
537 
538  // Print the total percentage followed by dashed line
539  oss << std::fixed
540  << std::setprecision(2)
541  << std::setw(pct_active_col_width)
542  << std::left
543  << summed_percentage
544  << std::setw(pct_active_incl_sub_col_width)
545  << ""
546  << "|\n "
547  << std::string(total_col_width, '-')
548  << '\n';
549  }
550 
551  return oss.str();
552 }
553 
554 
555 
556 std::string PerfLog::get_log() const
557 {
558  std::ostringstream oss;
559 
560  if (log_events)
561  {
562  // Only print the log
563  // if it isn't empty
564  if (!log.empty())
565  {
566  // Possibly print machine info,
567  // but only do this once
568  if (!called)
569  {
570  called = true;
571  oss << get_info_header();
572  }
573  oss << get_perf_info();
574  }
575  }
576 
577  return oss.str();
578 }
579 
580 
581 
582 void PerfLog::print_log() const
583 {
584  if (log_events)
585  {
586  // Check to see if the log_string is empty, and if so,
587  // avoid printing an unnecessary newline.
588  std::string log_string = this->get_log();
589  if (log_string.size() > 0)
590  libMesh::out << log_string << std::endl;
591  }
592 }
593 
594 PerfData PerfLog::get_perf_data(const std::string &label, const std::string &header)
595 {
596  return log[std::make_pair(header, label)];
597 }
598 
599 void PerfLog::start_event(const std::string &label,
600  const std::string &header)
601 {
602  this->push(label,header);
603 }
604 
605 
606 
607 void PerfLog::stop_event(const std::string &label,
608  const std::string &header)
609 {
610  this->pop(label,header);
611 }
612 
613 
614 
615 void PerfLog::pause_event(const std::string &,
616  const std::string &)
617 {
618  // nothing to do. pushing the next object on the stack will handle it
619 }
620 
621 
622 
623 void PerfLog::restart_event(const std::string &,
624  const std::string &)
625 {
626  // nothing to do. popping the top off the stack will handle it.
627 }
628 
629 
630 
631 void PerfLog::split_on_whitespace(const std::string& input, std::vector<std::string>& output) const
632 {
633  // Check for easy return
634  if (input.size()==0)
635  return;
636 
637  // Here we hard-code the string to split on, since the algorithm below
638  // is somewhat specific to it...
639  const std::string split_on("' '");
640 
641  size_t current_pos = 0;
642  while (true)
643  {
644  // Find next end location
645  size_t end_pos = input.find(split_on, current_pos);
646 
647  if (end_pos != std::string::npos)
648  {
649  // Create substring. Note: the second argument to substr is
650  // the *length* of string to create, not the ending position!
651  output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
652 
653  // Update search starting position, make sure to go past the end of the split_on string, but
654  // include the previous single quote (hence the -1).
655  current_pos = end_pos + split_on.size() - 1;
656  }
657  else
658  {
659  // Push back whatever remains of the string onto the output.
660  // Note that substr with only 1 argument pushes back
661  // whatever remains of the string. This also handles the
662  // case where the string does not contain any matches.
663  output.push_back( input.substr(current_pos) );
664 
665  // We are done searching the string, so break out of the while loop
666  break;
667  }
668  }
669 }
670 
671 } // namespace libMesh

Site Created By: libMesh Developers
Last modified: February 07 2014 16:57:06 UTC

Hosted By:
SourceForge.net Logo