libMesh::PerfLog Class Reference

The PerfLog class allows monitoring of specific events. More...

#include <perf_log.h>

Public Types
typedef std::map< std::pair< const char *, const char * >, PerfData >	log_type
	Typdef for the underlying logging data structure. More...

Public Member Functions
	PerfLog (std::string label_name="", const bool log_events=true)
	Constructor. More...
	~PerfLog ()
	Destructor. More...
void	clear ()
	Clears all the internal data and restores the data structures to a pristine state. More...
void	disable_logging ()
	Disables performance logging for an active object. More...
void	enable_logging ()
	Enables performance logging for an active object. More...
bool	logging_enabled () const
void	enable_summarized_logs ()
	Tells the PerfLog to only print log results summarized by header. More...
void	disable_summarized_logs ()
	Tells the PerfLog to print detailed log results (this is the default behavior) More...
bool	summarized_logs_enabled ()
void	fast_push (const char *label, const char *header="")
	Push the event label onto the stack, pausing any active event. More...
void	push (const char *label, const char *header="")
	Push the event label onto the stack, pausing any active event. More...
void	push (const std::string &label, const std::string &header="")
	Push the event label onto the stack, pausing any active event. More...
void	fast_pop (const char *label, const char *header="") noexcept
	Pop the event label off the stack, resuming any lower event. More...
void	pop (const char *label, const char *header="")
	Pop the event label off the stack, resuming any lower event. More...
void	pop (const std::string &label, const std::string &header="")
	Pop the event label off the stack, resuming any lower event. More...
void	start_event (const std::string &label, const std::string &header="")
	Start monitoring the event named label. More...
void	stop_event (const std::string &label, const std::string &header="")
	Stop monitoring the event named label. More...
void	pause_event (const std::string &label, const std::string &header="")
	Suspend monitoring of the event. More...
void	restart_event (const std::string &label, const std::string &header="")
	Restart monitoring the event. More...
std::string	get_log () const
std::string	get_info_header () const
std::string	get_perf_info () const
void	print_log () const
	Print the log. More...
double	get_elapsed_time () const
double	get_active_time () const
PerfData	get_perf_data (const std::string &label, const std::string &header="")
	Return the PerfData object associated with a label and header. More...

Private Member Functions
void	split_on_whitespace (const std::string &input, std::vector< std::string > &output) const
	Splits a string on whitespace into a vector of separate strings. More...

Private Attributes
const std::string	label_name
	The label for this object. More...
bool	log_events
	Flag to optionally disable all logging. More...
bool	summarize_logs
	Flag to optionally summarize logs. More...
double	total_time
	The total running time for recorded events. More...
struct timeval	tstart
	The time we were constructed or last cleared. More...
log_type	log
	The actual log. More...
std::stack< PerfData * >	log_stack
	A stack to hold the current performance log trace. More...
std::map< std::string, std::unique_ptr< const char[]> >	non_temporary_strings
	Workaround to give us fixed pointers to character arrays for every string. More...

Static Private Attributes
static bool	called = false
	Flag indicating if print_log() has been called. More...

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

Author

Benjamin Kirk

Date

2003 Responsible for timing and summarizing events.

Definition at line 153 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 341 of file perf_log.h.

Constructor & Destructor Documentation

PerfLog()

