libMesh::PerfLog Class Reference

Responsible for timing and summarizing events. More...

#include <perf_log.h>

Public Types
typedef std::map< std::pair< const char *, const char * >, PerfData >	log_type

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	fast_push (const char *label, const char *header="")
void	push (const char *label, const char *header="")
void	push (const std::string &label, const std::string &header="")
void	fast_pop (const char *label, const char *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="")
const log_type &	get_log_raw () 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
log_type	log
std::stack< PerfData * >	log_stack
std::map< std::string, const char * >	non_temporary_strings

Static Private Attributes
static bool	called = false

Detailed Description

Responsible for timing and summarizing events.

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 particularly useful for finding performance bottlenecks.

Author

Benjamin Kirk

Date

2003

Definition at line 125 of file perf_log.h.

Member Typedef Documentation

log_type

typedef std::map<std::pair<const char *, const char *>, PerfData> libMesh::PerfLog::log_type

Typdef for the underlying logging data structure.

Definition at line 295 of file perf_log.h.

Constructor & Destructor Documentation

PerfLog()

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

References clear(), log_events, and tstart.

                                :
  label_name(ln),
  log_events(le),
  total_time(0.)
{
  gettimeofday (&tstart, nullptr);

  if (log_events)
    this->clear();
}

~PerfLog()

libMesh::PerfLog::~PerfLog

(

)

Destructor. Calls clear() and print_log().

Definition at line 66 of file perf_log.C.

References log_events, non_temporary_strings, and print_log().

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

  for (const auto & pos : non_temporary_strings)
    delete [] pos.second;
}

Member Function Documentation

clear()

void libMesh::PerfLog::clear

(

)

Clears all the internal data and restores 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 77 of file perf_log.C.

References label_name, log, log_events, log_stack, and tstart.

Referenced by libMesh::libmesh_terminate_handler(), and PerfLog().

{
  if (log_events)
    {
      //  check that all events are closed
      for (auto pos : log)
        if (pos.second.open)
          libmesh_error_msg("ERROR clearing performance log for class " \
                            << label_name                             \
                            << "\nevent "                             \
                            << pos.first.second                      \
                            << " is still being monitored!");

      gettimeofday (&tstart, nullptr);

      log.clear();

      while (!log_stack.empty())
        log_stack.pop();
    }
}

disable_logging()

void libMesh::PerfLog::disable_logging ( )

inline

Disables performance logging for an active object.

Definition at line 156 of file perf_log.h.

References log_events.

Referenced by libMesh::LibMeshInit::LibMeshInit().

{ log_events = false; }

enable_logging()

void libMesh::PerfLog::enable_logging ( )

inline

Enables performance logging for an active object.

Definition at line 161 of file perf_log.h.

References log_events.

{ log_events = true; }

fast_pop()

void libMesh::PerfLog::fast_pop ( const char *  label, const char *  header = ""  )

inline

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

This method must be passed the exact same pointers as were passed to fast_push, not merely pointers to identical strings.

Definition at line 486 of file perf_log.h.

References libMesh::err, log, log_events, log_stack, and total_time.

Referenced by pop(), and libMesh::PerfItem::~PerfItem().

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

#ifndef NDEBUG
      PerfData * perf_data = &(log[std::make_pair(header,label)]);
      if (perf_data != log_stack.top())
        {
          libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
          libMesh::err << "From top of stack of running logs:" << std::endl;
          for (auto i : log)
            if (&(i.second) == log_stack.top())
              libMesh::err << '(' << i.first.first << ',' << i.first.second << ')' << std::endl;

          libmesh_assert_equal_to (perf_data, log_stack.top());
        }
#endif

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

      log_stack.pop();

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

fast_push()

void libMesh::PerfLog::fast_push ( const char *  label, const char *  header = ""  )

inline

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

Note - for speed the PerfLog directly considers the pointers here. Supply pointers to string literals or other character arrays whose lifetime will exceed the lifetime of the PerfLog object, not to temporarily allocated arrays.

Definition at line 466 of file perf_log.h.

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

Referenced by libMesh::PerfItem::PerfItem(), and push().

{
  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_for(*perf_data);
      else
        perf_data->start();
      log_stack.push(perf_data);
    }
}

get_active_time()

double libMesh::PerfLog::get_active_time ( ) const

inline

Returns

The active time

Definition at line 531 of file perf_log.h.

References total_time.

{
  return total_time;
}

