blender
/
blender
127
395
Fork 566
Code Issues 6.2k Pull Requests 751 Projects 19 Wiki Activity

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
This commit is contained in:
Erik Abrahamsson 2021-11-23 17:37:31 +01:00
parent fab39440e9
commit e4986f92f3
Notes: blender-bot 2023-02-14 02:13:08 +01:00 
Referenced by issue #93345, Segmentation Fault When Initiating Render of Geometry-Nodes-Generated Geometry
Referenced by issue #92982, Display the execution time of nodes
9 changed files with 289 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
release/scripts/startup/bl_ui/space_node.py
View File

@ -721,6 +721,10 @@ class NODE_PT_overlay(Panel):
col.prop(snode, "show_annotation", text="Annotations")
if snode.tree_type == 'GeometryNodeTree':
col.separator()
col.prop(overlay, "show_timing", text="Timings")
class NODE_UL_interface_sockets(bpy.types.UIList):
def draw_item(self, context, layout, _data, item, icon, _active_data, _active_propname, _index):

7
source/blender/editors/space_node/drawnode.cc
View File

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

235
source/blender/editors/space_node/node_draw.cc
View File

@ -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 = {

1
source/blender/editors/space_node/node_intern.hh
View File

@ -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,

1
source/blender/makesdna/DNA_space_types.h
View File

@ -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 {

6
source/blender/makesrna/intern/rna_space.c
View File

@ -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)

8
source/blender/modifiers/intern/MOD_nodes_evaluator.cc
View File

@ -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,

16
source/blender/nodes/NOD_geometry_nodes_eval_log.hh
View File

@ -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;
};

13
source/blender/nodes/intern/geometry_nodes_eval_log.cc
View File

@ -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