$extrastylesheet
#include <perf_log.h>
Public Member Functions | |
| PerfLog (const std::string &label_name="", const bool log_events=true) | |
| ~PerfLog () | |
| void | clear () |
| void | disable_logging () |
| void | enable_logging () |
| bool | logging_enabled () const |
| void | push (const char *label, const char *header="") |
| void | push (const std::string &label, const std::string &header="") |
| void | pop (const char *label, const char *header="") |
| void | pop (const std::string &label, const std::string &header="") |
| void | start_event (const std::string &label, const std::string &header="") |
| void | stop_event (const std::string &label, const std::string &header="") |
| void | pause_event (const std::string &label, const std::string &header="") |
| void | restart_event (const std::string &label, const std::string &header="") |
| std::string | get_log () const |
| std::string | get_info_header () const |
| std::string | get_perf_info () const |
| void | print_log () const |
| double | get_elapsed_time () const |
| double | get_active_time () const |
| PerfData | get_perf_data (const std::string &label, const std::string &header="") |
Private Member Functions | |
| void | split_on_whitespace (const std::string &input, std::vector< std::string > &output) const |
Private Attributes | |
| const std::string | label_name |
| bool | log_events |
| double | total_time |
| struct timeval | tstart |
| std::map< std::pair < std::string, std::string > , PerfData > | log |
| std::stack< PerfData * > | log_stack |
Static Private Attributes | |
| static bool | called = false |
The PerfLog class allows monitoring of specific events. An event is defined by a unique string that functions as a label. Each time the event is executed data are recorded. This class is particulary useful for finding performance bottlenecks.
Definition at line 123 of file perf_log.h.
| libMesh::PerfLog::PerfLog | ( | const std::string & | label_name = "", |
| const bool | log_events = true |
||
| ) |
Constructor. label_name is the name of the object, which will bw print in the log to distinguish it from other objects. log_events is a flag to optionally disable logging. You can use this flag to turn off logging without touching any other code.
Definition at line 45 of file perf_log.C.
References clear(), log_events, and tstart.
: label_name(ln), log_events(le), total_time(0.) { gettimeofday (&tstart, NULL); if (log_events) this->clear(); }
Destructor. Calls clear() and print_log().
Definition at line 59 of file perf_log.C.
References log_events, and print_log().
{
if (log_events)
this->print_log();
}
| void libMesh::PerfLog::clear | ( | ) |
Clears all the internal data and returns the data structures to a pristine state. This function checks to see if it is currently monitoring any events, and if so errors. Be sure you are not logging any events when you call this function.
Definition at line 67 of file perf_log.C.
References label_name, log, log_events, log_stack, and tstart.
Referenced by libMesh::libmesh_terminate_handler(), PerfLog(), and libMesh::LibMeshInit::~LibMeshInit().
{
if (log_events)
{
// check that all events are closed
for (std::map<std::pair<std::string,std::string>, PerfData>::iterator
pos = log.begin(); pos != log.end(); ++pos)
if (pos->second.open)
libmesh_error_msg("ERROR clearning performance log for class " \
<< label_name \
<< "\nevent " \
<< pos->first.second \
<< " is still being monitored!");
gettimeofday (&tstart, NULL);
log.clear();
while (!log_stack.empty())
log_stack.pop();
}
}
| void libMesh::PerfLog::disable_logging | ( | ) | [inline] |
Disables performance logging for an active object.
Definition at line 155 of file perf_log.h.
References log_events.
Referenced by libMesh::LibMeshInit::LibMeshInit(), libMesh::Threads::parallel_for(), and libMesh::Threads::parallel_reduce().
{ log_events = false; }
| void libMesh::PerfLog::enable_logging | ( | ) | [inline] |
Enables performance logging for an active object.
Definition at line 160 of file perf_log.h.
References log_events.
Referenced by libMesh::Threads::parallel_for(), and libMesh::Threads::parallel_reduce().
{ log_events = true; }
| double libMesh::PerfLog::get_active_time | ( | ) | const [inline] |
Definition at line 464 of file perf_log.h.
References total_time.
{
return total_time;
}
| double libMesh::PerfLog::get_elapsed_time | ( | ) | const [inline] |
Definition at line 452 of file perf_log.h.
References tstart.
| std::string libMesh::PerfLog::get_info_header | ( | ) | const |
Definition at line 91 of file perf_log.C.
References libMesh::Utility::get_timestamp(), libMesh::global_n_processors(), libMesh::global_processor_id(), log_events, and split_on_whitespace().
Referenced by get_log().
{
std::ostringstream oss;
if (log_events)
{
std::string date = Utility::get_timestamp();
// Get system information
struct utsname sysInfo;
uname(&sysInfo);
// Get user information
//
// Some systems, for example Crays, actually have getpwuid on the head-node
// but (if I understand correctly) a dynamically-linked glibc is not available
// on the backend, which is running a reduced operating system like Compute
// Node Linux. Thus functions like getpwuid cannot be called. This makes
// automatically testing for the existence of getpwuid on the login node
// difficult. The configure test would work on the login node but will fail
// on the backend. Hence we have added a configure flag, --disable-getpwuid,
// to manually turn this off.
#ifdef LIBMESH_HAVE_GETPWUID
struct passwd* p = getpwuid(getuid());
#endif
oss << "\n";
// Construct string stream objects for each of the outputs
std::ostringstream
pid_stream,
nprocs_stream,
time_stream,
os_stream,
host_stream,
osrel_stream,
osver_stream,
machine_stream,
user_stream;
// Put pointers to these streams in a vector
std::vector<std::ostringstream*> v;
v.push_back(&pid_stream);
v.push_back(&nprocs_stream);
v.push_back(&time_stream);
v.push_back(&os_stream);
v.push_back(&host_stream);
v.push_back(&osrel_stream);
v.push_back(&osver_stream);
v.push_back(&machine_stream);
v.push_back(&user_stream);
// Fill string stream objects
if (libMesh::global_n_processors() > 1)
{
pid_stream << "| Processor id: " << libMesh::global_processor_id();
nprocs_stream << "| Num Processors: " << libMesh::global_n_processors();
}
time_stream << "| Time: " << date ;
os_stream << "| OS: " << sysInfo.sysname ;
host_stream << "| HostName: " << sysInfo.nodename ;
osrel_stream << "| OS Release: " << sysInfo.release ;
osver_stream << "| OS Version: " << sysInfo.version ;
machine_stream << "| Machine: " << sysInfo.machine ;
user_stream << "| Username: ";
#ifdef LIBMESH_HAVE_GETPWUID
if (p && p->pw_name)
user_stream << p->pw_name;
else
#endif
user_stream << "Unknown";
// Parse the LIBMESH_CONFIGURE_INFO string literal before using it in PerfLog output
std::string libmesh_configure_info(LIBMESH_CONFIGURE_INFO);
std::vector<std::string> parsed_libmesh_configure_info;
this->split_on_whitespace(libmesh_configure_info,
parsed_libmesh_configure_info);
// There should always be at at least one entry in
// parsed_libmesh_configure_info, even if the user just ran
// ../configure.
libmesh_assert_greater (parsed_libmesh_configure_info.size(), 0);
// Find the longest string in all the streams
unsigned int max_length = 0;
for (unsigned int i=0; i<v.size(); ++i)
if (v[i]->str().size() > max_length)
max_length = cast_int<unsigned int>
(v[i]->str().size());
// Find the longest string in the parsed_libmesh_configure_info
for (unsigned i=0; i<parsed_libmesh_configure_info.size(); ++i)
if (parsed_libmesh_configure_info[i].size() > max_length)
max_length = cast_int<unsigned int>
(parsed_libmesh_configure_info[i].size());
// Print dashed line for the header
oss << ' '
<< std::string(max_length+1, '-')
<< '\n';
// Loop over all the strings and add end formatting
for (unsigned int i=0; i<v.size(); ++i)
{
if (v[i]->str().size())
oss << v[i]->str()
<< std::setw (cast_int<int>
(max_length + 4 - v[i]->str().size()))
<< std::right
<< "|\n";
}
// Print out configuration header plus first parsed string. The
// magic number 18 below accounts for the length of the word
// 'Configuration'.
oss << "| Configuration: "
<< parsed_libmesh_configure_info[0]
<< std::setw (cast_int<int>
(max_length + 4 -
parsed_libmesh_configure_info[0].size() - 18))
<< std::right
<< "|\n";
// Loop over the parsed_libmesh_configure_info and add end formatting. The magic
// number 3 below accounts for the leading 'pipe' character and indentation
for (unsigned i=1; i<parsed_libmesh_configure_info.size(); ++i)
{
oss << "| "
<< parsed_libmesh_configure_info[i]
<< std::setw (cast_int<int>
(max_length + 4 -
parsed_libmesh_configure_info[i].size() - 3))
<< std::right
<< "|\n";
}
// Print dashed line
oss << ' '
<< std::string(max_length+1, '-')
<< '\n';
}
return oss.str();
}
| std::string libMesh::PerfLog::get_log | ( | ) | const |
Definition at line 556 of file perf_log.C.
References called, get_info_header(), get_perf_info(), log, and log_events.
Referenced by print_log().
{
std::ostringstream oss;
if (log_events)
{
// Only print the log
// if it isn't empty
if (!log.empty())
{
// Possibly print machine info,
// but only do this once
if (!called)
{
called = true;
oss << get_info_header();
}
oss << get_perf_info();
}
}
return oss.str();
}
| PerfData libMesh::PerfLog::get_perf_data | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Return the PerfData object associated with a label and header.
Definition at line 594 of file perf_log.C.
References log.
{
return log[std::make_pair(header, label)];
}
| std::string libMesh::PerfLog::get_perf_info | ( | ) | const |
Definition at line 241 of file perf_log.C.
References libMesh::PerfData::count, label_name, log, log_events, libMesh::Real, libMesh::PerfData::tot_time, libMesh::PerfData::tot_time_incl_sub, total_time, and tstart.
Referenced by get_log().
{
std::ostringstream oss;
if (log_events && !log.empty())
{
// Stop timing for this event.
struct timeval tstop;
gettimeofday (&tstop, NULL);
const double elapsed_time = (static_cast<double>(tstop.tv_sec - tstart.tv_sec) +
static_cast<double>(tstop.tv_usec - tstart.tv_usec)*1.e-6);
// Figure out the formatting required based on the event names
// Unsigned ints for each of the column widths
unsigned int event_col_width = 30;
const unsigned int ncalls_col_width = 11;
const unsigned int tot_time_col_width = 12;
const unsigned int avg_time_col_width = 12;
const unsigned int tot_time_incl_sub_col_width = 12;
const unsigned int avg_time_incl_sub_col_width = 12;
const unsigned int pct_active_col_width = 9;
const unsigned int pct_active_incl_sub_col_width = 9;
// Iterator to be used to loop over the map of timed events
std::map<std::pair<std::string,std::string>, PerfData>::const_iterator pos;
// Reset the event column width based on the longest event name plus
// a possible 2-character indentation, plus a space.
for (pos = log.begin(); pos != log.end(); ++pos)
if (pos->first.second.size()+3 > event_col_width)
event_col_width = cast_int<unsigned int>
(pos->first.second.size()+3);
// Set the total width of the column
const unsigned int total_col_width =
event_col_width +
ncalls_col_width +
tot_time_col_width +
avg_time_col_width +
tot_time_incl_sub_col_width +
avg_time_incl_sub_col_width +
pct_active_col_width+
pct_active_incl_sub_col_width+1;
// Print dashed line
oss << ' '
<< std::string(total_col_width, '-')
<< '\n';
{
// Construct temporary message string
std::ostringstream temp;
temp << "| " << label_name << " Performance: Alive time=" << elapsed_time
<< ", Active time=" << total_time;
// Get the size of the temporary string
const unsigned int temp_size = cast_int<unsigned int>
(temp.str().size());
// Send the temporary message to the output
oss << temp.str();
// If this string is longer than the previously computed total
// column width, skip the additional formatting... this shouldn't
// happen often, hopefully. Add two additional characters for a
// space and a "|" character at the end.
if (temp_size < total_col_width+2)
oss << std::setw(total_col_width - temp_size + 2)
<< std::right
<< "|";
oss << '\n';
}
// Print dashed line
oss << ' '
<< std::string(total_col_width, '-')
<< '\n';
// Write out the header for the events listing
oss << "| "
<< std::setw(event_col_width)
<< std::left
<< "Event"
<< std::setw(ncalls_col_width)
<< std::left
<< "nCalls"
<< std::setw(tot_time_col_width)
<< std::left
<< "Total Time"
<< std::setw(avg_time_col_width)
<< std::left
<< "Avg Time"
<< std::setw(tot_time_incl_sub_col_width)
<< std::left
<< "Total Time"
<< std::setw(avg_time_incl_sub_col_width)
<< std::left
<< "Avg Time"
<< std::setw(pct_active_col_width+pct_active_incl_sub_col_width)
<< std::left
<< "% of Active Time"
<< "|\n"
<< "| "
<< std::setw(event_col_width)
<< std::left
<< ""
<< std::setw(ncalls_col_width)
<< std::left
<< ""
<< std::setw(tot_time_col_width)
<< std::left
<< "w/o Sub"
<< std::setw(avg_time_col_width)
<< std::left
<< "w/o Sub"
<< std::setw(tot_time_incl_sub_col_width)
<< std::left
<< "With Sub"
<< std::setw(avg_time_incl_sub_col_width)
<< std::left
<< "With Sub"
<< std::setw(pct_active_col_width)
<< std::left
<< "w/o S"
<< std::setw(pct_active_incl_sub_col_width)
<< std::left
<< "With S"
<< "|\n|"
<< std::string(total_col_width, '-')
<< "|\n|"
<< std::string(total_col_width, ' ')
<< "|\n";
unsigned int summed_function_calls = 0;
double summed_total_time = 0;
double summed_percentage = 0;
std::string last_header("");
for (pos = log.begin(); pos != log.end(); ++pos)
{
const PerfData& perf_data = pos->second;
// Only print the event if the count is non-zero.
if (perf_data.count != 0)
{
const unsigned int perf_count = perf_data.count;
const double perf_time = perf_data.tot_time;
const double perf_avg_time = perf_time / static_cast<double>(perf_count);
const double perf_time_incl_sub = perf_data.tot_time_incl_sub;
const double perf_avg_time_incl_sub = perf_time_incl_sub / static_cast<double>(perf_count);
const double perf_percent = (total_time != 0.) ? perf_time / total_time * 100. : 0.;
const double perf_percent_incl_sub = (total_time != 0.) ? perf_time_incl_sub / total_time * 100. : 0.;
summed_function_calls += perf_count;
summed_total_time += perf_time;
summed_percentage += perf_percent;
// Print the event name
if (pos->first.first == "")
oss << "| "
<< std::setw(event_col_width)
<< std::left
<< pos->first.second;
else
{
if (last_header != pos->first.first)
{
last_header = pos->first.first;
// print blank line followed by header name
// (account for additional space before the
// header)
oss << "|"
<< std::string(total_col_width, ' ')
<< "|\n| "
<< std::setw(total_col_width-1)
<< std::left
<< pos->first.first
<< "|\n";
}
oss << "| "
<< std::setw(event_col_width-2)
<< std::left
<< pos->first.second;
}
// Print the number of calls to the event.
oss << std::setw(ncalls_col_width)
<< perf_count;
// Save the original stream flags
std::ios_base::fmtflags out_flags = oss.flags();
// Print the total time spent in the event
oss << std::fixed
<< std::setprecision(4)
<< std::setw(tot_time_col_width)
<< std::left
<< perf_time;
// Print the average time per function call
oss << std::fixed
<< std::setprecision(6)
<< std::setw(avg_time_col_width)
<< std::left
<< perf_avg_time;
// Print the total time spent in the event incl. sub-events
oss << std::fixed
<< std::setprecision(4)
<< std::setw(tot_time_incl_sub_col_width)
<< std::left
<< perf_time_incl_sub;
// Print the average time per function call incl. sub-events
oss << std::fixed
<< std::setprecision(6)
<< std::setw(avg_time_incl_sub_col_width)
<< std::left
<< perf_avg_time_incl_sub;
// Print the percentage of the time spent in the event
oss << std::fixed
<< std::setprecision(2)
<< std::setw(pct_active_col_width)
<< std::left
<< perf_percent;
// Print the percentage of the time spent in the event incl. sub-events
oss << std::fixed
<< std::setprecision(2)
<< std::setw(pct_active_incl_sub_col_width)
<< std::left
<< perf_percent_incl_sub;
// Reset the stream flags
oss.flags(out_flags);
oss << "|\n";
}
}
oss << ' '
<< std::string(total_col_width, '-')
<< "\n| "
<< std::setw(event_col_width)
<< std::left
<< "Totals:";
// Print the total number of logged function calls
// For routines which are called many times, summed_function_calls may
// exceed 7 digits. If this happens use, scientific notation.
if (summed_function_calls < 9999999)
oss << std::setw(ncalls_col_width)
<< summed_function_calls;
else
{
// Save the original stream flags
std::ios_base::fmtflags out_flags = oss.flags();
oss << std::scientific
<< std::setprecision(3)
<< std::setw(ncalls_col_width)
<< std::left
<< static_cast<Real>(summed_function_calls);
// Reset the stream flags
oss.flags(out_flags);
}
// Print the total time spent in logged function calls. Don't bother saving/restoring
// the flags here since we are almost done with this stream anyway...
oss << std::fixed
<< std::setprecision(4)
<< std::setw(tot_time_col_width)
<< std::left
<< summed_total_time;
// Null, the average time doesn't make sense as a total
oss << std::setw(avg_time_col_width) << "";
// Same for times that include sub-events
oss << std::setw(tot_time_incl_sub_col_width)
<< ""
<< std::setw(avg_time_incl_sub_col_width)
<< "";
// Print the total percentage followed by dashed line
oss << std::fixed
<< std::setprecision(2)
<< std::setw(pct_active_col_width)
<< std::left
<< summed_percentage
<< std::setw(pct_active_incl_sub_col_width)
<< ""
<< "|\n "
<< std::string(total_col_width, '-')
<< '\n';
}
return oss.str();
}
| bool libMesh::PerfLog::logging_enabled | ( | ) | const [inline] |
Returns true iff performance logging is enabled
Definition at line 165 of file perf_log.h.
References log_events.
Referenced by libMesh::Threads::parallel_for(), and libMesh::Threads::parallel_reduce().
{ return log_events; }
| void libMesh::PerfLog::pause_event | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Suspend monitoring of the event.
Definition at line 615 of file perf_log.C.
{
// nothing to do. pushing the next object on the stack will handle it
}
| void libMesh::PerfLog::pop | ( | const char * | label, |
| const char * | header = "" |
||
| ) | [inline] |
Pop the event label off the stack, resuming any lower event.
Definition at line 442 of file perf_log.h.
References log_events.
Referenced by stop_event().
{
if (this->log_events)
this->pop(std::string(label), std::string(header));
}
| void libMesh::PerfLog::pop | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Pop the event label off the stack, resuming any lower event.
| void libMesh::PerfLog::print_log | ( | ) | const |
Print the log.
Definition at line 582 of file perf_log.C.
References get_log(), log_events, and libMesh::out.
Referenced by libMesh::libmesh_terminate_handler(), libMesh::LibMeshInit::~LibMeshInit(), and ~PerfLog().
{
if (log_events)
{
// Check to see if the log_string is empty, and if so,
// avoid printing an unnecessary newline.
std::string log_string = this->get_log();
if (log_string.size() > 0)
libMesh::out << log_string << std::endl;
}
}
| void libMesh::PerfLog::push | ( | const char * | label, |
| const char * | header = "" |
||
| ) | [inline] |
Push the event label onto the stack, pausing any active event.
Definition at line 397 of file perf_log.h.
References log_events.
Referenced by start_event().
{
if (this->log_events)
this->push(std::string(label), std::string(header));
}
| void libMesh::PerfLog::push | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) | [inline] |
Push the event label onto the stack, pausing any active event.
Definition at line 376 of file perf_log.h.
References log, log_events, log_stack, libMesh::PerfData::start(), and total_time.
{
if (this->log_events)
{
// Get a reference to the event data to avoid
// repeated map lookups
PerfData *perf_data = &(log[std::make_pair(header,label)]);
if (!log_stack.empty())
total_time +=
log_stack.top()->pause();
perf_data->start();
log_stack.push(perf_data);
}
}
| void libMesh::PerfLog::restart_event | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Restart monitoring the event.
Definition at line 623 of file perf_log.C.
{
// nothing to do. popping the top off the stack will handle it.
}
| void libMesh::PerfLog::split_on_whitespace | ( | const std::string & | input, |
| std::vector< std::string > & | output | ||
| ) | const [private] |
Splits a string on whitespace into a vector of separate strings. This is used to make the LIBMESH_CONFIGURE_INFO a little more manageable.
Definition at line 631 of file perf_log.C.
Referenced by get_info_header().
{
// Check for easy return
if (input.size()==0)
return;
// Here we hard-code the string to split on, since the algorithm below
// is somewhat specific to it...
const std::string split_on("' '");
size_t current_pos = 0;
while (true)
{
// Find next end location
size_t end_pos = input.find(split_on, current_pos);
if (end_pos != std::string::npos)
{
// Create substring. Note: the second argument to substr is
// the *length* of string to create, not the ending position!
output.push_back( input.substr(current_pos, end_pos - current_pos + 1) );
// Update search starting position, make sure to go past the end of the split_on string, but
// include the previous single quote (hence the -1).
current_pos = end_pos + split_on.size() - 1;
}
else
{
// Push back whatever remains of the string onto the output.
// Note that substr with only 1 argument pushes back
// whatever remains of the string. This also handles the
// case where the string does not contain any matches.
output.push_back( input.substr(current_pos) );
// We are done searching the string, so break out of the while loop
break;
}
}
}
| void libMesh::PerfLog::start_event | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Start monitoring the event named label.
Definition at line 599 of file perf_log.C.
References push().
{
this->push(label,header);
}
| void libMesh::PerfLog::stop_event | ( | const std::string & | label, |
| const std::string & | header = "" |
||
| ) |
Stop monitoring the event named label.
Definition at line 607 of file perf_log.C.
References pop().
{
this->pop(label,header);
}
bool libMesh::PerfLog::called = false [static, private] |
Flag indicating if print_log() has been called. This is used to print a header with machine-specific data the first time that print_log() is called.
Definition at line 292 of file perf_log.h.
Referenced by get_log().
const std::string libMesh::PerfLog::label_name [private] |
The label for this object.
Definition at line 258 of file perf_log.h.
Referenced by clear(), and get_perf_info().
std::map<std::pair<std::string, std::string>, PerfData> libMesh::PerfLog::log [private] |
The actual log.
Definition at line 280 of file perf_log.h.
Referenced by clear(), get_log(), get_perf_data(), get_perf_info(), and push().
bool libMesh::PerfLog::log_events [private] |
Flag to optionally disable all logging.
Definition at line 263 of file perf_log.h.
Referenced by clear(), disable_logging(), enable_logging(), get_info_header(), get_log(), get_perf_info(), logging_enabled(), PerfLog(), pop(), print_log(), push(), and ~PerfLog().
std::stack<PerfData*> libMesh::PerfLog::log_stack [private] |
A stack to hold the current performance log trace.
Definition at line 285 of file perf_log.h.
double libMesh::PerfLog::total_time [private] |
The total running time for recorded events.
Definition at line 268 of file perf_log.h.
Referenced by get_active_time(), get_perf_info(), and push().
struct timeval libMesh::PerfLog::tstart [private] |
The time we were constructed or last cleared.
Definition at line 273 of file perf_log.h.
Referenced by clear(), get_elapsed_time(), get_perf_info(), and PerfLog().