PerfGraph

Overview

Note: this is API/developer documentation intended for those developing code using MOOSE. For end-user focused documentation see PerfGraphOutput.

The PerfGraph object holds timing data for MOOSE. The idea behind the design is to create a nested set of timing data that faithfully represents the call structure in MOOSE.

The performance graph is part of an ecosystem of objects:

PerfGraph: Holds the full graph and the routines for printing it out
PerfNode: Makes up each node in the graph and holds timing information for each section of code
PerfGuard: Scope guard used to active and deactivate timers
PerfGraphInterface: An interface class for gaining access to the PerfGraph for adding timers and pulling timing data
PerfGraphOutput: Responsible for printing out the graph
PerfGraphData: Postprocessor for outputting time from the graph
PerfGraphLivePrint: Object responsible for printing performance information duruing the run

The PerfGraph works by utilizing the TIME_SECTION macro to specify that the current scope should be timed (see below for more information). The timed sections are placed in an execution tree and the current "stack" of sections is kept up to date. When timing starts, a snapshot of both the memory and current time are taken then these are compared when the current scope ends in order to tally time for that section of code. The PerfGraphLivePrint object is watching the stream of what is executing and possibly printing out what is happening if it takes too long (or uses too much memory). At the end of the run the PerfGraphOutput object is responsible for dumping out the relevant information.

warning