get_elapsed_time()

double libMesh::PerfLog::get_elapsed_time ( ) const

inline

Returns

The total time spent on this event.

Definition at line 519 of file perf_log.h.

References tstart.

{
  struct timeval tnow;

  gettimeofday (&tnow, nullptr);

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

get_info_header()

std::string libMesh::PerfLog::get_info_header

(

)

const

Returns

A string containing ONLY the information header.

Definition at line 170 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();

#ifdef LIBMESH_HAVE_SYS_UTSNAME_H
      // Get system information
      struct utsname sysInfo;
      uname(&sysInfo);
#endif

      // 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:           ";
      os_stream      << "| OS:             ";
      host_stream    << "| HostName:       ";
      osrel_stream   << "| OS Release:     ";
      osver_stream   << "| OS Version:     ";
      machine_stream << "| Machine:        ";

      time_stream << date;
#ifdef LIBMESH_HAVE_SYS_UTSNAME_H
      os_stream      << sysInfo.sysname     ;
      host_stream    << sysInfo.nodename    ;
      osrel_stream   << sysInfo.release     ;
      osver_stream   << sysInfo.version     ;
      machine_stream << sysInfo.machine     ;
#else
      os_stream      << "Unknown";
      host_stream    << "Unknown";
      osrel_stream   << "Unknown";
      osver_stream   << "Unknown";
      machine_stream << "Unknown";

#endif
      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 (std::size_t 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 (std::size_t 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 (std::size_t 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 (std::size_t 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();
}

get_log()

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

get_log_raw()

const log_type& libMesh::PerfLog::get_log_raw ( ) const

inline

Returns

the raw underlying data structure for the entire performance log.

Deprecated:

because encapsulation is good.

Also probably broken by the switch from string to const char *, though users who are liberal with "auto" might be safe.

Definition at line 305 of file perf_log.h.

References log.

  {
    libmesh_deprecated();
    return log;
  }

get_perf_data()

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

References log, and non_temporary_strings.

{
  if (non_temporary_strings.count(label) &&
      non_temporary_strings.count(header))
    {
      const char * label_c_str = non_temporary_strings[label];
      const char * header_c_str = non_temporary_strings[header];
      return log[std::make_pair(header_c_str, label_c_str)];
    }

  auto iter = std::find_if
    (log.begin(), log.end(),
     [&label, &header] (log_type::const_reference a)
     {
       return
       !std::strcmp(header.c_str(), a.first.first) &&
       !std::strcmp(label.c_str(), a.first.second);
     });

  libmesh_assert(iter != log.end());

  return iter->second;
}

get_perf_info()

std::string libMesh::PerfLog::get_perf_info

(

)

const

Returns

A string containing ONLY the log information

Definition at line 338 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, nullptr);

      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;

      // Reset the event column width based on the longest event name plus
      // a possible 2-character indentation, plus a space.
      for (auto pos : log)
        if (std::strlen(pos.first.second)+3 > event_col_width)
          event_col_width = cast_int<unsigned int>
            (std::strlen(pos.first.second)+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("");

      // Make a new log to sort entries alphabetically
      std::map<std::pair<std::string, std::string>, PerfData> string_log;

      for (auto char_data : log)
        string_log[std::make_pair(char_data.first.first,
                                  char_data.first.second)] =
          char_data.second;

      for (auto pos : string_log)
        {
          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();
}

logging_enabled()

bool libMesh::PerfLog::logging_enabled ( ) const

inline

Returns

true iff performance logging is enabled

Definition at line 166 of file perf_log.h.

References log_events.

{ return log_events; }

pause_event()

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

Suspend monitoring of the event.

Definition at line 736 of file perf_log.C.

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

pop() [1/2]

void libMesh::PerfLog::pop	(	const char *	label,
		const char *	header = ""
	)

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

This method will eventually be deprecated. Use fast_pop() (with the exact same pointers supplied to fast_push()) instead.

Definition at line 162 of file perf_log.C.

Referenced by stop_event().

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

pop() [2/2]

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

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

This method will eventually be deprecated. String manipulation is too low performance to use when performance monitoring hot spots. Use fast_pop() instead.

Definition at line 142 of file perf_log.C.

References fast_pop(), log_events, and non_temporary_strings.

{

  const char * label_c_str = non_temporary_strings[label];
  const char * header_c_str = non_temporary_strings[header];

  // This could happen if users are *mixing* string and char* APIs for
  // the same label/header combination.  For perfect backwards
  // compatibility we should handle that, but there's just no fast way
  // to do so.
  libmesh_assert(label_c_str);
  libmesh_assert(header_c_str);

  if (this->log_events)
    this->fast_pop(label_c_str, header_c_str);
}

print_log()

void libMesh::PerfLog::print_log

(

)

const

Print the log.

Definition at line 684 of file perf_log.C.

References get_log(), log_events, and libMesh::out.

Referenced by libMesh::libmesh_terminate_handler(), 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;
    }
}

push() [1/2]

void libMesh::PerfLog::push	(	const char *	label,
		const char *	header = ""
	)

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

This method will eventually be deprecated. For backwards compatibility, the PerfLog must copy the contents of these character arrays into strings, which ironically damages the performance we are trying to profile. Use fast_push() (with compatible long-lived character array data) instead.

Definition at line 132 of file perf_log.C.

Referenced by start_event().

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

push() [2/2]

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

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

This method will eventually be deprecated. String manipulation is too low performance to use when performance monitoring hot spots. Use fast_push() instead.

Definition at line 101 of file perf_log.C.

References fast_push(), log_events, and non_temporary_strings.

{
  const char * label_c_str;
  const char * header_c_str;
  if (non_temporary_strings.count(label))
    label_c_str = non_temporary_strings[label];
  else
    {
      char * newcopy = new char [label.size()+1];
      strcpy(newcopy, label.c_str());
      label_c_str = newcopy;
      non_temporary_strings[label] = label_c_str;
    }

  if (non_temporary_strings.count(header))
    header_c_str = non_temporary_strings[header];
  else
    {
      char * newcopy = new char [header.size()+1];
      strcpy(newcopy, header.c_str());
      header_c_str = newcopy;
      non_temporary_strings[header] = header_c_str;
    }

  if (this->log_events)
    this->fast_push(label_c_str, header_c_str);
}

restart_event()

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

Restart monitoring the event.

Definition at line 744 of file perf_log.C.

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

split_on_whitespace()

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 752 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;
        }
    }
}