libMesh::PerfLog::PerfLog	(	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 55 of file perf_log.C.

References clear(), gettimeofday(), log_events, and tstart.

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

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

~PerfLog()

libMesh::PerfLog::~PerfLog

(

)

Destructor.

Calls clear() and print_log().

Definition at line 70 of file perf_log.C.

References log_events, and print_log().

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

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

References gettimeofday(), label_name, log, log_events, log_stack, and tstart.

Referenced by libMesh::libmesh_abort(), main(), PerfLog(), and libMesh::LibMeshInit::~LibMeshInit().

{
  if (log_events)
    {
      //  check that all events are closed
      for (auto pos : log)
        libmesh_error_msg_if(pos.second.open,
                             "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 184 of file perf_log.h.

References log_events.

Referenced by libMesh::Threads::DisablePerfLogInScope::DisablePerfLogInScope().

{ log_events = false; }

disable_summarized_logs()

void libMesh::PerfLog::disable_summarized_logs ( )

inline

Tells the PerfLog to print detailed log results (this is the default behavior)

Definition at line 205 of file perf_log.h.

References summarize_logs.

{ summarize_logs = false; }

enable_logging()

void libMesh::PerfLog::enable_logging ( )

inline

Enables performance logging for an active object.

Definition at line 189 of file perf_log.h.

References log_events.

Referenced by libMesh::Threads::DisablePerfLogInScope::~DisablePerfLogInScope().

{ log_events = true; }

enable_summarized_logs()

void libMesh::PerfLog::enable_summarized_logs ( )

inline

Tells the PerfLog to only print log results summarized by header.

Definition at line 199 of file perf_log.h.

References summarize_logs.

Referenced by main().

{ summarize_logs = true; }

fast_pop()

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

inlinenoexcept

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. This method is called from the PerfItem destructor, so it should not throw. We have therefore marked it noexcept as a reminder.

Definition at line 539 of file perf_log.h.

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

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

{
  if (this->log_events)
    {
      // The global perflog stack may not be thread-safe, but if we're
      // creating threads we should have disabled it already
      libmesh_exceptionless_assert(Threads::active_threads == 1);
#ifdef LIBMESH_HAVE_OPENMP
      // Users might be doing their own non-libMesh threading.  We
      // can't catch every case of that but we can catch OpenMP.
      libmesh_exceptionless_assert(omp_get_num_threads() == 1);
#endif

#ifdef LIBMESH_HAVE_NVTX_API
      nvtxRangePop();
#endif
      // If there's nothing on the stack, then we can't pop anything. Previously we
      // asserted that the log_stack was not empty, but we should not throw from
      // this function, so instead just return in that case.
      if (log_stack.empty())
        return;

#ifndef NDEBUG
      // In debug mode, we carefully check that before popping the stack,
      // we have the correct event.

      // Get pointer to corresponding PerfData, or nullptr if it does not exist.
      auto it = log.find(std::make_pair(header, label));
      PerfData * perf_data = (it == log.end()) ? nullptr : &(it->second);

      // If this event is not found in the log, then it could indicate
      // that you have a STOP_LOG(a,b) without a corresponding
      // START_LOG(a,b) call. We don't pop anything from the log_stack
      // in this case.
      if (!perf_data)
        {
          libMesh::err << "PerfLog can't pop (" << header << ',' << label << ')' << std::endl;
          libMesh::err << "No such event was found in the log, you may have a mismatched START/STOP_LOG statement." << std::endl;
          return;
        }

      if (perf_data != log_stack.top())
        {
          // We've been asked to pop an event which is not at the
          // top() of the log_stack. The event may be deeper in the
          // stack instead, so search for it now. If we find it, we'll
          // pop all intermediate items off the stack (abandoning any
          // attempt to time them accurately) and let the optimized
          // code path take over from there.
          std::deque<PerfData*> tmp_stack;

          while (!log_stack.empty() && perf_data != log_stack.top())
            {
              tmp_stack.push_front(log_stack.top());
              log_stack.pop();
            }

          // If we exhaustively searched the log_stack without finding
          // the event, we can't do anything else so just put
          // everything back and return, not doing anything for this
          // event.
          if (log_stack.empty())
            {
              while (!tmp_stack.empty())
                {
                  log_stack.push(tmp_stack.back());
                  tmp_stack.pop_back();
                }

              return;
            }
        }
#endif

      // In optimized mode, we just pop from the top of the stack and
      // resume timing the next entry.
      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 502 of file perf_log.h.

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

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

{
  if (this->log_events)
    {
      // The global perflog stack may not be thread-safe, but if we're
      // creating threads we should have disabled it already
      libmesh_assert_equal_to(Threads::active_threads, 1);
#ifdef LIBMESH_HAVE_OPENMP
      // Users might be doing their own non-libMesh threading.  We
      // can't catch every case of that but we can catch OpenMP
      libmesh_assert_equal_to(omp_get_num_threads(), 1);
#endif

      // 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);

#ifdef LIBMESH_HAVE_NVTX_API
      // This takes a single const char *, and we don't want to waste
      // time allocating a new string on every push, so for now we'll
      // drop the header.  Maybe we should allocate a new string in
      // the PerfData?
      nvtxRangePushA(label);
#endif
    }
}

get_active_time()

double libMesh::PerfLog::get_active_time ( ) const

inline

Returns

The active time

Definition at line 640 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 628 of file perf_log.h.

References gettimeofday(), tstart, timeval::tv_sec, and timeval::tv_usec.

{
  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 193 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 (auto & v_i : v)
        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 (auto & plci_i : parsed_libmesh_configure_info)
        if (plci_i.size() > max_length)
          max_length = cast_int<unsigned int> (plci_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 (auto & v_i : v)
        {
          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 (auto i : IntRange<std::size_t>(1, parsed_libmesh_configure_info.size()))
        {
          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 688 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_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 726 of file perf_log.C.

References libMesh::libmesh_assert(), 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].get();
      const char * header_c_str = non_temporary_strings[header].get();
      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 360 of file perf_log.C.

References libMesh::PerfData::count, gettimeofday(), label_name, log, log_events, libMesh::Real, summarize_logs, libMesh::PerfData::tot_time, libMesh::PerfData::tot_time_incl_sub, total_time, tstart, timeval::tv_sec, and timeval::tv_usec.

Referenced by get_log().

{
  std::ostringstream oss;

  if (!log_events || log.empty())
    return oss.str();

  // 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)
    if (summarize_logs)
      {
        string_log[std::make_pair(std::string(), char_data.first.first)] +=
          char_data.second;
      }
    else
      {
        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 194 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 766 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 185 of file perf_log.C.

Referenced by assemble_biharmonic(), assemble_laplace(), assemble_poisson(), main(), stop_event(), and UnitPerfItem::~UnitPerfItem().

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

References libMesh::Threads::active_threads, fast_pop(), libMesh::libmesh_assert(), log_events, and non_temporary_strings.

{
  // The global perflog stack may not be thread-safe, but if we're
  // creating threads we should have disabled it already
  libmesh_assert_equal_to(Threads::active_threads, 1);
#ifdef LIBMESH_HAVE_OPENMP
  // Users might be doing their own non-libMesh threading.  We can't
  // catch every case of that but we can catch OpenMP.
  libmesh_exceptionless_assert(omp_get_num_threads() == 1);
#endif

  const char * label_c_str = non_temporary_strings[label].get();
  const char * header_c_str = non_temporary_strings[header].get();

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

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

Referenced by assemble_biharmonic(), assemble_laplace(), assemble_poisson(), main(), start_event(), and UnitPerfItem::UnitPerfItem().

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

References libMesh::Threads::active_threads, fast_push(), log_events, and non_temporary_strings.

{
  // The global perflog stack may not be thread-safe, but if we're
  // creating threads we should have disabled it already
  libmesh_assert_equal_to(Threads::active_threads, 1);
#ifdef LIBMESH_HAVE_OPENMP
  // Users might be doing their own non-libMesh threading.  We can't
  // catch every case of that but we can catch OpenMP.
  libmesh_assert_equal_to(omp_get_num_threads(), 1);
#endif

  const char * label_c_str;
  const char * header_c_str;

  if (const auto label_it = non_temporary_strings.find(label);
      label_it != non_temporary_strings.end())
    label_c_str = label_it->second.get();
  else
    {
      const std::size_t labelsizep1 = label.size()+1;
      auto newcopy = std::make_unique<char[]>(labelsizep1);
      std::strncpy(newcopy.get(), label.c_str(), labelsizep1);
      label_c_str = newcopy.get();
      non_temporary_strings[label] = std::move(newcopy);
    }

  if (const auto header_it = non_temporary_strings.find(header);
      header_it != non_temporary_strings.end())
    header_c_str = header_it->second.get();
  else
    {
      const std::size_t headersizep1 = header.size()+1;
      auto newcopy = std::make_unique<char[]>(headersizep1);
      std::strncpy(newcopy.get(), header.c_str(), headersizep1);
      header_c_str = newcopy.get();
      non_temporary_strings[header] = std::move(newcopy);
    }

  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 774 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 782 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
      if (size_t end_pos = input.find(split_on, current_pos);
          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 750 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 758 of file perf_log.C.

References pop().

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

summarized_logs_enabled()

bool libMesh::PerfLog::summarized_logs_enabled ( )

inline

Returns

true iff log results will be summarized by header

Definition at line 210 of file perf_log.h.

References summarize_logs.

Referenced by DistributedVectorTest::DistributedVectorTest(), EigenSparseMatrixTest::EigenSparseMatrixTest(), EigenSparseVectorTest::EigenSparseVectorTest(), EpetraVectorTest::EpetraVectorTest(), LaspackMatrixTest::LaspackMatrixTest(), LaspackVectorTest::LaspackVectorTest(), PetscMatrixTest::PetscMatrixTest(), PetscVectorTest::PetscVectorTest(), and RealVectorValueTest::RealVectorValueTest().

{ return summarize_logs; }

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 390 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 349 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 378 of file perf_log.h.

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

log_events

bool libMesh::PerfLog::log_events

private

Flag to optionally disable all logging.

Definition at line 354 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 383 of file perf_log.h.

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

non_temporary_strings

std::map<std::string, std::unique_ptr<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 407 of file perf_log.h.

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

summarize_logs

bool libMesh::PerfLog::summarize_logs

private

Flag to optionally summarize logs.

Definition at line 359 of file perf_log.h.

Referenced by disable_summarized_logs(), enable_summarized_logs(), get_perf_info(), and summarized_logs_enabled().

total_time

double libMesh::PerfLog::total_time

private

The total running time for recorded events.

Definition at line 364 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 369 of file perf_log.h.

Referenced by clear(), get_elapsed_time(), get_perf_info(), libMesh::PerfData::pause_for(), PerfLog(), libMesh::PerfData::restart(), libMesh::PerfData::start(), and libMesh::PerfData::stop_or_pause().

---

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

• include/utils/perf_log.h
• src/utils/perf_log.C