PerfGraph based timing should NOT be used inside tight compute loops or anything called inside a tight compute loop (i.e. don't use it in computeQpResidual()). It takes about 1e-6 seconds for the timing itself to happen. That's in the 1 MHz range... meaning that your calculation can't run any faster than that wherever this timer is! As a general rule... that means that you should have >1000 operations going on inside a timed section.

Inheriting From `PerfGraphInterface`

To use for timing, make sure that your system inherits from PerfGraphInterface. There are a couple of different constructors for PerfGraphInterface:

The first one allows you to pass in a MooseObject* and infer a "prefix" based on the type() of the object (the name of the object). The "prefix" is prependended to the name of the timed sections to give uniform naming from each object

  PerfGraphInterface(const MooseObject * moose_object);

The second one allows you to pass in a MooseObject* and explicitly set a prefix:

  PerfGraphInterface(const MooseObject * moose_object, const std::string prefix);

The final one is for when your object is NOT a MooseObject inherited object. You explicitly pass in the PerfLog & (usually by retrieving it from the MooseApp) and explicitly set a prefix.

  PerfGraphInterface(PerfGraph & perf_graph, const std::string prefix = "");

Logging Levels

The PerfGraph relies on loggging "levels" to determine how verbose the output should be. When timing a section, be sure to set the level appropriately so that users are not inundated with too much noise. The levels are:

0: Just the "root" - the whole application time
1: Minimal set of the most important routines (residual/jacobian computation, etc.)
2: Important initialization routines (setting up the mesh, initializing the systems, etc.)
3: More detailed information from levels 1 and 2
4: This is where the Actions will start to print
5: Fairly unimportant, or less used routines
6: Routines that rarely take up much time

Timing a Section

There are two different methods for timing: on-the-fly registration and pre-registration. On-the-fly registration is the preferred method and should be used whenever possible.

On-The-Fly Section Timing

Timing a section is as simple as using the TIME_SECTION macro within a C++ scope. TIME_SECTION can take between one and four arguments. The single argument version is used when doing pre-registration of sections. For on-the-fly you invoke TIME_SECTION like so:

TIME_SECTION(section_name, level, live_message="", print_dots=true)

section_name: The short name of the section. This is the name used in the final table. It is normally the function name or some other short name.
level: The logging level
live_message: OPTIONAL - but highly recommended. This is the message PerfGraphLivePrint will print to the screen (if necessary). It should be descriptive, title-cased, and written in an active way, e.g. "Calculating Lama Heights"
print_dots: OPTIONAL - defaults to true. This controls whether or not progress dots will be printed for this section. Only turn this off if printing dots would intermingle with some screen output that is out of MOOSE's control (for instance, in a library that you are calling into).

An example showing the most-often use-case for TIME_SECTION:


void
Dog::clean()
{
  TIME_SECTION("clean", 2, "Cleaning the Dog");
  ...

  {
    TIME_SECTION("soap", 3, "Soaping the Dog");
    ...
  }

  {
    TIME_SECTION("rinse", 3, "Rinsing the Dog");
    ...
  }
  ...
}

What TIME_SECTION is doing is creating a static variable to hold a PerfID that is initialized by registering the section with the PerfGraphRegistry. Since this is a static variable the registration only happens the very first time that line of code is hit . Every time after that it simply creates PerfGuard object using the passed in PerfID. The PerfGuard tells the PerfGraph about the new scope and the timing is then started for that section. At the end of the function the PerfGuard dies and in the destructor it tells the PerfGraph to remove that scope. Timing this way means that it is exception safe and impossible to "foul up" because there are no "push/pop" methods to match.

Pre-registered Timing

This type of timing should _only_ be utilized when absolutely necessary. The main case where this comes up is timing in base classes that main get instantiated multiple times through different derived classes. An example is the Action base class.

Timing a section using pre-registration is a two part process:

Register the section and save off the PerfID
Using the TIME_SECTION macro to start timing a PerfID

Registration

Registering the section of code to be timed is accomplished by calling:

  PerfID registerTimedSection(const std::string & section_name,

The section_name names the section of code. The prefix + section_name must be globally unique. level is the "log level" of the section. A higher number represents a more detailed log level. Here are some quick guidelines for selecting level:

registerTimedSection() returns a PerfID that is a unique identifier that identifies that code section. This PerfID should typically get saved as a member variable of the class that is registering the section... this is normally done by initializing a PerfID member variable using registerTimedSection() in the initialization list of a constructor like so:


MyClass::MyClass() : _slow_function_timer(registerTimedSection("slowFunction")) {}

Timing

Once a timed section is registered and a PerfID is captured the section can be timed using the TIME_SECTION macro like so:



void slowFunction()
{
  TIME_SECTION(_slow_function_timer);

  // do all the things
}

What TIME_SECTION is doing is creating a PerfGuard object using the passed in PerfID. The PerfGuard tells the PerfGraph about the new scope and the timing is then started for that section. At the end of the function the PerfGuard dies and in the destructor it tells the PerfGraph to remove that scope. Timing this way means that it is exception safe and impossible to "foul up" because there are no "push/pop" methods to match.

Retrieving Time

An object that inherits from PerfGraphInterface can retrieve the time for a registered section by calling _perf_graph.getTime() (or _perf_graph.getSelf/Children/TotalTime()). These functions return a reference to where the time will be updated for that particular section. In the normal MOOSE way, the object should hold onto that reference and just use the value of it when it needs to know the time a section has taken. There is one small issue though... _perf_graph.updateTiming() should be called to ensure that the time held by the referene is up to date.

The `PerfGraph` Internals

The PerfGraph object's main purpose is to store the complete call-graph of PerfNodes and the current call-stack of PerfNodes. The graph is held by holding onto the _root_node. All other scopes that are pushed into the graph are then children/descendents of the _root_node.

The call-stack is held within the _stack variable. The _stack is statically allocated to MAX_STACK_SIZE and _current_position is used to point at the most recent node on the stack. When a PerfGuard tells the PerfStack about a new scope, the new scope is added a child to the PerfNode that is in the _current_position. _current_position is then incremented and the new PerfNode is put there. When a scope is removed by the PerfGuard the _current_position is simply decremented - with no other action being necessrry.

In addition, the _execution_list is keeping a running list of every section that executes. This is utilized by PerfGraphLivePrint to print messages out that are multiple levels deep.

Printing

Some other capability the PerfGraph has is the ability to print formatted tables displaying the values held in the graph. These normally shouldn't be called directly, but instead should be accessed using a PerfGraphOutput output object.

The print() method prints out an indented set of section names and shows their timing like so:


Performance Graph:
----------------------------------------------------------------------------------------------------------------------------------------------
|                  Section                 | Calls |   Self(s)  |   Avg(s)   |    %   | Mem(MB) |  Total(s)  |   Avg(s)   |    %   | Mem(MB) |
----------------------------------------------------------------------------------------------------------------------------------------------
| MooseTestApp (main)                      |     1 |      0.008 |      0.008 |   0.66 |       1 |      1.259 |      1.259 | 100.00 |      67 |
|   FEProblem::outputStep                  |     2 |      0.001 |      0.000 |   0.04 |       0 |      0.064 |      0.032 |   5.09 |       8 |
|   Steady::PicardSolve                    |     1 |      0.000 |      0.000 |   0.01 |       0 |      0.717 |      0.717 |  56.92 |      32 |
|     FEProblem::solve                     |     1 |      0.134 |      0.134 |  10.61 |      29 |      0.716 |      0.716 |  56.89 |      32 |
|       FEProblem::computeResidualInternal |    14 |      0.000 |      0.000 |   0.01 |       0 |      0.458 |      0.033 |  36.34 |       1 |
|       FEProblem::computeJacobianInternal |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.125 |      0.062 |   9.91 |       2 |
|     FEProblem::outputStep                |     1 |      0.000 |      0.000 |   0.02 |       0 |      0.000 |      0.000 |   0.02 |       0 |
|   Steady::final                          |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.02 |       0 |
|     FEProblem::outputStep                |     1 |      0.000 |      0.000 |   0.01 |       0 |      0.000 |      0.000 |   0.02 |       0 |
----------------------------------------------------------------------------------------------------------------------------------------------

Calls is the number of times that section was run. Self time is the time actually taken by the section while Children time is the cumulative time of all of the sub-sections below that section and Total is the sum of the two. The Avg and % columns represent the average and percent of the total run-time of the app for the number in the column to the left. Mem is the memory (in Megabytes) for the column to the left (Self or Total).

There are also two other ways to print information out about the graph using printHeaviestBranch() and printHeaviestSections(). These are described well over on the PerfGraphOutput page.

(framework/include/interfaces/PerfGraphInterface.h)

// This file is part of the MOOSE framework
// https://www.mooseframework.org
//
// All rights reserved, see COPYRIGHT for full restrictions
// https://github.com/idaholab/moose/blob/master/COPYRIGHT
//
// Licensed under LGPL 2.1, please see LICENSE for details
// https://www.gnu.org/licenses/lgpl-2.1.html

#pragma once

#include "Moose.h"
#include "PerfGuard.h"
#include "InputParameters.h"

#ifndef MOOSE_NO_PERF_GRAPH
#define TIME_SECTION1(id)                                                                          \
  mooseAssert(!Threads::in_threads, "PerfGraph timing cannot be used within threaded sections");   \
  PerfGuard time_guard(_perf_graph, id);
#else
#define TIME_SECTION1(id)
#endif

#define TIME_SECTION2(section_name, level)                                                         \
  static const PerfID __perf_id = registerTimedSection(section_name, level);                       \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION3(section_name, level, live_message)                                           \
  static const PerfID __perf_id = registerTimedSection(section_name, level, live_message);         \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION4(section_name, level, live_message, print_dots)                               \
  static const PerfID __perf_id =                                                                  \
      registerTimedSection(section_name, level, live_message, print_dots);                         \
  TIME_SECTION1(__perf_id);

// Overloading solution from https://stackoverflow.com/a/11763277
#define GET_MACRO(_1, _2, _3, _4, NAME, ...) NAME
#define TIME_SECTION(...)                                                                          \
  GET_MACRO(__VA_ARGS__, TIME_SECTION4, TIME_SECTION3, TIME_SECTION2, TIME_SECTION1, )(__VA_ARGS__)

// Forward declarations
class PerfGraphInterface;

template <>
InputParameters validParams<PerfGraphInterface>();

/**
 * Interface for objects that needs transient capabilities
 */
class PerfGraphInterface
{
public:
  /**
   * For objects that _are_ MooseObjects with a default prefix of type()
   */
  PerfGraphInterface(const MooseObject * moose_object);

  static InputParameters validParams();

  /**
   * For objects that _are_ MooseObjects
   */
  PerfGraphInterface(const MooseObject * moose_object, const std::string prefix);

  /**
   * For objects that aren't MooseObjects
   */
  PerfGraphInterface(PerfGraph & perf_graph, const std::string prefix = "");

  virtual ~PerfGraphInterface() = default;

protected:
  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name, const unsigned int level) const;

  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @param live_message The message to be printed to the screen during execution
   * @param print_dots Whether or not progress dots should be printed for this section
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name,
                              const unsigned int level,
                              const std::string & live_message,
                              const bool print_dots = true) const;

  /// Params
  const InputParameters * const _pg_params;

  /// The performance graph to add to
  PerfGraph & _perf_graph;

  /// A prefix to use for all sections
  std::string _prefix;
};

