Geometry Nodes: Node execution time overlay

Adds a new overlay called "Timings" to the Geometry Node editor.
This shows the node execution time in milliseconds above the node.
For group nodes and frames, the total time for all nodes inside
(recursively) is shown. Group output node shows the node tree total.
The code is prepared for easily adding new rows of information
to the box above the node in the future.

Differential Revision: https://developer.blender.org/D13256

8 files changed, 285 insertions, 2 deletions

diff --git a/source/blender/editors/space_node/drawnode.cc b/source/blender/editors/space_node/drawnode.cc
index cf79893a8cb..97fa93ab0bc 100644
--- a/source/blender/editors/space_node/drawnode.cc
+++ b/source/blender/editors/space_node/drawnode.cc
@@ -337,8 +337,9 @@ static void node_draw_frame_prepare(const bContext *UNUSED(C), bNodeTree *ntree,
   node->totr = rect;
 }
 
-static void node_draw_frame_label(bNodeTree *ntree, bNode *node, const float aspect)
+static void node_draw_frame_label(bNodeTree *ntree, bNode *node, SpaceNode *snode)
 {
+  const float aspect = snode->runtime->aspect;
   /* XXX font id is crap design */
   const int fontid = UI_style_get()->widgetlabel.uifont_id;
   NodeFrame *data = (NodeFrame *)node->storage;
@@ -468,7 +469,9 @@ static void node_draw_frame(const bContext *C,
   }
 
   /* label and text */
-  node_draw_frame_label(ntree, node, snode->runtime->aspect);
+  node_draw_frame_label(ntree, node, snode);
+
+  node_draw_extra_info_panel(snode, node);
 
   UI_block_end(C, node->block);
   UI_block_draw(C, node->block);
diff --git a/source/blender/editors/space_node/node_draw.cc b/source/blender/editors/space_node/node_draw.cc
index f9a9e491403..1aa6ec4e56c 100644
--- a/source/blender/editors/space_node/node_draw.cc
+++ b/source/blender/editors/space_node/node_draw.cc
@@ -87,6 +87,8 @@
 
 #include "node_intern.hh" /* own include */
 
+#include <iomanip>
+
 #ifdef WITH_COMPOSITOR
 #  include "COM_compositor.h"
 #endif
@@ -1577,6 +1579,237 @@ static void node_add_error_message_button(
   UI_block_emboss_set(node.block, UI_EMBOSS);
 }
 
+static void get_exec_time_other_nodes(const bNode *node,
+                                      const SpaceNode *snode,
+                                      std::chrono::microseconds &exec_time,
+                                      int &node_count)
+{
+  if (node->type == NODE_GROUP) {
+    const geo_log::TreeLog *root_tree_log = geo_log::ModifierLog::find_tree_by_node_editor_context(
+        *snode);
+    if (root_tree_log == nullptr) {
+      return;
+    }
+    const geo_log::TreeLog *tree_log = root_tree_log->lookup_child_log(node->name);
+    if (tree_log == nullptr) {
+      return;
+    }
+    tree_log->foreach_node_log([&](const geo_log::NodeLog &node_log) {
+      exec_time += node_log.execution_time();
+      node_count++;
+    });
+  }
+  else {
+    const geo_log::NodeLog *node_log = geo_log::ModifierLog::find_node_by_node_editor_context(
+        *snode, *node);
+    if (node_log) {
+      exec_time += node_log->execution_time();
+      node_count++;
+    }
+  }
+}
+
+static std::chrono::microseconds node_get_execution_time(const bNodeTree *ntree,
+                                                         const bNode *node,
+                                                         const SpaceNode *snode,
+                                                         int &node_count)
+{
+  std::chrono::microseconds exec_time = std::chrono::microseconds::zero();
+  if (node->type == NODE_GROUP_OUTPUT) {
+    const geo_log::TreeLog *tree_log = geo_log::ModifierLog::find_tree_by_node_editor_context(
+        *snode);
+
+    if (tree_log == nullptr) {
+      return exec_time;
+    }
+    tree_log->foreach_node_log([&](const geo_log::NodeLog &node_log) {
+      exec_time += node_log.execution_time();
+      node_count++;
+    });
+  }
+  else if (node->type == NODE_FRAME) {
+    /* Could be cached in the future if this recursive code turns out to be slow. */
+    LISTBASE_FOREACH (bNode *, tnode, &ntree->nodes) {
+      if (tnode->parent != node) {
+        continue;
+      }
+
+      if (tnode->type == NODE_FRAME) {
+        exec_time += node_get_execution_time(ntree, tnode, snode, node_count);
+      }
+      else {
+        get_exec_time_other_nodes(tnode, snode, exec_time, node_count);
+      }
+    }
+  }
+  else {
+    get_exec_time_other_nodes(node, snode, exec_time, node_count);
+  }
+  return exec_time;
+}
+
+static std::string node_get_execution_time_label(const SpaceNode *snode, const bNode *node)
+{
+  int node_count = 0;
+  std::chrono::microseconds exec_time = node_get_execution_time(
+      snode->nodetree, node, snode, node_count);
+
+  if (node_count == 0) {
+    return std::string("");
+  }
+
+  uint64_t exec_time_us = exec_time.count();
+
+  /* Don't show time if execution time is 0 microseconds. */
+  if (exec_time_us == 0) {
+    return std::string("-");
+  }
+  else if (exec_time_us < 100) {
+    return std::string("< 0.1 ms");
+  }
+  else {
+    short precision = 0;
+    /* Show decimal if value is below 1ms */
+    if (exec_time_us < 1000) {
+      precision = 2;
+    }
+    else if (exec_time_us < 10000) {
+      precision = 1;
+    }
+
+    std::stringstream stream;
+    stream << std::fixed << std::setprecision(precision) << (exec_time_us / 1000.0f);
+    return std::string(stream.str() + " ms");
+  }
+  return std::string("");
+}
+
+struct NodeExtraInfoRow {
+  std::string text;
+  const char *tooltip;
+  int icon;
+};
+
+static Vector<NodeExtraInfoRow> node_get_extra_info(const SpaceNode *snode, const bNode *node)
+{
+  Vector<NodeExtraInfoRow> rows;
+  if (!(snode->overlay.flag & SN_OVERLAY_SHOW_OVERLAYS)) {
+    return rows;
+  }
+
+  if (snode->overlay.flag & SN_OVERLAY_SHOW_TIMINGS && snode->edittree->type == NTREE_GEOMETRY &&
+      (ELEM(node->typeinfo->nclass, NODE_CLASS_GEOMETRY, NODE_CLASS_GROUP, NODE_CLASS_ATTRIBUTE) ||
+       ELEM(node->type, NODE_FRAME, NODE_GROUP_OUTPUT))) {
+    NodeExtraInfoRow row;
+    row.text = node_get_execution_time_label(snode, node);
+    if (!row.text.empty()) {
+      row.tooltip = TIP_(
+          "The execution time from the node tree's latest evaluation. For frame and group nodes, "
+          "the time for all sub-nodes");
+      row.icon = ICON_PREVIEW_RANGE;
+      rows.append(std::move(row));
+    }
+  }
+  return rows;
+}
+
+static void node_draw_extra_info_row(const bNode *node,
+                                     const rctf *rect,
+                                     const int row,
+                                     const NodeExtraInfoRow &extra_info_row)
+{
+  uiBut *but_timing = uiDefBut(node->block,
+                               UI_BTYPE_LABEL,
+                               0,
+                               extra_info_row.text.c_str(),
+                               (int)(rect->xmin + 4.0f * U.dpi_fac + NODE_MARGIN_X + 0.4f),
+                               (int)(rect->ymin + row * (20.0f * U.dpi_fac)),
+                               (short)(rect->xmax - rect->xmin),
+                               (short)NODE_DY,
+                               nullptr,
+                               0,
+                               0,
+                               0,
+                               0,
+                               "");
+  UI_block_emboss_set(node->block, UI_EMBOSS_NONE);
+  uiBut *but_icon = uiDefIconBut(node->block,
+                                 UI_BTYPE_BUT,
+                                 0,
+                                 extra_info_row.icon,
+                                 (int)(rect->xmin + 6.0f * U.dpi_fac),
+                                 (int)(rect->ymin + row * (20.0f * U.dpi_fac)),
+                                 NODE_HEADER_ICON_SIZE * 0.8f,
+                                 UI_UNIT_Y,
+                                 nullptr,
+                                 0,
+                                 0,
+                                 0,
+                                 0,
+                                 extra_info_row.tooltip);
+  UI_block_emboss_set(node->block, UI_EMBOSS);
+  if (node->flag & NODE_MUTED) {
+    UI_but_flag_enable(but_timing, UI_BUT_INACTIVE);
+    UI_but_flag_enable(but_icon, UI_BUT_INACTIVE);
+  }
+}
+
+void node_draw_extra_info_panel(const SpaceNode *snode, const bNode *node)
+{
+  Vector<NodeExtraInfoRow> extra_info_rows = node_get_extra_info(snode, node);
+
+  if (extra_info_rows.size() == 0) {
+    return;
+  }
+
+  const rctf *rct = &node->totr;
+  float color[4];
+  rctf extra_info_rect;
+
+  if (node->type == NODE_FRAME) {
+    extra_info_rect.xmin = rct->xmin;
+    extra_info_rect.xmax = rct->xmin + 95.0f * U.dpi_fac;
+    extra_info_rect.ymin = rct->ymin + 2.0f * U.dpi_fac;
+    extra_info_rect.ymax = rct->ymin + 2.0f * U.dpi_fac;
+  }
+  else {
+    extra_info_rect.xmin = rct->xmin + 3.0f * U.dpi_fac;
+    extra_info_rect.xmax = rct->xmin + 95.0f * U.dpi_fac;
+    extra_info_rect.ymin = rct->ymax;
+    extra_info_rect.ymax = rct->ymax + extra_info_rows.size() * (20.0f * U.dpi_fac);
+
+    if (node->flag & NODE_MUTED) {
+      UI_GetThemeColorBlend4f(TH_BACK, TH_NODE, 0.2f, color);
+    }
+    else {
+      UI_GetThemeColorBlend4f(TH_BACK, TH_NODE, 0.75f, color);
+    }
+    color[3] -= 0.35f;
+    UI_draw_roundbox_corner_set(
+        UI_CNR_ALL & ~UI_CNR_BOTTOM_LEFT &
+        ((rct->xmax) > extra_info_rect.xmax ? ~UI_CNR_BOTTOM_RIGHT : UI_CNR_ALL));
+    UI_draw_roundbox_4fv(&extra_info_rect, true, BASIS_RAD, color);
+
+    /* Draw outline. */
+    const float outline_width = 1.0f;
+    extra_info_rect.xmin = rct->xmin + 3.0f * U.dpi_fac - outline_width;
+    extra_info_rect.xmax = rct->xmin + 95.0f * U.dpi_fac + outline_width;
+    extra_info_rect.ymin = rct->ymax - outline_width;
+    extra_info_rect.ymax = rct->ymax + outline_width +
+                           extra_info_rows.size() * (20.0f * U.dpi_fac);
+
+    UI_GetThemeColorBlendShade4fv(TH_BACK, TH_NODE, 0.4f, -20, color);
+    UI_draw_roundbox_corner_set(
+        UI_CNR_ALL & ~UI_CNR_BOTTOM_LEFT &
+        ((rct->xmax) > extra_info_rect.xmax ? ~UI_CNR_BOTTOM_RIGHT : UI_CNR_ALL));
+    UI_draw_roundbox_4fv(&extra_info_rect, false, BASIS_RAD, color);
+  }
+
+  for (int row : extra_info_rows.index_range()) {
+    node_draw_extra_info_row(node, &extra_info_rect, row, extra_info_rows[row]);
+  }
+}
+
 static void node_draw_basis(const bContext *C,
                             const View2D *v2d,
                             const SpaceNode *snode,
@@ -1602,6 +1835,8 @@ static void node_draw_basis(const bContext *C,
 
   GPU_line_width(1.0f);
 
+  node_draw_extra_info_panel(snode, node);
+
   /* Header. */
   {
     const rctf rect = {
diff --git a/source/blender/editors/space_node/node_intern.hh b/source/blender/editors/space_node/node_intern.hh
index 2e973def867..6dc57c1fb79 100644
--- a/source/blender/editors/space_node/node_intern.hh
+++ b/source/blender/editors/space_node/node_intern.hh
@@ -96,6 +96,7 @@ void node_link_calculate_multi_input_position(const float socket_x,
                                               float r[2]);
 
 int node_get_colorid(bNode *node);
+void node_draw_extra_info_panel(const SpaceNode *snode, const bNode *node);
 int node_get_resize_cursor(int directions);
 void node_draw_shadow(const SpaceNode *snode, const bNode *node, float radius, float alpha);
 void node_draw_default(const bContext *C,
diff --git a/source/blender/makesdna/DNA_space_types.h b/source/blender/makesdna/DNA_space_types.h
index 7fb15fc8508..88c5ace9cb3 100644
--- a/source/blender/makesdna/DNA_space_types.h
+++ b/source/blender/makesdna/DNA_space_types.h
@@ -1520,6 +1520,7 @@ typedef struct SpaceNodeOverlay {
 typedef enum eSpaceNodeOverlay_Flag {
   SN_OVERLAY_SHOW_OVERLAYS = (1 << 1),
   SN_OVERLAY_SHOW_WIRE_COLORS = (1 << 2),
+  SN_OVERLAY_SHOW_TIMINGS = (1 << 3),
 } eSpaceNodeOverlay_Flag;
 
 typedef struct SpaceNode {
diff --git a/source/blender/makesrna/intern/rna_space.c b/source/blender/makesrna/intern/rna_space.c
index e7bcd387eaf..8f04524c5c1 100644
--- a/source/blender/makesrna/intern/rna_space.c
+++ b/source/blender/makesrna/intern/rna_space.c
@@ -7110,6 +7110,12 @@ static void rna_def_space_node_overlay(BlenderRNA *brna)
   RNA_def_property_ui_text(
       prop, "Show Wire Colors", "Color node links based on their connected sockets");
   RNA_def_property_update(prop, NC_SPACE | ND_SPACE_NODE, NULL);
+
+  prop = RNA_def_property(srna, "show_timing", PROP_BOOLEAN, PROP_NONE);
+  RNA_def_property_boolean_sdna(prop, NULL, "overlay.flag", SN_OVERLAY_SHOW_TIMINGS);
+  RNA_def_property_boolean_default(prop, false);
+  RNA_def_property_ui_text(prop, "Show Timing", "Display each node's last execution time");
+  RNA_def_property_update(prop, NC_SPACE | ND_SPACE_NODE, NULL);
 }
 
 static void rna_def_space_node(BlenderRNA *brna)
diff --git a/source/blender/modifiers/intern/MOD_nodes_evaluator.cc b/source/blender/modifiers/intern/MOD_nodes_evaluator.cc
index 4d081450fd8..e23c494f7cf 100644
--- a/source/blender/modifiers/intern/MOD_nodes_evaluator.cc
+++ b/source/blender/modifiers/intern/MOD_nodes_evaluator.cc
@@ -35,6 +35,8 @@
 #include "BLI_task.hh"
 #include "BLI_vector_set.hh"
 
+#include <chrono>
+
 namespace blender::modifiers::geometry_nodes {
 
 using fn::CPPType;
@@ -929,7 +931,13 @@ class GeometryNodesEvaluator {
       params.error_message_add(geo_log::NodeWarningType::Legacy,
                                TIP_("Legacy node will be removed before Blender 4.0"));
     }
+    using Clock = std::chrono::steady_clock;
+    Clock::time_point begin = Clock::now();
     bnode.typeinfo->geometry_node_execute(params);
+    Clock::time_point end = Clock::now();
+    const std::chrono::microseconds duration =
+        std::chrono::duration_cast<std::chrono::microseconds>(end - begin);
+    params_.geo_logger->local().log_execution_time(node, duration);
   }
 
   void execute_multi_function_node(const DNode node,
diff --git a/source/blender/nodes/NOD_geometry_nodes_eval_log.hh b/source/blender/nodes/NOD_geometry_nodes_eval_log.hh
index 2a118057a03..0fbc1803db6 100644
--- a/source/blender/nodes/NOD_geometry_nodes_eval_log.hh
+++ b/source/blender/nodes/NOD_geometry_nodes_eval_log.hh
@@ -41,6 +41,8 @@
 
 #include "NOD_derived_node_tree.hh"
 
+#include <chrono>
+
 struct SpaceNode;
 struct SpaceSpreadsheet;
 
@@ -169,6 +171,11 @@ struct NodeWithWarning {
   NodeWarning warning;
 };
 
+struct NodeWithExecutionTime {
+  DNode node;
+  std::chrono::microseconds exec_time;
+};
+
 /** The same value can be referenced by multiple sockets when they are linked. */
 struct ValueOfSockets {
   Span<DSocket> sockets;
@@ -189,6 +196,7 @@ class LocalGeoLogger {
   std::unique_ptr<LinearAllocator<>> allocator_;
   Vector<ValueOfSockets> values_;
   Vector<NodeWithWarning> node_warnings_;
+  Vector<NodeWithExecutionTime> node_exec_times_;
 
   friend ModifierLog;
 
@@ -201,6 +209,7 @@ class LocalGeoLogger {
   void log_value_for_sockets(Span<DSocket> sockets, GPointer value);
   void log_multi_value_socket(DSocket socket, Span<GPointer> values);
   void log_node_warning(DNode node, NodeWarningType type, std::string message);
+  void log_execution_time(DNode node, std::chrono::microseconds exec_time);
 };
 
 /** The root logger class. */
@@ -274,12 +283,14 @@ class NodeLog {
   Vector<SocketLog> input_logs_;
   Vector<SocketLog> output_logs_;
   Vector<NodeWarning, 0> warnings_;
+  std::chrono::microseconds exec_time_;
 
   friend ModifierLog;
 
  public:
   const SocketLog *lookup_socket_log(eNodeSocketInOut in_out, int index) const;
   const SocketLog *lookup_socket_log(const bNode &node, const bNodeSocket &socket) const;
+  void execution_time(std::chrono::microseconds exec_time);
 
   Span<SocketLog> input_logs() const
   {
@@ -296,6 +307,11 @@ class NodeLog {
     return warnings_;
   }
 
+  std::chrono::microseconds execution_time() const
+  {
+    return exec_time_;
+  }
+
   Vector<const GeometryAttributeInfo *> lookup_available_attributes() const;
 };
 
diff --git a/source/blender/nodes/intern/geometry_nodes_eval_log.cc b/source/blender/nodes/intern/geometry_nodes_eval_log.cc
index 782ab43336c..4cba9669647 100644
--- a/source/blender/nodes/intern/geometry_nodes_eval_log.cc
+++ b/source/blender/nodes/intern/geometry_nodes_eval_log.cc
@@ -25,6 +25,8 @@
 
 #include "BLT_translation.h"
 
+#include <chrono>
+
 namespace blender::nodes::geometry_nodes_eval_log {
 
 using fn::CPPType;
@@ -64,6 +66,12 @@ ModifierLog::ModifierLog(GeoLogger &logger)
                                                        node_with_warning.node);
       node_log.warnings_.append(node_with_warning.warning);
     }
+
+    for (NodeWithExecutionTime &node_with_exec_time : local_logger.node_exec_times_) {
+      NodeLog &node_log = this->lookup_or_add_node_log(log_by_tree_context,
+                                                       node_with_exec_time.node);
+      node_log.exec_time_ = node_with_exec_time.exec_time;
+    }
   }
 }
 
@@ -471,4 +479,9 @@ void LocalGeoLogger::log_node_warning(DNode node, NodeWarningType type, std::str
   node_warnings_.append({node, {type, std::move(message)}});
 }
 
+void LocalGeoLogger::log_execution_time(DNode node, std::chrono::microseconds exec_time)
+{
+  node_exec_times_.append({node, exec_time});
+}
+
 }  // namespace blender::nodes::geometry_nodes_eval_log