start_event()

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

Start monitoring the event named label.

Definition at line 720 of file perf_log.C.

References push().

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

stop_event()

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

Stop monitoring the event named label.

Definition at line 728 of file perf_log.C.

References pop().

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

Member Data Documentation

called

bool libMesh::PerfLog::called = false

staticprivate

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

Referenced by get_log().

label_name

const std::string libMesh::PerfLog::label_name

private

The label for this object.

Definition at line 318 of file perf_log.h.

Referenced by clear(), and get_perf_info().

log

log_type libMesh::PerfLog::log

private

The actual log.

An unsorted_map would work fine here and would be asymptotically faster, but in my tests for our log sizes there was no improvement.

Definition at line 342 of file perf_log.h.

Referenced by clear(), fast_pop(), fast_push(), get_log(), get_log_raw(), get_perf_data(), and get_perf_info().

log_events

bool libMesh::PerfLog::log_events

private

Flag to optionally disable all logging.

Definition at line 323 of file perf_log.h.

Referenced by clear(), disable_logging(), enable_logging(), fast_pop(), fast_push(), get_info_header(), get_log(), get_perf_info(), logging_enabled(), PerfLog(), pop(), print_log(), push(), and ~PerfLog().

log_stack

std::stack<PerfData*> libMesh::PerfLog::log_stack

private

A stack to hold the current performance log trace.

Definition at line 347 of file perf_log.h.

Referenced by clear(), fast_pop(), and fast_push().

non_temporary_strings

std::map<std::string, const char *> libMesh::PerfLog::non_temporary_strings

private

Workaround to give us fixed pointers to character arrays for every string. Using std::set instead might work: it won't invalidate iterators, which I think means it doesn't have any reason to modify or copy their contents or otherwise invalidate their c_str() pointers... but I can't prove it from the standards doc, so let's be safe.

Definition at line 371 of file perf_log.h.

Referenced by get_perf_data(), pop(), push(), and ~PerfLog().

total_time

double libMesh::PerfLog::total_time

private

The total running time for recorded events.

Definition at line 328 of file perf_log.h.

Referenced by fast_pop(), fast_push(), get_active_time(), and get_perf_info().

tstart

struct timeval libMesh::PerfLog::tstart

private

The time we were constructed or last cleared.

Definition at line 333 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