(framework/include/interfaces/PerfGraphInterface.h)

// This file is part of the MOOSE framework
// https://www.mooseframework.org
//
// All rights reserved, see COPYRIGHT for full restrictions
// https://github.com/idaholab/moose/blob/master/COPYRIGHT
//
// Licensed under LGPL 2.1, please see LICENSE for details
// https://www.gnu.org/licenses/lgpl-2.1.html

#pragma once

#include "Moose.h"
#include "PerfGuard.h"
#include "InputParameters.h"

#ifndef MOOSE_NO_PERF_GRAPH
#define TIME_SECTION1(id)                                                                          \
  mooseAssert(!Threads::in_threads, "PerfGraph timing cannot be used within threaded sections");   \
  PerfGuard time_guard(_perf_graph, id);
#else
#define TIME_SECTION1(id)
#endif

#define TIME_SECTION2(section_name, level)                                                         \
  static const PerfID __perf_id = registerTimedSection(section_name, level);                       \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION3(section_name, level, live_message)                                           \
  static const PerfID __perf_id = registerTimedSection(section_name, level, live_message);         \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION4(section_name, level, live_message, print_dots)                               \
  static const PerfID __perf_id =                                                                  \
      registerTimedSection(section_name, level, live_message, print_dots);                         \
  TIME_SECTION1(__perf_id);

