18 #include "libmesh/perf_log.h" 21 #include "libmesh/int_range.h" 22 #include "libmesh/timestamp.h" 30 #ifdef LIBMESH_HAVE_UNISTD_H 33 #include <sys/types.h> 37 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H 38 #include <sys/utsname.h> 41 #ifdef LIBMESH_HAVE_PWD_H 57 label_name(
std::move(ln)),
59 summarize_logs(false),
84 libmesh_error_msg_if(pos.second.open,
85 "ERROR clearing performance log for class " 89 <<
" is still being monitored!");
103 const std::string & header)
105 const char * label_c_str;
106 const char * header_c_str;
110 label_c_str = label_it->second.get();
113 const std::size_t labelsizep1 = label.size()+1;
114 auto newcopy = std::make_unique<char[]>(labelsizep1);
115 std::strncpy(newcopy.get(), label.c_str(), labelsizep1);
116 label_c_str = newcopy.get();
122 header_c_str = header_it->second.get();
125 const std::size_t headersizep1 = header.size()+1;
126 auto newcopy = std::make_unique<char[]>(headersizep1);
127 std::strncpy(newcopy.get(), header.c_str(), headersizep1);
128 header_c_str = newcopy.get();
133 this->
fast_push(label_c_str, header_c_str);
141 this->
push(std::string(label), std::string(header));
149 const std::string & header)
163 this->
fast_pop(label_c_str, header_c_str);
171 this->
pop(std::string(label), std::string(header));
178 std::ostringstream oss;
184 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H 186 struct utsname sysInfo;
200 #ifdef LIBMESH_HAVE_GETPWUID 201 struct passwd * p = getpwuid(getuid());
219 std::vector<std::ostringstream*> v;
220 v.push_back(&pid_stream);
221 v.push_back(&nprocs_stream);
222 v.push_back(&time_stream);
223 v.push_back(&os_stream);
224 v.push_back(&host_stream);
225 v.push_back(&osrel_stream);
226 v.push_back(&osver_stream);
227 v.push_back(&machine_stream);
228 v.push_back(&user_stream);
237 time_stream <<
"| Time: ";
238 os_stream <<
"| OS: ";
239 host_stream <<
"| HostName: ";
240 osrel_stream <<
"| OS Release: ";
241 osver_stream <<
"| OS Version: ";
242 machine_stream <<
"| Machine: ";
245 #ifdef LIBMESH_HAVE_SYS_UTSNAME_H 246 os_stream << sysInfo.sysname ;
247 host_stream << sysInfo.nodename ;
248 osrel_stream << sysInfo.release ;
249 osver_stream << sysInfo.version ;
250 machine_stream << sysInfo.machine ;
252 os_stream <<
"Unknown";
253 host_stream <<
"Unknown";
254 osrel_stream <<
"Unknown";
255 osver_stream <<
"Unknown";
256 machine_stream <<
"Unknown";
259 user_stream <<
"| Username: ";
260 #ifdef LIBMESH_HAVE_GETPWUID 262 user_stream << p->pw_name;
265 user_stream <<
"Unknown";
268 std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
269 std::vector<std::string> parsed_libmesh_configure_info;
271 parsed_libmesh_configure_info);
276 libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
279 unsigned int max_length = 0;
281 if (v_i->str().size() > max_length)
282 max_length = cast_int<unsigned int>
286 for (
auto & plci_i : parsed_libmesh_configure_info)
287 if (plci_i.size() > max_length)
288 max_length = cast_int<unsigned int> (plci_i.size());
292 << std::string(max_length+1,
'-')
298 if (v_i->str().size())
300 << std::setw (cast_int<int>
301 (max_length + 4 - v_i->str().size()))
309 oss <<
"| Configuration: " 310 << parsed_libmesh_configure_info[0]
311 << std::setw (cast_int<int>
313 parsed_libmesh_configure_info[0].size() - 18))
322 << parsed_libmesh_configure_info[i]
323 << std::setw (cast_int<int>
325 parsed_libmesh_configure_info[i].size() - 3))
333 << std::string(max_length+1,
'-')
345 std::ostringstream oss;
360 unsigned int event_col_width = 30;
361 const unsigned int ncalls_col_width = 11;
362 const unsigned int tot_time_col_width = 12;
363 const unsigned int avg_time_col_width = 12;
364 const unsigned int tot_time_incl_sub_col_width = 12;
365 const unsigned int avg_time_incl_sub_col_width = 12;
366 const unsigned int pct_active_col_width = 9;
367 const unsigned int pct_active_incl_sub_col_width = 9;
372 if (std::strlen(pos.first.second)+3 > event_col_width)
373 event_col_width = cast_int<unsigned int>
374 (std::strlen(pos.first.second)+3);
377 const unsigned int total_col_width =
382 tot_time_incl_sub_col_width +
383 avg_time_incl_sub_col_width +
384 pct_active_col_width+
385 pct_active_incl_sub_col_width+1;
389 << std::string(total_col_width,
'-')
394 std::ostringstream temp;
395 temp <<
"| " <<
label_name <<
" Performance: Alive time=" << elapsed_time
399 const unsigned int temp_size = cast_int<unsigned int>
409 if (temp_size < total_col_width+2)
410 oss << std::setw(total_col_width - temp_size + 2)
419 << std::string(total_col_width,
'-')
425 << std::setw(event_col_width)
428 << std::setw(ncalls_col_width)
431 << std::setw(tot_time_col_width)
434 << std::setw(avg_time_col_width)
437 << std::setw(tot_time_incl_sub_col_width)
440 << std::setw(avg_time_incl_sub_col_width)
443 << std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
445 <<
"% of Active Time" 448 << std::setw(event_col_width)
451 << std::setw(ncalls_col_width)
454 << std::setw(tot_time_col_width)
457 << std::setw(avg_time_col_width)
460 << std::setw(tot_time_incl_sub_col_width)
463 << std::setw(avg_time_incl_sub_col_width)
466 << std::setw(pct_active_col_width)
469 << std::setw(pct_active_incl_sub_col_width)
473 << std::string(total_col_width,
'-')
475 << std::string(total_col_width,
' ')
478 unsigned int summed_function_calls = 0;
479 double summed_total_time = 0;
480 double summed_percentage = 0;
482 std::string last_header(
"");
485 std::map<std::pair<std::string, std::string>,
PerfData> string_log;
487 for (
auto char_data :
log)
490 string_log[std::make_pair(std::string(), char_data.first.first)] +=
495 string_log[std::make_pair(char_data.first.first,
496 char_data.first.second)] =
500 for (
auto pos : string_log)
502 const PerfData & perf_data = pos.second;
505 if (perf_data.
count != 0)
507 const unsigned int perf_count = perf_data.
count;
508 const double perf_time = perf_data.
tot_time;
509 const double perf_avg_time = perf_time /
static_cast<double>(perf_count);
511 const double perf_avg_time_incl_sub = perf_time_incl_sub /
static_cast<double>(perf_count);
513 const double perf_percent_incl_sub = (
total_time != 0.) ? perf_time_incl_sub /
total_time * 100. : 0.;
515 summed_function_calls += perf_count;
516 summed_total_time += perf_time;
517 summed_percentage += perf_percent;
520 if (pos.first.first ==
"")
522 << std::setw(event_col_width)
528 if (last_header != pos.first.first)
530 last_header = pos.first.first;
536 << std::string(total_col_width,
' ')
538 << std::setw(total_col_width-1)
545 << std::setw(event_col_width-2)
552 oss << std::setw(ncalls_col_width)
556 std::ios_base::fmtflags out_flags = oss.flags();
560 << std::setprecision(4)
561 << std::setw(tot_time_col_width)
568 << std::setprecision(6)
569 << std::setw(avg_time_col_width)
575 << std::setprecision(4)
576 << std::setw(tot_time_incl_sub_col_width)
578 << perf_time_incl_sub;
582 << std::setprecision(6)
583 << std::setw(avg_time_incl_sub_col_width)
585 << perf_avg_time_incl_sub;
589 << std::setprecision(2)
590 << std::setw(pct_active_col_width)
596 << std::setprecision(2)
597 << std::setw(pct_active_incl_sub_col_width)
599 << perf_percent_incl_sub;
602 oss.flags(out_flags);
609 << std::string(total_col_width,
'-')
611 << std::setw(event_col_width)
618 if (summed_function_calls < 9999999)
619 oss << std::setw(ncalls_col_width)
620 << summed_function_calls;
625 std::ios_base::fmtflags out_flags = oss.flags();
627 oss << std::scientific
628 << std::setprecision(3)
629 << std::setw(ncalls_col_width)
631 <<
static_cast<Real>(summed_function_calls);
634 oss.flags(out_flags);
640 << std::setprecision(4)
641 << std::setw(tot_time_col_width)
643 << summed_total_time;
646 oss << std::setw(avg_time_col_width) <<
"";
649 oss << std::setw(tot_time_incl_sub_col_width)
651 << std::setw(avg_time_incl_sub_col_width)
656 << std::setprecision(2)
657 << std::setw(pct_active_col_width)
660 << std::setw(pct_active_incl_sub_col_width)
663 << std::string(total_col_width,
'-')
673 std::ostringstream oss;
703 std::string log_string = this->
get_log();
704 if (log_string.size() > 0)
716 return log[std::make_pair(header_c_str, label_c_str)];
719 auto iter = std::find_if
721 [&label, &header] (log_type::const_reference a)
724 !std::strcmp(header.c_str(), a.first.first) &&
725 !std::strcmp(label.c_str(), a.first.second);
734 const std::string & header)
736 this->
push(label,header);
742 const std::string & header)
744 this->
pop(label,header);
773 const std::string split_on(
"' '");
775 size_t current_pos = 0;
779 if (
size_t end_pos = input.find(split_on, current_pos);
780 end_pos != std::string::npos)
784 output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
788 current_pos = end_pos + split_on.size() - 1;
796 output.push_back( input.substr(current_pos) );
double tot_time_incl_sub
Total time spent in this event, including sub-events.
void pop(const char *label, const char *header="")
Pop the event label off the stack, resuming any lower event.
PerfLog(std::string label_name="", const bool log_events=true)
Constructor.
processor_id_type global_n_processors()
void fast_push(const char *label, const char *header="")
Push the event label onto the stack, pausing any active event.
The IntRange templated class is intended to make it easy to loop over integers which are indices of a...
std::string get_timestamp()
The PerfData class simply contains the performance data that is recorded for individual events...
bool log_events
Flag to optionally disable all logging.
int gettimeofday(struct timeval *tp, struct timezone *tzp)
double total_time
The total running time for recorded events.
void stop_event(const std::string &label, const std::string &header="")
Stop monitoring the event named label.
log_type log
The actual log.
The libMesh namespace provides an interface to certain functionality in the library.
void fast_pop(const char *label, const char *header="") noexcept
Pop the event label off the stack, resuming any lower event.
std::stack< PerfData * > log_stack
A stack to hold the current performance log trace.
bool summarize_logs
Flag to optionally summarize logs.
PerfData get_perf_data(const std::string &label, const std::string &header="")
Return the PerfData object associated with a label and header.
std::string get_perf_info() const
const std::string label_name
The label for this object.
std::string get_log() const
std::string get_info_header() const
void push(const char *label, const char *header="")
Push the event label onto the stack, pausing any active event.
void restart_event(const std::string &label, const std::string &header="")
Restart monitoring the event.
void split_on_whitespace(const std::string &input, std::vector< std::string > &output) const
Splits a string on whitespace into a vector of separate strings.
void clear()
Clears all the internal data and restores the data structures to a pristine state.
double tot_time
Total time spent in this event.
DIE A HORRIBLE DEATH HERE typedef LIBMESH_DEFAULT_SCALAR_TYPE Real
processor_id_type global_processor_id()
void print_log() const
Print the log.
void pause_event(const std::string &label, const std::string &header="")
Suspend monitoring of the event.
unsigned int count
The number of times this event has been executed.
struct timeval tstart
The time we were constructed or last cleared.
static bool called
Flag indicating if print_log() has been called.
std::map< std::string, std::unique_ptr< const char[]> > non_temporary_strings
Workaround to give us fixed pointers to character arrays for every string.
void start_event(const std::string &label, const std::string &header="")
Start monitoring the event named label.