PerfLog

Section: C Library Functions (3) Updated: Thu Apr 7 2011 Local index Up

NAME

PerfLog -

SYNOPSIS

Public Member Functions

PerfLog (const std::string &label_name='', const bool log_events=true)

~PerfLog ()

void clear ()

void disable_logging ()

void enable_logging ()

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 _character_line (const unsigned int n, const char c, OStringStream &out) 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 127 of file perf_log.h.

Constructor & Destructor Documentation

PerfLog::PerfLog (const std::string &label_name = '', const boollog_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 43 of file perf_log.C.

References clear(), and log_events.

                                :
  label_name(ln),
  log_events(le),
  total_time(0.)
{
  if (log_events)
    this->clear();
}

PerfLog::~PerfLog ()Destructor. Calls clear() and print_log().

Definition at line 55 of file perf_log.C.

References log_events, and print_log().

{
  if (log_events)
    this->print_log();
}

Member Function Documentation

void PerfLog::_character_line (const unsigned intn, const charc, OStringStream &out) const [private]Prints a line of 'n' repeated characters 'c' to the output string stream 'out'.

Definition at line 508 of file perf_log.C.

Referenced by get_info_header(), and get_perf_info().

{
  for (unsigned int i=0; i<n; ++i)
    out << c;
}

void 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 63 of file perf_log.C.

References label_name, log, log_events, log_stack, 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)
          {
            std::cout
              << '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 PerfLog::disable_logging () [inline]Disables performance logging for an active object.

Definition at line 159 of file perf_log.h.

References log_events.

Referenced by Threads::parallel_for(), and Threads::parallel_reduce().

{ log_events = false; }

void PerfLog::enable_logging () [inline]Enables performance logging for an active object.

Definition at line 164 of file perf_log.h.

References log_events.

Referenced by Threads::parallel_for(), and Threads::parallel_reduce().

{ log_events = true; }

double PerfLog::get_elapsed_time () const [inline]Returns:

: the total time spent on this event.

Definition at line 401 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 PerfLog::get_info_header () constReturns:

: a string containing ONLY the information header.

Definition at line 92 of file perf_log.C.

References _character_line(), log_events, libMesh::n_processors(), and libMesh::processor_id().

Referenced by get_log().

{
  OStringStream out;
  
  if (log_events)
    {

#ifdef LIBMESH_HAVE_LOCALE
      OStringStream  dateStr;
      time_t tm         = time(NULL);
      struct tm* tmb    = localtime(&tm);
      std::locale loc;
      TimeIter            begin(dateStr);
      const TimePut& tp = std::use_facet<TimePut>(loc);
      tp.put(begin,
             dateStr,
             dateStr.fill(),
             tmb,
             'c');
#endif
      
      // Get system information
      struct utsname sysInfo;
      uname(&sysInfo);
      
      // Get user information
      struct passwd* p = getpwuid(getuid());
      out << ';

      // Construct string stream objects for each of the outputs
      OStringStream pid_stream;
      OStringStream nprocs_stream;
      OStringStream time_stream;
      OStringStream os_stream;
      OStringStream host_stream;
      OStringStream osrel_stream;
      OStringStream osver_stream;
      OStringStream machine_stream;
      OStringStream user_stream;
      OStringStream config_stream;
      

      // Put pointers to these streams in a vector
      std::vector<OStringStream*> v(10);
      v[0] = &pid_stream;
      v[1] = &nprocs_stream;
      v[2] = &time_stream;
      v[3] = &os_stream;
      v[4] = &host_stream;
      v[5] = &osrel_stream;
      v[6] = &osver_stream;
      v[7] = &machine_stream;
      v[8] = &user_stream;
      v[9] = &config_stream;

      // Fill string stream objects
      if (libMesh::n_processors() > 1)
        {
          pid_stream     << '| Processor id:   ' << libMesh::processor_id(); 
          nprocs_stream  << '| Num Processors: ' << libMesh::n_processors();
        }
      
#ifdef LIBMESH_HAVE_LOCALE                                                     
      time_stream    << '| Time:           ' << dateStr.str()          ; 
#endif                                                                 
      
      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:       ' << p->pw_name             ;
      config_stream  << '| Configuration:  ' << LIBMESH_CONFIGURE_INFO;
      
      // Find the longest string, use that to set the line length for formatting.
      unsigned int max_length = 0;
      for (unsigned int i=0; i<v.size(); ++i)
        if (v[i]->str().size() > max_length)
          max_length = v[i]->str().size();
      
      // Print dashed line
      this->_character_line(max_length+2, '-', out);
      out << ';

      // Loop over all the strings and print them out with end-formatting
      for (unsigned int i=0; i<v.size(); ++i)
        {
          if (v[i]->str().size() > 0)
            {
              out << v[i]->str();
              OSSStringright(out, max_length+4 - v[i]->str().size(), '|);
            }
        }

      // Print dashed line
      this->_character_line(max_length+2, '-', out);
      out << ';
    }

  return out.str();
}

std::string PerfLog::get_log () constReturns:

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

Definition at line 435 of file perf_log.C.

References called, get_info_header(), get_perf_info(), log, and log_events.

Referenced by print_log().

{
  OStringStream out;
  
  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;
              out << get_info_header();
            }     
          out << get_perf_info();
        }
    }
  
  return out.str();
}