// Overloading solution from https://stackoverflow.com/a/11763277
#define GET_MACRO(_1, _2, _3, _4, NAME, ...) NAME
#define TIME_SECTION(...)                                                                          \
  GET_MACRO(__VA_ARGS__, TIME_SECTION4, TIME_SECTION3, TIME_SECTION2, TIME_SECTION1, )(__VA_ARGS__)

// Forward declarations
class PerfGraphInterface;

template <>
InputParameters validParams<PerfGraphInterface>();

/**
 * Interface for objects that needs transient capabilities
 */
class PerfGraphInterface
{
public:
  /**
   * For objects that _are_ MooseObjects with a default prefix of type()
   */
  PerfGraphInterface(const MooseObject * moose_object);

  static InputParameters validParams();

  /**
   * For objects that _are_ MooseObjects
   */
  PerfGraphInterface(const MooseObject * moose_object, const std::string prefix);

  /**
   * For objects that aren't MooseObjects
   */
  PerfGraphInterface(PerfGraph & perf_graph, const std::string prefix = "");

  virtual ~PerfGraphInterface() = default;

protected:
  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name, const unsigned int level) const;

  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @param live_message The message to be printed to the screen during execution
   * @param print_dots Whether or not progress dots should be printed for this section
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name,
                              const unsigned int level,
                              const std::string & live_message,
                              const bool print_dots = true) const;

  /// Params
  const InputParameters * const _pg_params;

  /// The performance graph to add to
  PerfGraph & _perf_graph;

  /// A prefix to use for all sections
  std::string _prefix;
};

(framework/include/interfaces/PerfGraphInterface.h)

// This file is part of the MOOSE framework
// https://www.mooseframework.org
//
// All rights reserved, see COPYRIGHT for full restrictions
// https://github.com/idaholab/moose/blob/master/COPYRIGHT
//
// Licensed under LGPL 2.1, please see LICENSE for details
// https://www.gnu.org/licenses/lgpl-2.1.html

#pragma once

#include "Moose.h"
#include "PerfGuard.h"
#include "InputParameters.h"

#ifndef MOOSE_NO_PERF_GRAPH
#define TIME_SECTION1(id)                                                                          \
  mooseAssert(!Threads::in_threads, "PerfGraph timing cannot be used within threaded sections");   \
  PerfGuard time_guard(_perf_graph, id);
#else
#define TIME_SECTION1(id)
#endif

#define TIME_SECTION2(section_name, level)                                                         \
  static const PerfID __perf_id = registerTimedSection(section_name, level);                       \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION3(section_name, level, live_message)                                           \
  static const PerfID __perf_id = registerTimedSection(section_name, level, live_message);         \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION4(section_name, level, live_message, print_dots)                               \
  static const PerfID __perf_id =                                                                  \
      registerTimedSection(section_name, level, live_message, print_dots);                         \
  TIME_SECTION1(__perf_id);

// Overloading solution from https://stackoverflow.com/a/11763277
#define GET_MACRO(_1, _2, _3, _4, NAME, ...) NAME
#define TIME_SECTION(...)                                                                          \
  GET_MACRO(__VA_ARGS__, TIME_SECTION4, TIME_SECTION3, TIME_SECTION2, TIME_SECTION1, )(__VA_ARGS__)

// Forward declarations
class PerfGraphInterface;

template <>
InputParameters validParams<PerfGraphInterface>();

/**
 * Interface for objects that needs transient capabilities
 */
class PerfGraphInterface
{
public:
  /**
   * For objects that _are_ MooseObjects with a default prefix of type()
   */
  PerfGraphInterface(const MooseObject * moose_object);

  static InputParameters validParams();

  /**
   * For objects that _are_ MooseObjects
   */
  PerfGraphInterface(const MooseObject * moose_object, const std::string prefix);

  /**
   * For objects that aren't MooseObjects
   */
  PerfGraphInterface(PerfGraph & perf_graph, const std::string prefix = "");

  virtual ~PerfGraphInterface() = default;

protected:
  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name, const unsigned int level) const;

  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @param live_message The message to be printed to the screen during execution
   * @param print_dots Whether or not progress dots should be printed for this section
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name,
                              const unsigned int level,
                              const std::string & live_message,
                              const bool print_dots = true) const;

  /// Params
  const InputParameters * const _pg_params;

  /// The performance graph to add to
  PerfGraph & _perf_graph;

  /// A prefix to use for all sections
  std::string _prefix;
};

