From 5bc04fb2587f01413ce9400f1b277e369fdfab6c Mon Sep 17 00:00:00 2001 From: Derek Gaston Date: Sun, 28 Jun 2020 20:25:22 -0600 Subject: [PATCH] Can now register live print names and skip printing sections without it refs #15444 --- framework/include/actions/SetupMeshAction.h | 5 + .../include/interfaces/PerfGraphInterface.h | 11 ++ framework/include/utils/PerfGraph.h | 34 ++++- framework/src/actions/SetupMeshAction.C | 13 +- framework/src/interfaces/PerfGraphInterface.C | 9 ++ framework/src/mesh/MooseMesh.C | 34 ++--- framework/src/problems/FEProblemBase.C | 48 +++---- framework/src/utils/PerfGraph.C | 117 ++++++++++++------ 8 files changed, 181 insertions(+), 90 deletions(-) diff --git a/framework/include/actions/SetupMeshAction.h b/framework/include/actions/SetupMeshAction.h index 8ee22002b219..567e31037ddf 100644 --- a/framework/include/actions/SetupMeshAction.h +++ b/framework/include/actions/SetupMeshAction.h @@ -35,4 +35,9 @@ class SetupMeshAction : public MooseObjectAction * @return The new type of object that will be built. */ std::string modifyParamsForUseSplit(InputParameters & moose_object_params) const; + + /// Timers + PerfID _setup_mesh_timer; + PerfID _set_mesh_base_timer; + PerfID _init_mesh_timer; }; diff --git a/framework/include/interfaces/PerfGraphInterface.h b/framework/include/interfaces/PerfGraphInterface.h index 238978e8920b..fa1bf9c61c52 100644 --- a/framework/include/interfaces/PerfGraphInterface.h +++ b/framework/include/interfaces/PerfGraphInterface.h @@ -60,6 +60,17 @@ class PerfGraphInterface */ PerfID registerTimedSection(const std::string & section_name, const unsigned int level); + /** + * 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); + /// Params const InputParameters * _pg_params; diff --git a/framework/include/utils/PerfGraph.h b/framework/include/utils/PerfGraph.h index 0b9af7de6825..28b642124605 100644 --- a/framework/include/utils/PerfGraph.h +++ b/framework/include/utils/PerfGraph.h @@ -71,10 +71,25 @@ class PerfGraph : protected ConsoleStreamInterface /** * Registers a named section of code * + * Note: this will automatically set the section_name to what will print out + * during a live print. It will only be printed out if live printing is forced. + * It will also dissallow the printing of progress dots. + * * @return The unique ID to use for that section */ PerfID registerSection(const std::string & section_name, unsigned int level); + /** + * Registers a named section of code + * + * @param section_name The name of the section as it will be printed in the PerfGraph + * @param level The verbosity level + * @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 unique ID to use for that section + */ + PerfID registerSection(const std::string & section_name, unsigned int level, const std::string & live_message, const bool print_dots); + /** * Print the tree out * @@ -210,6 +225,18 @@ class PerfGraph : protected ConsoleStreamInterface typedef VariadicTable HeaviestTable; + /** + * Used to hold metadata about the registered sections + */ + struct SectionInfo + { + PerfID _id; + std::string _name; + unsigned int _level; + std::string _live_message; + bool _print_dots; + }; + /** * Use to hold the time for each section * @@ -352,11 +379,8 @@ class PerfGraph : protected ConsoleStreamInterface /// Map of section names to IDs std::map _section_name_to_id; - /// Map of IDs to section names - std::map _id_to_section_name; - - /// Map of IDs to level - std::map _id_to_level; + /// Map of IDs to section information + std::map _id_to_section_info; /// The time for each section. This is updated on updateTiming() /// Note that this is _total_ cumulative time across every place diff --git a/framework/src/actions/SetupMeshAction.C b/framework/src/actions/SetupMeshAction.C index ff1724d1fbe2..267514c2779a 100644 --- a/framework/src/actions/SetupMeshAction.C +++ b/framework/src/actions/SetupMeshAction.C @@ -97,7 +97,12 @@ SetupMeshAction::validParams() return params; } -SetupMeshAction::SetupMeshAction(InputParameters params) : MooseObjectAction(params) {} +SetupMeshAction::SetupMeshAction(InputParameters params) : MooseObjectAction(params), + _setup_mesh_timer(registerTimedSection("SetupMeshAction::act::setup_mesh", 1, "Setting Up Mesh", true)), + _set_mesh_base_timer(registerTimedSection("SetupMeshAction::act::set_mesh_base", 1, "Setting Mesh", true)), + _init_mesh_timer(registerTimedSection("SetupMeshAction::act::set_mesh_base", 1, "Initializing Mesh", true)) + + {} void SetupMeshAction::setupMesh(MooseMesh * mesh) @@ -226,6 +231,8 @@ SetupMeshAction::act() // Create the mesh object and tell it to build itself if (_current_task == "setup_mesh") { + TIME_SECTION(_setup_mesh_timer); + if (_app.masterMesh()) _mesh = _app.masterMesh()->safeClone(); else @@ -277,6 +284,8 @@ SetupMeshAction::act() else if (_current_task == "set_mesh_base") { + TIME_SECTION(_set_mesh_base_timer); + if (!_app.masterMesh() && !_mesh->hasMeshBase()) { // We want to set the MeshBase object to that coming from mesh generators when the following @@ -294,6 +303,8 @@ SetupMeshAction::act() else if (_current_task == "init_mesh") { + TIME_SECTION(_init_mesh_timer); + if (_app.masterMesh()) { if (_app.masterDisplacedMesh()) diff --git a/framework/src/interfaces/PerfGraphInterface.C b/framework/src/interfaces/PerfGraphInterface.C index 8043a974b639..745bcb098f28 100644 --- a/framework/src/interfaces/PerfGraphInterface.C +++ b/framework/src/interfaces/PerfGraphInterface.C @@ -55,3 +55,12 @@ PerfGraphInterface::registerTimedSection(const std::string & section_name, const else return _perf_graph.registerSection(section_name, level); } + +PerfID +PerfGraphInterface::registerTimedSection(const std::string & section_name, const unsigned int level, const std::string & live_message, const bool print_dots) +{ + if (_prefix != "") + return _perf_graph.registerSection(_prefix + "::" + section_name, level, live_message, print_dots); + else + return _perf_graph.registerSection(section_name, level, live_message, print_dots); +} diff --git a/framework/src/mesh/MooseMesh.C b/framework/src/mesh/MooseMesh.C index 080c3fa2f091..7e8b33b736e5 100644 --- a/framework/src/mesh/MooseMesh.C +++ b/framework/src/mesh/MooseMesh.C @@ -226,17 +226,17 @@ MooseMesh::MooseMesh(const InputParameters & parameters) _regular_orthogonal_mesh(false), _allow_recovery(true), _construct_node_list_from_side_list(getParam("construct_node_list_from_side_list")), - _prepare_timer(registerTimedSection("prepare", 2)), - _update_timer(registerTimedSection("update", 3)), - _mesh_changed_timer(registerTimedSection("meshChanged", 3)), - _cache_changed_lists_timer(registerTimedSection("cacheChangedLists", 5)), + _prepare_timer(registerTimedSection("prepare", 2, "Preparing Mesh", true)), + _update_timer(registerTimedSection("update", 3, "Updating Mesh", true)), + _mesh_changed_timer(registerTimedSection("meshChanged", 3, "Updating Because Mesh Changed", true)), + _cache_changed_lists_timer(registerTimedSection("cacheChangedLists", 5, "Caching Changed Lists", true)), _update_active_semi_local_node_range_timer( - registerTimedSection("updateActiveSemiLocalNodeRange", 5)), - _build_node_list_timer(registerTimedSection("buildNodeList", 5)), - _build_bnd_elem_list_timer(registerTimedSection("buildBndElemList", 5)), - _node_to_elem_map_timer(registerTimedSection("nodeToElemMap", 5)), + registerTimedSection("updateActiveSemiLocalNodeRange", 5, "Updating ActiveSemiLocalNode Range", true)), + _build_node_list_timer(registerTimedSection("buildNodeList", 5, "Building Node List", true)), + _build_bnd_elem_list_timer(registerTimedSection("buildBndElemList", 5, "Building Boundary Elements List", true)), + _node_to_elem_map_timer(registerTimedSection("nodeToElemMap", 5, "Building Node To Elem Map", true)), _node_to_active_semilocal_elem_map_timer( - registerTimedSection("nodeToActiveSemilocalElemMap", 5)), + registerTimedSection("nodeToActiveSemilocalElemMap", 5, "Building SemiLocalElemMap", true)), _get_active_local_element_range_timer(registerTimedSection("getActiveLocalElementRange", 5)), _get_active_node_range_timer(registerTimedSection("getActiveNodeRange", 5)), _get_local_node_range_timer(registerTimedSection("getLocalNodeRange", 5)), @@ -406,15 +406,11 @@ MooseMesh::prepare(bool force) // setting if (force || _needs_prepare_for_use) { - CONSOLE_TIMED_PRINT("Preparing for use"); - getMesh().prepare_for_use(false, false); } } else { - CONSOLE_TIMED_PRINT("Preparing for use"); - // Call prepare_for_use() and DO NOT allow renumbering getMesh().allow_renumbering(false); if (force || _needs_prepare_for_use) @@ -695,7 +691,6 @@ void MooseMesh::buildNodeList() { TIME_SECTION(_build_node_list_timer); - CONSOLE_TIMED_PRINT("Building node lists"); freeBndNodes(); @@ -730,7 +725,6 @@ void MooseMesh::buildBndElemList() { TIME_SECTION(_build_bnd_elem_list_timer); - CONSOLE_TIMED_PRINT("Building element lists"); freeBndElems(); @@ -760,7 +754,6 @@ MooseMesh::nodeToElemMap() if (!_node_to_elem_map_built) { TIME_SECTION(_node_to_elem_map_timer); - CONSOLE_TIMED_PRINT("Building node to element map"); for (const auto & elem : getMesh().active_element_ptr_range()) for (unsigned int n = 0; n < elem->n_nodes(); n++) @@ -781,7 +774,6 @@ MooseMesh::nodeToActiveSemilocalElemMap() Threads::spin_mutex::scoped_lock lock(Threads::spin_mtx); TIME_SECTION(_node_to_active_semilocal_elem_map_timer); - CONSOLE_TIMED_PRINT("Building active semilocal element map"); if (!_node_to_active_semilocal_elem_map_built) { @@ -805,7 +797,6 @@ MooseMesh::getActiveLocalElementRange() if (!_active_local_elem_range) { TIME_SECTION(_get_active_local_element_range_timer); - CONSOLE_TIMED_PRINT("Caching active local element range"); _active_local_elem_range = libmesh_make_unique( getMesh().active_local_elements_begin(), getMesh().active_local_elements_end(), GRAIN_SIZE); @@ -820,7 +811,6 @@ MooseMesh::getActiveNodeRange() if (!_active_node_range) { TIME_SECTION(_get_active_node_range_timer); - CONSOLE_TIMED_PRINT("Caching active node range"); _active_node_range = libmesh_make_unique( getMesh().active_nodes_begin(), getMesh().active_nodes_end(), GRAIN_SIZE); @@ -844,7 +834,6 @@ MooseMesh::getLocalNodeRange() if (!_local_node_range) { TIME_SECTION(_get_local_node_range_timer); - CONSOLE_TIMED_PRINT("Caching local node range"); _local_node_range = libmesh_make_unique( getMesh().local_nodes_begin(), getMesh().local_nodes_end(), GRAIN_SIZE); @@ -859,7 +848,6 @@ MooseMesh::getBoundaryNodeRange() if (!_bnd_node_range) { TIME_SECTION(_get_boundary_node_range_timer); - CONSOLE_TIMED_PRINT("Caching boundary node range"); _bnd_node_range = libmesh_make_unique(bndNodesBegin(), bndNodesEnd(), GRAIN_SIZE); @@ -874,7 +862,6 @@ MooseMesh::getBoundaryElementRange() if (!_bnd_elem_range) { TIME_SECTION(_get_boundary_element_range_timer); - CONSOLE_TIMED_PRINT("Caching boundary element range"); _bnd_elem_range = libmesh_make_unique(bndElemsBegin(), bndElemsEnd(), GRAIN_SIZE); @@ -893,7 +880,6 @@ void MooseMesh::cacheInfo() { TIME_SECTION(_cache_info_timer); - CONSOLE_TIMED_PRINT("Caching mesh information"); _subdomain_boundary_ids.clear(); _neighbor_subdomain_boundary_ids.clear(); @@ -2186,7 +2172,6 @@ MooseMesh::init() // sub-apps need to just build their mesh like normal { TIME_SECTION(_read_recovered_mesh_timer); - CONSOLE_TIMED_PRINT("Rcovering mesh"); getMesh().read(_app.getRestartRecoverFileBase() + "_mesh." + _app.getRestartRecoverFileSuffix()); } @@ -2196,7 +2181,6 @@ MooseMesh::init() } else // Normally just build the mesh { - CONSOLE_TIMED_PRINT("Building mesh"); buildMesh(); } } diff --git a/framework/src/problems/FEProblemBase.C b/framework/src/problems/FEProblemBase.C index e6eb4b6fb7c4..d98aef7a1fe3 100644 --- a/framework/src/problems/FEProblemBase.C +++ b/framework/src/problems/FEProblemBase.C @@ -286,26 +286,26 @@ FEProblemBase::FEProblemBase(const InputParameters & parameters) _fail_next_linear_convergence_check(false), _started_initial_setup(false), _has_internal_edge_residual_objects(false), - _initial_setup_timer(registerTimedSection("initialSetup", 2)), - _project_solution_timer(registerTimedSection("projectSolution", 2)), - _compute_indicators_timer(registerTimedSection("computeIndicators", 1)), - _compute_markers_timer(registerTimedSection("computeMarkers", 1)), - _compute_user_objects_timer(registerTimedSection("computeUserObjects", 1)), - _execute_controls_timer(registerTimedSection("executeControls", 1)), - _execute_samplers_timer(registerTimedSection("executeSamplers", 1)), - _update_active_objects_timer(registerTimedSection("updateActiveObjects", 5)), + _initial_setup_timer(registerTimedSection("initialSetup", 2, "Performing Initial Setup")), + _project_solution_timer(registerTimedSection("projectSolution", 2, "Projecting Initial Solutions")), + _compute_indicators_timer(registerTimedSection("computeIndicators", 1, "Computing Indicators")), + _compute_markers_timer(registerTimedSection("computeMarkers", 1, "Computing Markers")), + _compute_user_objects_timer(registerTimedSection("computeUserObjects", 1, "Computing User Objects")), + _execute_controls_timer(registerTimedSection("executeControls", 1, "Executing Controls")), + _execute_samplers_timer(registerTimedSection("executeSamplers", 1, "Executing Samplers")), + _update_active_objects_timer(registerTimedSection("updateActiveObjects", 5, "Updating Active Objects")), _reinit_because_of_ghosting_or_new_geom_objects_timer( - registerTimedSection("reinitBecauseOfGhostingOrNewGeomObjects", 3)), - _exec_multi_app_transfers_timer(registerTimedSection("execMultiAppTransfers", 1)), - _init_timer(registerTimedSection("init", 2)), - _eq_init_timer(registerTimedSection("EquationSystems::Init", 2)), - _solve_timer(registerTimedSection("solve", 1)), + registerTimedSection("reinitBecauseOfGhostingOrNewGeomObjects", 3, "Reinitializing Because of Geometric Search Objects")), + _exec_multi_app_transfers_timer(registerTimedSection("execMultiAppTransfers", 1, "Executing Transfers")), + _init_timer(registerTimedSection("init", 2, "Initializing")), + _eq_init_timer(registerTimedSection("EquationSystems::Init", 2, "Initializing Equation Systems")), + _solve_timer(registerTimedSection("solve", 1, "Solving", false)), _check_exception_and_stop_solve_timer(registerTimedSection("checkExceptionAndStopSolve", 5)), _advance_state_timer(registerTimedSection("advanceState", 5)), _restore_solutions_timer(registerTimedSection("restoreSolutions", 5)), _save_old_solutions_timer(registerTimedSection("saveOldSolutions", 5)), _restore_old_solutions_timer(registerTimedSection("restoreOldSolutions", 5)), - _output_step_timer(registerTimedSection("outputStep", 1)), + _output_step_timer(registerTimedSection("outputStep", 1, "Outputting", false)), _on_timestep_begin_timer(registerTimedSection("onTimestepBegin", 2)), _compute_residual_l2_norm_timer(registerTimedSection("computeResidualL2Norm", 2)), _compute_residual_sys_timer(registerTimedSection("computeResidualSys", 5)), @@ -322,18 +322,18 @@ FEProblemBase::FEProblemBase(const InputParameters & parameters) _compute_damping_timer(registerTimedSection("computeDamping", 1)), _possibly_rebuild_geom_search_patches_timer( registerTimedSection("possiblyRebuildGeomSearchPatches", 5)), - _initial_adapt_mesh_timer(registerTimedSection("initialAdaptMesh", 2)), - _adapt_mesh_timer(registerTimedSection("adaptMesh", 3)), - _update_mesh_xfem_timer(registerTimedSection("updateMeshXFEM", 5)), - _mesh_changed_timer(registerTimedSection("meshChanged", 3)), + _initial_adapt_mesh_timer(registerTimedSection("initialAdaptMesh", 2, "Performing Initial Adaptivity")), + _adapt_mesh_timer(registerTimedSection("adaptMesh", 3, "Adapting Mesh")), + _update_mesh_xfem_timer(registerTimedSection("updateMeshXFEM", 5, "Updating XFEM")), + _mesh_changed_timer(registerTimedSection("meshChanged", 3, "Handling Mesh Changes")), _mesh_changed_helper_timer(registerTimedSection("meshChangedHelper", 5)), _check_problem_integrity_timer(registerTimedSection("notifyWhenMeshChanges", 5)), - _serialize_solution_timer(registerTimedSection("serializeSolution", 3)), - _check_nonlinear_convergence_timer(registerTimedSection("checkNonlinearConvergence", 5)), - _check_linear_convergence_timer(registerTimedSection("checkLinearConvergence", 5)), - _update_geometric_search_timer(registerTimedSection("updateGeometricSearch", 3)), - _exec_multi_apps_timer(registerTimedSection("execMultiApps", 1)), - _backup_multi_apps_timer(registerTimedSection("backupMultiApps", 5)), + _serialize_solution_timer(registerTimedSection("serializeSolution", 3, "Serializing Solution")), + _check_nonlinear_convergence_timer(registerTimedSection("checkNonlinearConvergence", 5, "Checking Nonlinear Convergence")), + _check_linear_convergence_timer(registerTimedSection("checkLinearConvergence", 5, "Checking Linear Convergence")), + _update_geometric_search_timer(registerTimedSection("updateGeometricSearch", 3, "Updating Geometric Search")), + _exec_multi_apps_timer(registerTimedSection("execMultiApps", 1, "Executing MultiApps", false)), + _backup_multi_apps_timer(registerTimedSection("backupMultiApps", 5, "Backing Up MultiApp")), _u_dot_requested(false), _u_dotdot_requested(false), _u_dot_old_requested(false), diff --git a/framework/src/utils/PerfGraph.C b/framework/src/utils/PerfGraph.C index 35ed70d82a5a..1831ccd8b915 100644 --- a/framework/src/utils/PerfGraph.C +++ b/framework/src/utils/PerfGraph.C @@ -35,7 +35,7 @@ PerfGraph::PerfGraph(const std::string & root_name, MooseApp & app) auto & execution_list = this->_execution_list; - auto & id_to_section_name = this->_id_to_section_name; + auto & id_to_section_info = this->_id_to_section_info; // This is one beyond the last thing on the stack unsigned int stack_level = 0; @@ -72,6 +72,10 @@ PerfGraph::PerfGraph(const std::string & root_name, MooseApp & app) // reads, will be reading synchronized memory std::atomic_thread_fence(std::memory_order_acquire); + // Only happens if nothing has been added + if (current_execution_list_end == 0 && last_execution_list_end == current_execution_list_end) + continue; + // Iterate from the last thing printed (begin) to the last thing in the list (end) // If the time or memory of any section is above the threshold, print everything inbetween and // update begin @@ -89,31 +93,36 @@ PerfGraph::PerfGraph(const std::string & root_name, MooseApp & app) // We need to print out everything on the stack before this that hasn't already been printed... for (unsigned int s = printed_stack_level_end; s < stack_level - 1; s++) { - console << std::string(s * 2, ' ') << id_to_section_name[print_thread_stack[s]._id] << '\n'; + console << std::string(s * 2, ' ') << id_to_section_info[print_thread_stack[s]._id]._live_message << '\n'; printed_stack_level_end++; } - console << std::string(2 * (stack_level -1), ' ') << id_to_section_name[last_section_increment._id]; + console << std::string(2 * (stack_level -1), ' ') << id_to_section_info[last_section_increment._id]._live_message; printed_name_of_current_section = true; printed_stack_level_end++; } else // Need to print dots - console << " ."; + if (id_to_section_info[last_section_increment._id]._print_dots) + console << " ."; } else // If it's not, then we need to continue the section _before_ this { - auto & last_stack_section = print_thread_stack[stack_level - 1]; - - if (!printed_name_of_current_section) + if (stack_level > 0) { - console << "Still " << id_to_section_name[last_stack_section._id]; + auto & last_stack_section = print_thread_stack[stack_level - 1]; - printed_name_of_current_section = true; + if (!printed_name_of_current_section) + { + console << "Still " << id_to_section_info[last_stack_section._id]._live_message; + + printed_name_of_current_section = true; + } + else // Need to print dots + if (id_to_section_info[last_stack_section._id]._print_dots) + console << " ."; } - else // Need to print dots - console << " ."; } } @@ -161,13 +170,13 @@ PerfGraph::PerfGraph(const std::string & root_name, MooseApp & app) printed_name_of_current_section = false; } - console << std::string(s * 2, ' ') << id_to_section_name[print_thread_stack[s]._id] << '\n'; + console << std::string(s * 2, ' ') << id_to_section_info[print_thread_stack[s]._id]._live_message << '\n'; printed_stack_level_end++; } // Now print this thing - if (!printed_name_of_current_section) - console << std::string(2 * (stack_level - 1), ' ') << "Finishing: " << id_to_section_name[section_increment._id]; + if (!printed_name_of_current_section || !id_to_section_info[section_increment._id]._print_dots) + console << std::string(2 * (stack_level - 1), ' ') << "Finishing: " << id_to_section_info[section_increment._id]._live_message; console << ": " << time_increment << ", " << memory_increment << '\n'; @@ -218,8 +227,44 @@ PerfGraph::registerSection(const std::string & section_name, unsigned int level) // It's not... auto id = _section_name_to_id.size(); _section_name_to_id.emplace_hint(it, section_name, id); - _id_to_section_name[id] = section_name; - _id_to_level[id] = level; + + auto & section_info = _id_to_section_info[id]; + + section_info._id = id; + section_info._name = section_name; + section_info._level = level; + section_info._live_message = ""; + section_info._print_dots = false; + + return id; +} + +PerfID +PerfGraph::registerSection(const std::string & section_name, unsigned int level, const std::string & live_message, const bool print_dots) +{ + if (section_name == "") + mooseError("Section name not provided when registering timed section!"); + + if (live_message == "") + mooseError("Live message not provided when registering timed section!"); + + auto it = _section_name_to_id.lower_bound(section_name); + + // Is it already registered? + if (it != _section_name_to_id.end() && it->first == section_name) + return it->second; + + // It's not... + auto id = _section_name_to_id.size(); + _section_name_to_id.emplace_hint(it, section_name, id); + + auto & section_info = _id_to_section_info[id]; + + section_info._id = id; + section_info._name = section_name; + section_info._level = level; + section_info._live_message = live_message; + section_info._print_dots = print_dots; return id; } @@ -227,12 +272,12 @@ PerfGraph::registerSection(const std::string & section_name, unsigned int level) const std::string & PerfGraph::sectionName(const PerfID id) const { - auto find_it = _id_to_section_name.find(id); + auto find_it = _id_to_section_info.find(id); - if (find_it == _id_to_section_name.end()) + if (find_it == _id_to_section_info.end()) mooseError("PerfGraph cannot find a section name associated with id: ", id); - return find_it->second; + return find_it->second._name; } unsigned long int @@ -326,7 +371,8 @@ PerfGraph::push(const PerfID id) _stack[_current_position] = new_node; // Add this to the exection list - addToExecutionList(id, IncrementState::started, current_time, start_memory); + if (!_id_to_section_info[id]._live_message.empty()) + addToExecutionList(id, IncrementState::started, current_time, start_memory); } void @@ -349,7 +395,8 @@ PerfGraph::pop() _current_position--; // Add this to the exection list - addToExecutionList(current_node->id(), IncrementState::finished, current_time, current_memory); + if (!_id_to_section_info[current_node->id()]._live_message.empty()) + addToExecutionList(current_node->id(), IncrementState::finished, current_time, current_memory); } void @@ -389,7 +436,7 @@ PerfGraph::updateTiming() // Update vector pointing to section times // Note: we are doing this _after_ recursively filling // because new entries may have been created - _section_time_ptrs.resize(_id_to_section_name.size()); + _section_time_ptrs.resize(_id_to_section_info.size()); for (auto & section_time_it : _section_time) { @@ -414,7 +461,7 @@ PerfGraph::recursivelyFillTime(PerfNode * current_node) auto total_memory = current_node->totalMemory(); // RHS insertion on purpose - auto & section_time = _section_time[_id_to_section_name[id]]; + auto & section_time = _section_time[_id_to_section_info[id]._name]; section_time._self += self; section_time._children += children; @@ -435,13 +482,13 @@ PerfGraph::recursivelyPrintGraph(PerfNode * current_node, unsigned int level, unsigned int current_depth) { - mooseAssert(_id_to_section_name.find(current_node->id()) != _id_to_section_name.end(), + mooseAssert(_id_to_section_info.find(current_node->id()) != _id_to_section_info.end(), "Unable to find section name!"); - auto & name = current_node->id() == 0 ? _root_name : _id_to_section_name[current_node->id()]; + auto & name = current_node->id() == 0 ? _root_name : _id_to_section_info[current_node->id()]._name; - mooseAssert(_id_to_level.find(current_node->id()) != _id_to_level.end(), "Unable to find level!"); - auto & node_level = _id_to_level[current_node->id()]; + mooseAssert(_id_to_section_info.find(current_node->id()) != _id_to_section_info.end(), "Unable to find level!"); + auto & node_level = _id_to_section_info[current_node->id()]._level; if (node_level <= level) { @@ -458,9 +505,9 @@ PerfGraph::recursivelyPrintGraph(PerfNode * current_node, auto self_avg = self / static_cast(num_calls); auto self_percent = 100. * self / total_root_time; - auto children = std::chrono::duration(current_node->childrenTime()).count(); - auto children_avg = children / static_cast(num_calls); - auto children_percent = 100. * children / total_root_time; +// auto children = std::chrono::duration(current_node->childrenTime()).count(); +// auto children_avg = children / static_cast(num_calls); +// auto children_percent = 100. * children / total_root_time; auto total = std::chrono::duration(current_node->totalTime()).count(); auto total_avg = total / static_cast(num_calls); @@ -498,7 +545,7 @@ PerfGraph::recursivelyPrintHeaviestGraph(PerfNode * current_node, mooseAssert(!_section_time_ptrs.empty(), "updateTiming() must be run before recursivelyPrintGraph!"); - auto & name = current_node->id() == 0 ? _root_name : _id_to_section_name[current_node->id()]; + auto & name = current_node->id() == 0 ? _root_name : _id_to_section_info[current_node->id()]._name; auto section = std::string(current_depth * 2, ' ') + name; @@ -510,9 +557,9 @@ PerfGraph::recursivelyPrintHeaviestGraph(PerfNode * current_node, auto self_avg = self / static_cast(num_calls); auto self_percent = 100. * self / total_root_time; - auto children = std::chrono::duration(current_node->childrenTime()).count(); - auto children_avg = children / static_cast(num_calls); - auto children_percent = 100. * children / total_root_time; +// auto children = std::chrono::duration(current_node->childrenTime()).count(); +// auto children_avg = children / static_cast(num_calls); +// auto children_percent = 100. * children / total_root_time; auto total = std::chrono::duration(current_node->totalTime()).count(); auto total_avg = total / static_cast(num_calls); @@ -705,7 +752,7 @@ PerfGraph::printHeaviestSections(const ConsoleStream & console, const unsigned i { auto id = sorted[i]; - vtable.addRow(id == 0 ? _root_name : _id_to_section_name[id], + vtable.addRow(id == 0 ? _root_name : _id_to_section_info[id]._name, _section_time_ptrs[id]->_num_calls, _section_time_ptrs[id]->_total_memory, _section_time_ptrs[id]->_self,