More debug timing info from main RNA diffing func.

1 files changed, 38 insertions, 8 deletions

diff --git a/source/blender/makesrna/intern/rna_access.c b/source/blender/makesrna/intern/rna_access.c
index 42eb7b81c37..59d0095e3fb 100644
--- a/source/blender/makesrna/intern/rna_access.c
+++ b/source/blender/makesrna/intern/rna_access.c
@@ -7470,12 +7470,21 @@ bool RNA_struct_override_matches(
 	const bool do_create = (flags & RNA_OVERRIDE_COMPARE_CREATE) != 0;
 	const bool do_restore = (flags & RNA_OVERRIDE_COMPARE_RESTORE) != 0;
 
+//#define DEBUG_OVERRIDE_TIMEIT
 #ifdef DEBUG_OVERRIDE_TIMEIT
-	static float _sum_time = 0.0f;
-	static float _num_time = 0.0f;
-	double _timeit_time;
+	static float _sum_time_global = 0.0f;
+	static float _num_time_global = 0.0f;
+	double _timeit_time_global;
+	static float _sum_time_diffing = 0.0f;
+	static float _delta_time_diffing = 0.0f;
+	static int _num_delta_time_diffing = 0.0f;
+	static float _num_time_diffing = 0.0f;
+	double _timeit_time_diffing;
+
 	if (!root_path) {
-		_timeit_time = PIL_check_seconds_timer();
+		_delta_time_diffing = 0.0f;
+		_num_delta_time_diffing = 0;
+		_timeit_time_global = PIL_check_seconds_timer();
 	}
 #endif
 
@@ -7525,6 +7534,7 @@ bool RNA_struct_override_matches(
 			}
 		}
 		else {
+			/* This is rather slow, but is not much called, so not really worth optimizing. */
 			rna_path = RNA_path_from_ID_to_property(ptr_local, prop_local);
 		}
 		if (rna_path == NULL) {
@@ -7538,11 +7548,25 @@ bool RNA_struct_override_matches(
 			continue;
 		}
 
+#ifdef DEBUG_OVERRIDE_TIMEIT
+		if (!root_path) {
+			_timeit_time_diffing = PIL_check_seconds_timer();
+		}
+#endif
+
 		eRNAOverrideMatchResult report_flags = 0;
 		const int diff = rna_property_override_diff(
 		                     ptr_local, ptr_reference, NULL, prop_local, prop_reference, rna_path,
 		                     RNA_EQ_STRICT, override, flags, &report_flags);
 
+#ifdef DEBUG_OVERRIDE_TIMEIT
+		if (!root_path) {
+			const float _delta_time = (float)(PIL_check_seconds_timer() - _timeit_time_diffing);
+			_delta_time_diffing += _delta_time;
+			_num_delta_time_diffing++;
+		}
+#endif
+
 		matching = matching && diff == 0;
 		if (r_report_flags) {
 			*r_report_flags |= report_flags;
@@ -7597,12 +7621,18 @@ bool RNA_struct_override_matches(
 
 #ifdef DEBUG_OVERRIDE_TIMEIT
 	if (!root_path) {
-		const float _delta_time = (float)(PIL_check_seconds_timer() - _timeit_time);
-		_sum_time += _delta_time;
-		_num_time++;
+		const float _delta_time = (float)(PIL_check_seconds_timer() - _timeit_time_global);
+		_sum_time_global += _delta_time;
+		_num_time_global++;
+		_sum_time_diffing += _delta_time_diffing;
+		_num_time_diffing++;
 		printf("ID: %s\n", ((ID *)ptr_local->id.data)->name);
 		printf("time end      (%s): %.6f\n", __func__, _delta_time);
-		printf("time averaged (%s): %.6f (total: %.6f, in %d runs)\n", __func__, (_sum_time / _num_time), _sum_time, (int)_num_time);
+		printf("time averaged (%s): %.6f (total: %.6f, in %d runs)\n", __func__,
+		       (_sum_time_global / _num_time_global), _sum_time_global, (int)_num_time_global);
+		printf("diffing time end      (%s): %.6f (in %d runs)\n", __func__, _delta_time_diffing, _num_delta_time_diffing);
+		printf("diffing time averaged (%s): %.6f (total: %.6f, in %d runs)\n", __func__,
+		       (_sum_time_diffing / _num_time_diffing), _sum_time_diffing, (int)_num_time_diffing);
 	}
 #endif