(framework/include/interfaces/PerfGraphInterface.h)

// This file is part of the MOOSE framework
// https://www.mooseframework.org
//
// All rights reserved, see COPYRIGHT for full restrictions
// https://github.com/idaholab/moose/blob/master/COPYRIGHT
//
// Licensed under LGPL 2.1, please see LICENSE for details
// https://www.gnu.org/licenses/lgpl-2.1.html

#pragma once

#include "Moose.h"
#include "PerfGuard.h"
#include "InputParameters.h"

#ifndef MOOSE_NO_PERF_GRAPH
#define TIME_SECTION1(id)                                                                          \
  mooseAssert(!Threads::in_threads, "PerfGraph timing cannot be used within threaded sections");   \
  PerfGuard time_guard(_perf_graph, id);
#else
#define TIME_SECTION1(id)
#endif

#define TIME_SECTION2(section_name, level)                                                         \
  static const PerfID __perf_id = registerTimedSection(section_name, level);                       \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION3(section_name, level, live_message)                                           \
  static const PerfID __perf_id = registerTimedSection(section_name, level, live_message);         \
  TIME_SECTION1(__perf_id);

#define TIME_SECTION4(section_name, level, live_message, print_dots)                               \
  static const PerfID __perf_id =                                                                  \
      registerTimedSection(section_name, level, live_message, print_dots);                         \
  TIME_SECTION1(__perf_id);

// Overloading solution from https://stackoverflow.com/a/11763277
#define GET_MACRO(_1, _2, _3, _4, NAME, ...) NAME
#define TIME_SECTION(...)                                                                          \
  GET_MACRO(__VA_ARGS__, TIME_SECTION4, TIME_SECTION3, TIME_SECTION2, TIME_SECTION1, )(__VA_ARGS__)

// Forward declarations
class PerfGraphInterface;

template <>
InputParameters validParams<PerfGraphInterface>();

/**
 * Interface for objects that needs transient capabilities
 */
class PerfGraphInterface
{
public:
  /**
   * For objects that _are_ MooseObjects with a default prefix of type()
   */
  PerfGraphInterface(const MooseObject * moose_object);

  static InputParameters validParams();

  /**
   * For objects that _are_ MooseObjects
   */
  PerfGraphInterface(const MooseObject * moose_object, const std::string prefix);

  /**
   * For objects that aren't MooseObjects
   */
  PerfGraphInterface(PerfGraph & perf_graph, const std::string prefix = "");

  virtual ~PerfGraphInterface() = default;

protected:
  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name, const unsigned int level) const;

  /**
   * Call to register a named section for timing.
   *
   * @param section_name The name of the code section to be timed
   * @param level The importance of the timer - lower is more important (0 will always come out)
   * @param live_message The message to be printed to the screen during execution
   * @param print_dots Whether or not progress dots should be printed for this section
   * @return The ID of the section - use when starting timing
   */
  PerfID registerTimedSection(const std::string & section_name,
                              const unsigned int level,
                              const std::string & live_message,
                              const bool print_dots = true) const;

  /// Params
  const InputParameters * const _pg_params;

  /// The performance graph to add to
  PerfGraph & _perf_graph;

  /// A prefix to use for all sections
  std::string _prefix;
};

Overview
Inheriting From PerfGraphInterface
Logging Levels
Timing a Section
Retrieving Time
The Internals PerfGraph
Printing

Install MOOSE

New Users

Examples and Tutorials

Application Usage

Physics and Syntax

Application Development

Framework Development

MOOSEDocs

Infrastructure

Questions

Information and Tools

INL Applications and Remote Access

PerfGraph

Overview

Inheriting From `PerfGraphInterface`

Logging Levels

Timing a Section

On-The-Fly Section Timing

Pre-registered Timing

Registration

Timing

Retrieving Time

The `PerfGraph` Internals

Printing

PerfGraph

Overview

Inheriting From PerfGraphInterface

Logging Levels

Timing a Section

On-The-Fly Section Timing

Pre-registered Timing

Registration

Timing

Retrieving Time

The PerfGraph Internals

Printing

(framework/include/interfaces/PerfGraphInterface.h)

(framework/include/interfaces/PerfGraphInterface.h)

(framework/include/interfaces/PerfGraphInterface.h)

(framework/include/interfaces/PerfGraphInterface.h)

Inheriting From `PerfGraphInterface`

The `PerfGraph` Internals