From 21a24cf82b430afbb88e8f0468c0692fa36d0137 Mon Sep 17 00:00:00 2001 From: Jacques Lucke Date: Mon, 21 Oct 2024 14:13:23 +0200 Subject: [PATCH] Fix #129263: improve measured node execution times Measure the times of nodes and zones more explicitly in more cases instead of relying on adding up smaller measurements. --- .../nodes/NOD_geometry_nodes_lazy_function.hh | 28 +++++++++++++++++ .../intern/geometry_nodes_lazy_function.cc | 30 +++++-------------- .../nodes/intern/geometry_nodes_log.cc | 12 -------- 3 files changed, 36 insertions(+), 34 deletions(-) diff --git a/source/blender/nodes/NOD_geometry_nodes_lazy_function.hh b/source/blender/nodes/NOD_geometry_nodes_lazy_function.hh index d63ee244e06..5134f4b421f 100644 --- a/source/blender/nodes/NOD_geometry_nodes_lazy_function.hh +++ b/source/blender/nodes/NOD_geometry_nodes_lazy_function.hh @@ -498,4 +498,32 @@ class ScopedComputeContextTimer { } }; +/** + * Utility to measure the time that is spend in a specific node during geometry nodes evaluation. + */ +class ScopedNodeTimer { + private: + const lf::Context &context_; + const bNode &node_; + geo_eval_log::TimePoint start_; + + public: + ScopedNodeTimer(const lf::Context &context, const bNode &node) : context_(context), node_(node) + { + start_ = geo_eval_log::Clock::now(); + } + + ~ScopedNodeTimer() + { + const geo_eval_log::TimePoint end = geo_eval_log::Clock::now(); + auto &user_data = static_cast(*context_.user_data); + auto &local_user_data = static_cast(*context_.local_user_data); + if (geo_eval_log::GeoTreeLogger *tree_logger = local_user_data.try_get_tree_logger(user_data)) + { + tree_logger->node_execution_times.append(*tree_logger->allocator, + {node_.identifier, start_, end}); + } + } +}; + } // namespace blender::nodes diff --git a/source/blender/nodes/intern/geometry_nodes_lazy_function.cc b/source/blender/nodes/intern/geometry_nodes_lazy_function.cc index b76a3d0320e..0659b21bea9 100644 --- a/source/blender/nodes/intern/geometry_nodes_lazy_function.cc +++ b/source/blender/nodes/intern/geometry_nodes_lazy_function.cc @@ -196,6 +196,8 @@ class LazyFunctionForGeometryNode : public LazyFunction { void execute_impl(lf::Params ¶ms, const lf::Context &context) const override { + const ScopedNodeTimer node_timer{context, node_}; + GeoNodesLFUserData *user_data = dynamic_cast(context.user_data); BLI_assert(user_data != nullptr); const auto &local_user_data = *static_cast(context.local_user_data); @@ -254,15 +256,7 @@ class LazyFunctionForGeometryNode : public LazyFunction { own_lf_graph_info_.mapping.lf_input_index_for_attribute_propagation_to_output, get_anonymous_attribute_name}; - geo_eval_log::TimePoint start_time = geo_eval_log::Clock::now(); node_.typeinfo->geometry_node_execute(geo_params); - geo_eval_log::TimePoint end_time = geo_eval_log::Clock::now(); - - if (geo_eval_log::GeoTreeLogger *tree_logger = local_user_data.try_get_tree_logger(*user_data)) - { - tree_logger->node_execution_times.append(*tree_logger->allocator, - {node_.identifier, start_time, end_time}); - } } std::string input_name(const int index) const override @@ -1133,6 +1127,7 @@ class LazyFunctionForGroupNode : public LazyFunction { void execute_impl(lf::Params ¶ms, const lf::Context &context) const override { + const ScopedNodeTimer node_timer{context, group_node_}; GeoNodesLFUserData *user_data = dynamic_cast(context.user_data); BLI_assert(user_data != nullptr); @@ -1476,6 +1471,7 @@ class LazyFunctionForSimulationZone : public LazyFunction { void execute_impl(lf::Params ¶ms, const lf::Context &context) const override { + ScopedNodeTimer node_timer{context, sim_output_bnode_}; GeoNodesLFUserData &user_data = *static_cast(context.user_data); bke::SimulationZoneComputeContext compute_context{user_data.compute_context, @@ -1488,8 +1484,6 @@ class LazyFunctionForSimulationZone : public LazyFunction { GeoNodesLFLocalUserData zone_local_user_data{zone_user_data}; lf::Context zone_context{context.storage, &zone_user_data, &zone_local_user_data}; - - ScopedComputeContextTimer timer(zone_context); fn_.execute(params, zone_context); } @@ -1745,8 +1739,6 @@ class RepeatBodyNodeExecuteWrapper : public lf::GraphExecutorNodeExecuteWrapper GeoNodesLFLocalUserData body_local_user_data{body_user_data}; lf::Context body_context{context.storage, &body_user_data, &body_local_user_data}; - - ScopedComputeContextTimer timer(body_context); fn.execute(params, body_context); } }; @@ -1839,6 +1831,8 @@ class LazyFunctionForRepeatZone : public LazyFunction { void execute_impl(lf::Params ¶ms, const lf::Context &context) const override { + const ScopedNodeTimer node_timer{context, repeat_output_bnode_}; + auto &user_data = *static_cast(context.user_data); auto &local_user_data = *static_cast(context.local_user_data); @@ -2397,6 +2391,8 @@ class LazyFunctionForForeachGeometryElementZone : public LazyFunction { void execute_impl(lf::Params ¶ms, const lf::Context &context) const override { + const ScopedNodeTimer node_timer{context, output_bnode_}; + auto &user_data = *static_cast(context.user_data); auto &local_user_data = *static_cast(context.local_user_data); @@ -2405,16 +2401,6 @@ class LazyFunctionForForeachGeometryElementZone : public LazyFunction { auto &eval_storage = *static_cast(context.storage); geo_eval_log::GeoTreeLogger *tree_logger = local_user_data.try_get_tree_logger(user_data); - /* Measure execution time of the entire zone. */ - const geo_eval_log::TimePoint start_time = geo_eval_log::Clock::now(); - BLI_SCOPED_DEFER([&]() { - if (tree_logger) { - const geo_eval_log::TimePoint end_time = geo_eval_log::Clock::now(); - tree_logger->node_execution_times.append(*tree_logger->allocator, - {output_bnode_.identifier, start_time, end_time}); - } - }); - if (!eval_storage.graph_executor) { /* Create the execution graph in the first evaluation. */ this->initialize_execution_graph(params, eval_storage, node_storage); diff --git a/source/blender/nodes/intern/geometry_nodes_log.cc b/source/blender/nodes/intern/geometry_nodes_log.cc index 300479c26d2..013bb88fa98 100644 --- a/source/blender/nodes/intern/geometry_nodes_log.cc +++ b/source/blender/nodes/intern/geometry_nodes_log.cc @@ -351,18 +351,6 @@ void GeoTreeLog::ensure_execution_times() } this->execution_time += tree_logger->execution_time; } - for (const ComputeContextHash &child_hash : children_hashes_) { - GeoTreeLog &child_log = modifier_log_->get_tree_log(child_hash); - if (child_log.tree_loggers_.is_empty()) { - continue; - } - child_log.ensure_execution_times(); - const std::optional &parent_node_id = child_log.tree_loggers_[0]->parent_node_id; - if (parent_node_id.has_value()) { - this->nodes.lookup_or_add_default(*parent_node_id).execution_time += - child_log.execution_time; - } - } reduced_execution_times_ = true; }