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

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

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

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

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

source/blender/blenkernel/intern/modifier.cc

@@ -11,6 +11,7 @@
 #define DNA_DEPRECATED_ALLOW
 
 #include <cfloat>
+#include <chrono>
 #include <cmath>
 #include <cstdarg>
 #include <cstddef>
@@ -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<double, std::chrono::seconds::period>(
+             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

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

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

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;

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