std::string PerfLog::get_perf_info () constReturns:

: a string containing ONLY the log information

Definition at line 197 of file perf_log.C.

References _character_line(), PerfData::count, label_name, log, log_events, PerfData::tot_time, PerfData::tot_time_incl_sub, total_time, and tstart.

Referenced by get_log().

{
  OStringStream out;
  
  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 = 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
      out << ' ';
      this->_character_line(total_col_width, '-', out);
      out << ';
            
      {
        // Construct temporary message string
        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 = temp.str().size();

        // Send the temporary message to the output
        out << 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)
          {
            OSSStringright(out, total_col_width-temp_size+2, '|');
          }
        
        out << ';
      }
      
      // Print dashed line
      out << ' ';
      this->_character_line(total_col_width, '-', out);
      out << ';

      
      // Write out the header for the events listing
      out << '| ';
      OSSStringleft(out,event_col_width,'Event');      
      OSSStringleft(out,ncalls_col_width,'nCalls');      
      OSSStringleft(out,tot_time_col_width,'Total Time');
      OSSStringleft(out,avg_time_col_width,'Avg Time');
      OSSStringleft(out,tot_time_incl_sub_col_width,'Total Time');
      OSSStringleft(out,avg_time_incl_sub_col_width,'Avg Time');
      OSSStringleft(out,pct_active_col_width+pct_active_incl_sub_col_width,'% of Active Time');      
      out << '|;      
      out << '| ';
      OSSStringleft(out,event_col_width,'');
      OSSStringleft(out,ncalls_col_width,'');
      OSSStringleft(out,tot_time_col_width,'w/o Sub');
      OSSStringleft(out,avg_time_col_width,'w/o Sub');
      OSSStringleft(out,tot_time_incl_sub_col_width,'With Sub');
      OSSStringleft(out,avg_time_incl_sub_col_width,'With Sub');
      OSSStringleft(out,pct_active_col_width,'w/o S');
      OSSStringleft(out,pct_active_incl_sub_col_width,'With S');
      
      out << '|';
      this->_character_line(total_col_width, '-', out);
      out << '|';
      this->_character_line(total_col_width, ' ', out);
      out << '|;
      
      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 == '')
                {
                  out << '| ';
                  OSSStringleft(out,event_col_width,pos->first.second);
                }
              else
                {
                  if (last_header != pos->first.first)
                    {
                      last_header = pos->first.first;

                      // print blank line
                      out << '|';
                      this->_character_line(total_col_width, ' ', out);
                      out << '|;

                      // print header name (account for additional space before
                      // the header)
                      out << '| ';
                      OSSStringleft(out, total_col_width-1, pos->first.first);
                      out << '|;
                    }

                  out << '|   ';
                  OSSStringleft(out, event_col_width-2, pos->first.second);
                }
              

              // Print the number of calls to the event.  
              OSSInt(out,ncalls_col_width,perf_count);

              // Print the total time spent in the event
              out.setf(std::ios::fixed);
              OSSRealleft(out,tot_time_col_width,4,perf_time);

              // Print the average time per function call
              OSSRealleft(out,avg_time_col_width,6,perf_avg_time);

              // Print the total time spent in the event incl. sub-events
              OSSRealleft(out,tot_time_incl_sub_col_width,4,perf_time_incl_sub);

              // Print the average time per function call incl. sub-events
              OSSRealleft(out,avg_time_incl_sub_col_width,6,perf_avg_time_incl_sub);

              // Print the percentage of the time spent in the event
              OSSRealleft(out,pct_active_col_width,2,perf_percent);
              
              // Print the percentage of the time spent in the event incl. sub-events
              OSSRealleft(out,pct_active_incl_sub_col_width,2,perf_percent_incl_sub);
              
              out << '|';
              out << ';
            }
        }

      out << ' ';
      this->_character_line(total_col_width, '-', out);
      out << ';
      out << '| ';
      OSSStringleft(out,event_col_width,'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)
        {
          OSSInt(out,ncalls_col_width,summed_function_calls);
        }
      
      else
        {
          out.setf(std::ios::scientific);
          OSSRealleft(out, ncalls_col_width, 3, static_cast<Real>(summed_function_calls));
          out.unsetf(std::ios::scientific);
        }
        
      // Print the total time spent in logged function calls
      out.setf(std::ios::fixed);
      OSSRealleft(out,tot_time_col_width,4,summed_total_time);

      // Null, the average time doesn't make sense as a total
      out.width(avg_time_col_width);
      out << '';

      // Same for times that include sub-events
      out.width(tot_time_incl_sub_col_width);
      out << '';
      out.width(avg_time_incl_sub_col_width);
      out << '';

      // Print the total percentage
      OSSRealleft(out,pct_active_col_width,2,summed_percentage);
      
      out.width(pct_active_incl_sub_col_width);
      out << '';

      out << '|';
      this->_character_line(total_col_width, '-', out);
      out << ';
    }

  return out.str();
}

