From 8adebaeb7c3c663ec775fda239fdfe5ddb654b06 Mon Sep 17 00:00:00 2001 From: Jacques Lucke Date: Mon, 6 Feb 2023 15:39:59 +0100 Subject: [PATCH] Modifiers: measure execution time and provide Python access The goal is to give technical artists the ability to optimize modifier usage and/or geometry node groups for performance. In the long term, it would be useful if Blender could provide its own UI to display profiling information to users. However, right now, there are too many open design questions making it infeasible to tackle this in the short term. This commit uses a simpler approach: Instead of adding new ui for profiling data, it exposes the execution-time of modifiers in the Python API. This allows technical artists to access the information and to build their own UI to display the relevant information. In the long term this will hopefully also help us to integrate a native ui for this in Blender by observing how users use this information. Note: The execution time of a modifier highly depends on what other things the CPU is doing at the same time. For example, in many more complex files, many objects and therefore modifiers are evaluated at the same time by multiple threads which makes the measurement much less reliable. For best results, make sure that only one object is evaluated at a time (e.g. by changing it in isolation) and that no other process on the system keeps the CPU busy. As shown below, the execution time has to be accessed on the evaluated object, not the original object. ```lang=python import bpy depsgraph = bpy.context.view_layer.depsgraph ob = bpy.context.active_object ob_eval = ob.evaluated_get(depsgraph) modifier_eval = ob_eval.modifiers[0] print(modifier_eval.execution_time, "s") ``` Differential Revision: https://developer.blender.org/D17185 --- source/blender/blenkernel/BKE_modifier.h | 22 ++++++++++++++++ .../blender/blenkernel/intern/DerivedMesh.cc | 5 ++++ source/blender/blenkernel/intern/curves.cc | 2 ++ source/blender/blenkernel/intern/displist.cc | 4 +++ source/blender/blenkernel/intern/modifier.cc | 26 +++++++++++++++++++ .../blender/blenkernel/intern/pointcloud.cc | 2 ++ source/blender/blenkernel/intern/volume.cc | 2 ++ source/blender/makesdna/DNA_modifier_types.h | 3 ++- source/blender/makesrna/intern/rna_modifier.c | 8 ++++++ 9 files changed, 73 insertions(+), 1 deletion(-) diff --git a/source/blender/blenkernel/BKE_modifier.h b/source/blender/blenkernel/BKE_modifier.h index ce2f9e878f8..4641cc47b14 100644 --- a/source/blender/blenkernel/BKE_modifier.h +++ b/source/blender/blenkernel/BKE_modifier.h @@ -612,3 +612,25 @@ void BKE_modifier_blend_read_lib(struct BlendLibReader *reader, struct Object *o #ifdef __cplusplus } #endif + +#ifdef __cplusplus + +namespace blender::bke { + +/** + * A convenience class that can be used to set `ModifierData::execution_time` based on the lifetime + * of this class. + */ +class ScopedModifierTimer { + private: + ModifierData &md_; + double start_time_; + + public: + ScopedModifierTimer(ModifierData &md); + ~ScopedModifierTimer(); +}; + +} // namespace blender::bke + +#endif diff --git a/source/blender/blenkernel/intern/DerivedMesh.cc b/source/blender/blenkernel/intern/DerivedMesh.cc index 565009fe08f..c3d535a3e9d 100644 --- a/source/blender/blenkernel/intern/DerivedMesh.cc +++ b/source/blender/blenkernel/intern/DerivedMesh.cc @@ -760,6 +760,7 @@ static void mesh_calc_modifiers(struct Depsgraph *depsgraph, } if (mti->type == eModifierTypeType_OnlyDeform && !sculpt_dyntopo) { + blender::bke::ScopedModifierTimer modifier_timer{*md}; if (!deformed_verts) { deformed_verts = BKE_mesh_vert_coords_alloc(mesh_input, &num_deformed_verts); } @@ -846,6 +847,8 @@ static void mesh_calc_modifiers(struct Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + /* Add orco mesh as layer if needed by this modifier. */ if (mesh_final && mesh_orco && mti->requiredDataMask) { CustomData_MeshMasks mask = {0}; @@ -1323,6 +1326,8 @@ static void editbmesh_calc_modifiers(struct Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + /* Add an orco mesh as layer if needed by this modifier. */ if (mesh_final && mesh_orco && mti->requiredDataMask) { CustomData_MeshMasks mask = {0}; diff --git a/source/blender/blenkernel/intern/curves.cc b/source/blender/blenkernel/intern/curves.cc index 1519c0addd2..3003d014b4f 100644 --- a/source/blender/blenkernel/intern/curves.cc +++ b/source/blender/blenkernel/intern/curves.cc @@ -314,6 +314,8 @@ static void curves_evaluate_modifiers(struct Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + if (mti->modifyGeometrySet != nullptr) { mti->modifyGeometrySet(md, &mectx, &geometry_set); } diff --git a/source/blender/blenkernel/intern/displist.cc b/source/blender/blenkernel/intern/displist.cc index 8cdcb85a033..e51a2c3d85c 100644 --- a/source/blender/blenkernel/intern/displist.cc +++ b/source/blender/blenkernel/intern/displist.cc @@ -613,6 +613,8 @@ void BKE_curve_calc_modifiers_pre(Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + if (!deformedVerts) { deformedVerts = BKE_curve_nurbs_vert_coords_alloc(source_nurb, &numVerts); } @@ -733,6 +735,8 @@ static GeometrySet curve_calc_modifiers_post(Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + if (!geometry_set.has_mesh()) { geometry_set.replace_mesh(BKE_mesh_new_nomain(0, 0, 0, 0, 0)); } diff --git a/source/blender/blenkernel/intern/modifier.cc b/source/blender/blenkernel/intern/modifier.cc index 508c1fe2331..d0ccdedc136 100644 --- a/source/blender/blenkernel/intern/modifier.cc +++ b/source/blender/blenkernel/intern/modifier.cc @@ -11,6 +11,7 @@ #define DNA_DEPRECATED_ALLOW #include +#include #include #include #include @@ -1514,3 +1515,28 @@ void BKE_modifier_blend_read_lib(BlendLibReader *reader, Object *ob) } } } + +namespace blender::bke { + +using Clock = std::chrono::high_resolution_clock; + +static double get_current_time_in_seconds() +{ + return std::chrono::duration( + Clock::now().time_since_epoch()) + .count(); +} + +ScopedModifierTimer::ScopedModifierTimer(ModifierData &md) : md_(md) +{ + start_time_ = get_current_time_in_seconds(); +} + +ScopedModifierTimer::~ScopedModifierTimer() +{ + const double end_time = get_current_time_in_seconds(); + const double duration = end_time - start_time_; + md_.execution_time = duration; +} + +} // namespace blender::bke diff --git a/source/blender/blenkernel/intern/pointcloud.cc b/source/blender/blenkernel/intern/pointcloud.cc index aa3c2593f34..2fee1f4f4d3 100644 --- a/source/blender/blenkernel/intern/pointcloud.cc +++ b/source/blender/blenkernel/intern/pointcloud.cc @@ -380,6 +380,8 @@ static void pointcloud_evaluate_modifiers(struct Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + if (mti->modifyGeometrySet) { mti->modifyGeometrySet(md, &mectx, &geometry_set); } diff --git a/source/blender/blenkernel/intern/volume.cc b/source/blender/blenkernel/intern/volume.cc index bad2e844cc0..b2f62dd0d9d 100644 --- a/source/blender/blenkernel/intern/volume.cc +++ b/source/blender/blenkernel/intern/volume.cc @@ -1108,6 +1108,8 @@ static void volume_evaluate_modifiers(struct Depsgraph *depsgraph, continue; } + blender::bke::ScopedModifierTimer modifier_timer{*md}; + if (mti->modifyGeometrySet) { mti->modifyGeometrySet(md, &mectx, &geometry_set); } diff --git a/source/blender/makesdna/DNA_modifier_types.h b/source/blender/makesdna/DNA_modifier_types.h index fe35fea77ed..7af83f8f888 100644 --- a/source/blender/makesdna/DNA_modifier_types.h +++ b/source/blender/makesdna/DNA_modifier_types.h @@ -105,7 +105,8 @@ typedef struct ModifierData { struct ModifierData *next, *prev; int type, mode; - char _pad0[4]; + /** Time in seconds that the modifier took to evaluate. This is only set on evaluated objects. */ + float execution_time; short flag; /** An "expand" bit for each of the modifier's (sub)panels (#uiPanelDataExpansion). */ short ui_expand_flag; diff --git a/source/blender/makesrna/intern/rna_modifier.c b/source/blender/makesrna/intern/rna_modifier.c index aa7b1ae01dc..b86e202a791 100644 --- a/source/blender/makesrna/intern/rna_modifier.c +++ b/source/blender/makesrna/intern/rna_modifier.c @@ -7355,6 +7355,14 @@ void RNA_def_modifier(BlenderRNA *brna) RNA_def_property_ui_icon(prop, ICON_SURFACE_DATA, 0); RNA_def_property_update(prop, 0, "rna_Modifier_update"); + prop = RNA_def_property(srna, "execution_time", PROP_FLOAT, PROP_TIME_ABSOLUTE); + RNA_def_property_clear_flag(prop, PROP_EDITABLE); + RNA_def_property_ui_text( + prop, + "Execution Time", + "Time in seconds that the modifier took to evaluate. This is only set on evaluated objects. " + "If multiple modifiers run in parallel, execution time is not a reliable metric"); + /* types */ rna_def_modifier_subsurf(brna); rna_def_modifier_lattice(brna);