libMesh::PerfLog Class Reference

#include <perf_log.h>

List of all members.

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 std::string &label, const std::string &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
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

---

Detailed Description

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.

---

Constructor & Destructor Documentation

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();
}

libMesh::PerfLog::~PerfLog

(

)

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();
}

---

Member Function Documentation

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, libMesh::out, and tstart.

Referenced by PerfLog().

{
  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::out
              << "ERROR clearning performance log for class "
              << label_name << std::endl
              << "event " << pos->first.second << " is still being monitored!"
              << std::endl;

            libmesh_error();
          }


      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.

{ 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.

{ log_events = true; }

double libMesh::PerfLog::get_elapsed_time

(

)

const [inline]

Returns:

the total time spent on this event.

Definition at line 411 of file perf_log.h.

References tstart.

{
  struct timeval tnow;

  gettimeofday (&tnow, NULL);

  const double elapsed_time = (static_cast<double>(tnow.tv_sec  - tstart.tv_sec) +
                               static_cast<double>(tnow.tv_usec - tstart.tv_usec)*1.e-6);
  return elapsed_time;
}

std::string libMesh::PerfLog::get_info_header

(

)

const

Returns:

a string containing ONLY the information header.

Definition at line 96 of file perf_log.C.

References libMesh::Utility::get_timestamp(), log_events, libMesh::n_processors(), libMesh::processor_id(), 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::n_processors() > 1)
        {
          pid_stream     << "| Processor id:   " << libMesh::processor_id();
          nprocs_stream  << "| Num Processors: " << libMesh::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 = libmesh_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 = libmesh_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(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(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(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

Returns:

a string containing: (1) Basic machine information (if first call) (2) The performance log

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();
}

std::string libMesh::PerfLog::get_perf_info

(

)

const

Returns:

a string containing ONLY the log information

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     = 10;
      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 = libmesh_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 = libmesh_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.

{ return log_events; }

void libMesh::PerfLog::pause_event	(	const std::string &	label,
		const std::string &	header = ""
	)

Suspend monitoring of the event.

Definition at line 612 of file perf_log.C.

{
  // nothing to do.  pushing the next object on the stack will handle it
}

void libMesh::PerfLog::pop	(	const std::string &	label,
		const std::string &	header = ""
	)

Pop the event label off the stack, resuming any lower event.

Referenced by stop_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 ~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 std::string &	label,
		const std::string &	header = ""
	)			[inline]

Push the event label onto the stack, pausing any active event.

Definition at line 355 of file perf_log.h.

References log, log_events, log_stack, libMesh::PerfData::start(), and total_time.

Referenced by start_event().

{
  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 620 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 628 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 596 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 604 of file perf_log.C.

References pop().

{
  this->pop(label,header);
}

---

Member Data Documentation

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 271 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 237 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 259 of file perf_log.h.

Referenced by clear(), get_log(), get_perf_info(), and push().

bool libMesh::PerfLog::log_events [private]

Flag to optionally disable all logging.

Definition at line 242 of file perf_log.h.

Referenced by clear(), disable_logging(), enable_logging(), get_info_header(), get_log(), get_perf_info(), logging_enabled(), PerfLog(), 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 264 of file perf_log.h.

Referenced by clear(), and push().

double libMesh::PerfLog::total_time [private]

The total running time for recorded events.

Definition at line 247 of file perf_log.h.

Referenced by get_perf_info(), and push().

struct timeval libMesh::PerfLog::tstart [read, private]

The time we were constructed or last cleared.

Definition at line 252 of file perf_log.h.

Referenced by clear(), get_elapsed_time(), get_perf_info(), and PerfLog().

---

The documentation for this class was generated from the following files:

• perf_log.h
• perf_log.C