void PerfLog::pause_event (const std::string &label, const std::string &header = '')Suspend monitoring of the event.

Definition at line 491 of file perf_log.C.

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

void PerfLog::pop (const std::string &label, const std::string &header = '') [inline]Pop the event label off the stack, resuming any lower event.

Definition at line 377 of file perf_log.h.

References log, log_events, log_stack, and total_time.

Referenced by stop_event().

{
  if (this->log_events)
    {
      libmesh_assert (!log_stack.empty());

#ifndef NDEBUG
      PerfData *perf_data = &(log[std::make_pair(header,label)]);
      libmesh_assert (perf_data == log_stack.top());
#endif

      total_time += log_stack.top()->stopit();

      log_stack.pop();

      if (!log_stack.empty())
        log_stack.top()->restart();
    }
}

void PerfLog::print_log () constPrint the log.

Definition at line 461 of file perf_log.C.

References get_log(), and log_events.

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)
        std::cout << log_string << std::endl;
    }
}

void 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 356 of file perf_log.h.

References log, log_events, log_stack, 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 PerfLog::restart_event (const std::string &label, const std::string &header = '')Restart monitoring the event.

Definition at line 499 of file perf_log.C.

{
  // nothing to do.  popping the top off the stack will handle it.
}

void PerfLog::start_event (const std::string &label, const std::string &header = '')Start monitoring the event named label.

Definition at line 475 of file perf_log.C.

References push().

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

void PerfLog::stop_event (const std::string &label, const std::string &header = '')Stop monitoring the event named label.

Definition at line 483 of file perf_log.C.

References pop().

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

Member Data Documentation

bool 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 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> PerfLog::log [private]The actual log.

Definition at line 259 of file perf_log.h.

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

bool 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(), PerfLog(), pop(), print_log(), push(), and ~PerfLog().