Depsgraph: Add per-depsgraph debug name which is shown in the logs

This way we can see for which depsgraph datablock is being evaluated for.

8 files changed, 105 insertions, 17 deletions

diff --git a/source/blender/blenkernel/intern/layer.c b/source/blender/blenkernel/intern/layer.c
index fc1cc53ba77..d3b47681a75 100644
--- a/source/blender/blenkernel/intern/layer.c
+++ b/source/blender/blenkernel/intern/layer.c
@@ -2416,17 +2416,16 @@ static void layer_eval_layer_collection(Depsgraph *depsgraph,
                                         LayerCollection *layer_collection,
                                         LayerCollection *parent_layer_collection)
 {
-	if (DEG_debug_flags_get(depsgraph) & G_DEBUG_DEPSGRAPH_EVAL) {
-		/* TODO)sergey): Try to make it more generic and handled by depsgraph messaging. */
-		printf("%s on %s (%p) [%s], parent %s (%p) [%s]\n",
-		       __func__,
-		       layer_collection->scene_collection->name,
-		       layer_collection->scene_collection,
-		       collection_type_lookup[layer_collection->scene_collection->type],
-		       (parent_layer_collection != NULL) ? parent_layer_collection->scene_collection->name : "NONE",
-		       (parent_layer_collection != NULL) ? parent_layer_collection->scene_collection : NULL,
-		       (parent_layer_collection != NULL) ? collection_type_lookup[parent_layer_collection->scene_collection->type] : "");
-	}
+	DEG_debug_print_eval_parent_typed(
+	        depsgraph,
+	        __func__,
+	        layer_collection->scene_collection->name,
+	        layer_collection->scene_collection,
+	        collection_type_lookup[layer_collection->scene_collection->type],
+	        "parent",
+	        (parent_layer_collection != NULL) ? parent_layer_collection->scene_collection->name : "NONE",
+	        (parent_layer_collection != NULL) ? parent_layer_collection->scene_collection : NULL,
+	        (parent_layer_collection != NULL) ? collection_type_lookup[parent_layer_collection->scene_collection->type] : "");
 	BLI_assert(layer_collection != parent_layer_collection);
 
 	/* visibility */
diff --git a/source/blender/blenkernel/intern/scene.c b/source/blender/blenkernel/intern/scene.c
index 758db5178de..f3f08aec3cd 100644
--- a/source/blender/blenkernel/intern/scene.c
+++ b/source/blender/blenkernel/intern/scene.c
@@ -2000,6 +2000,13 @@ Depsgraph *BKE_scene_get_depsgraph(Scene *scene,
 			*key_ptr = MEM_mallocN(sizeof(DepsgraphKey), __func__);
 			**key_ptr = key;
 			*depsgraph_ptr = DEG_graph_new(scene, view_layer, DAG_EVAL_VIEWPORT);
+			/* TODO(sergey): Would be cool to avoid string format print,
+			 * but is a bit tricky because we can't know in advance  whether
+			 * we will ever enable debug messages for this depsgraph.
+			 */
+			char name[1024];
+			BLI_snprintf(name, sizeof(name), "%s :: %s", scene->id.name, view_layer->name);
+			DEG_debug_name_set(*depsgraph_ptr, name);
 		}
 		depsgraph = *depsgraph_ptr;
 	}
diff --git a/source/blender/depsgraph/DEG_depsgraph.h b/source/blender/depsgraph/DEG_depsgraph.h
index 5fffd8d7fcf..604034bb0a7 100644
--- a/source/blender/depsgraph/DEG_depsgraph.h
+++ b/source/blender/depsgraph/DEG_depsgraph.h
@@ -234,6 +234,8 @@ void DEG_editors_set_update_cb(DEG_EditorUpdateIDCb id_func,
 
 /* Evaluation Debug ------------------------------ */
 
+void DEG_debug_print_begin(struct Depsgraph *depsgraph);
+
 void DEG_debug_print_eval(struct Depsgraph *depsgraph,
                           const char* function_name,
                           const char* object_name,
@@ -256,6 +258,16 @@ void DEG_debug_print_eval_subdata_index(struct Depsgraph *depsgraph,
                                         const void *subdata_address,
                                         const int subdata_index);
 
+void DEG_debug_print_eval_parent_typed(struct Depsgraph *depsgraph,
+                                       const char *function_name,
+                                       const char *object_name,
+                                       const void *object_address,
+                                       const char *object_type,
+                                       const char *parent_comment,
+                                       const char *parent_name,
+                                       const void *parent_address,
+                                       const char *parent_type);
+
 void DEG_debug_print_eval_time(struct Depsgraph *depsgraph,
                                const char* function_name,
                                const char* object_name,
diff --git a/source/blender/depsgraph/DEG_depsgraph_debug.h b/source/blender/depsgraph/DEG_depsgraph_debug.h
index 326d2f87ed8..7c0f9ef3121 100644
--- a/source/blender/depsgraph/DEG_depsgraph_debug.h
+++ b/source/blender/depsgraph/DEG_depsgraph_debug.h
@@ -50,6 +50,9 @@ struct ViewLayer;
 void DEG_debug_flags_set(struct Depsgraph *depsgraph, int flags);
 int DEG_debug_flags_get(const struct Depsgraph *depsgraph);
 
+void DEG_debug_name_set(struct Depsgraph *depsgraph, const char *name);
+const char *DEG_debug_name_get(struct Depsgraph *depsgraph);
+
 /* ------------------------------------------------ */
 
 void DEG_stats_simple(const struct Depsgraph *graph,
diff --git a/source/blender/depsgraph/intern/depsgraph.cc b/source/blender/depsgraph/intern/depsgraph.cc
index d75e3b9b3c8..bae798b82f7 100644
--- a/source/blender/depsgraph/intern/depsgraph.cc
+++ b/source/blender/depsgraph/intern/depsgraph.cc
@@ -602,6 +602,21 @@ void DEG_editors_set_update_cb(DEG_EditorUpdateIDCb id_func,
 
 /* Evaluation and debug */
 
+static DEG::string depsgraph_name_for_logging(struct Depsgraph *depsgraph)
+{
+	const char *name = DEG_debug_name_get(depsgraph);
+	if (name[0] == '\0') {
+		return "";
+	}
+	return "[" + DEG::string(name) + "]: ";
+}
+
+void DEG_debug_print_begin(struct Depsgraph *depsgraph)
+{
+	fprintf(stdout, "%s",
+	        depsgraph_name_for_logging(depsgraph).c_str());
+}
+
 void DEG_debug_print_eval(struct Depsgraph *depsgraph,
                           const char *function_name,
                           const char *object_name,
@@ -611,7 +626,8 @@ void DEG_debug_print_eval(struct Depsgraph *depsgraph,
 		return;
 	}
 	fprintf(stdout,
-	        "%s on %s %s(%p)%s\n",
+	        "%s%s on %s %s(%p)%s\n",
+	        depsgraph_name_for_logging(depsgraph).c_str(),
 	        function_name,
 	        object_name,
 	        DEG::deg_color_for_pointer(object_address).c_str(),
@@ -632,7 +648,8 @@ void DEG_debug_print_eval_subdata(struct Depsgraph *depsgraph,
 		return;
 	}
 	fprintf(stdout,
-	        "%s on %s %s(%p)%s %s %s %s(%p)%s\n",
+	        "%s%s on %s %s(%p)%s %s %s %s(%p)%s\n",
+	        depsgraph_name_for_logging(depsgraph).c_str(),
 	        function_name,
 	        object_name,
 	        DEG::deg_color_for_pointer(object_address).c_str(),
@@ -659,7 +676,8 @@ void DEG_debug_print_eval_subdata_index(struct Depsgraph *depsgraph,
 		return;
 	}
 	fprintf(stdout,
-	        "%s on %s %s(%p)^%s %s %s[%d] %s(%p)%s\n",
+	        "%s%s on %s %s(%p)%s %s %s[%d] %s(%p)%s\n",
+	        depsgraph_name_for_logging(depsgraph).c_str(),
 	        function_name,
 	        object_name,
 	        DEG::deg_color_for_pointer(object_address).c_str(),
@@ -674,6 +692,37 @@ void DEG_debug_print_eval_subdata_index(struct Depsgraph *depsgraph,
 	fflush(stdout);
 }
 
+void DEG_debug_print_eval_parent_typed(struct Depsgraph *depsgraph,
+                                       const char *function_name,
+                                       const char *object_name,
+                                       const void *object_address,
+                                       const char *object_type,
+                                       const char *parent_comment,
+                                       const char *parent_name,
+                                       const void *parent_address,
+                                       const char *parent_type)
+{
+	if ((DEG_debug_flags_get(depsgraph) & G_DEBUG_DEPSGRAPH_EVAL) == 0) {
+		return;
+	}
+	fprintf(stdout,
+	        "%s%s on %s %s(%p)%s [%s] %s %s %s(%p)%s %s\n",
+	        depsgraph_name_for_logging(depsgraph).c_str(),
+	        function_name,
+	        object_name,
+	        DEG::deg_color_for_pointer(object_address).c_str(),
+	        object_address,
+	        object_type,
+	        DEG::deg_color_end().c_str(),
+	        parent_comment,
+	        parent_name,
+	        DEG::deg_color_for_pointer(parent_address).c_str(),
+	        parent_address,
+	        DEG::deg_color_end().c_str(),
+	        parent_type);
+	fflush(stdout);
+}
+
 void DEG_debug_print_eval_time(struct Depsgraph *depsgraph,
                                const char *function_name,
                                const char *object_name,
@@ -684,7 +733,8 @@ void DEG_debug_print_eval_time(struct Depsgraph *depsgraph,
 		return;
 	}
 	fprintf(stdout,
-	        "%s on %s %s(%p)%s at time %f\n",
+	        depsgraph_name_for_logging(depsgraph).c_str(),
+	        "%s%s on %s %s(%p)%s at time %f\n",
 	        function_name,
 	        object_name,
 	        DEG::deg_color_for_pointer(object_address).c_str(),
diff --git a/source/blender/depsgraph/intern/depsgraph.h b/source/blender/depsgraph/intern/depsgraph.h
index 9c61b9a1fc6..7b6af9deee1 100644
--- a/source/blender/depsgraph/intern/depsgraph.h
+++ b/source/blender/depsgraph/intern/depsgraph.h
@@ -205,6 +205,7 @@ struct Depsgraph {
 
 	/* NITE: Corresponds to G_DEBUG_DEPSGRAPH_* flags. */
 	int debug_flags;
+	string debug_name;
 };
 
 }  // namespace DEG
diff --git a/source/blender/depsgraph/intern/depsgraph_debug.cc b/source/blender/depsgraph/intern/depsgraph_debug.cc
index 6b74c11ed70..f7adaafe5b3 100644
--- a/source/blender/depsgraph/intern/depsgraph_debug.cc
+++ b/source/blender/depsgraph/intern/depsgraph_debug.cc
@@ -45,6 +45,7 @@ extern "C" {
 #include "DEG_depsgraph_query.h"
 
 #include "intern/depsgraph_intern.h"
+#include "intern/depsgraph_types.h"
 #include "intern/nodes/deg_node_id.h"
 #include "intern/nodes/deg_node_time.h"
 
@@ -64,6 +65,20 @@ int DEG_debug_flags_get(const Depsgraph *depsgraph)
 	return deg_graph->debug_flags;
 }
 
+void DEG_debug_name_set(struct Depsgraph *depsgraph, const char *name)
+{
+	DEG::Depsgraph *deg_graph =
+	        reinterpret_cast<DEG::Depsgraph *>(depsgraph);
+	deg_graph->debug_name = name;
+}
+
+const char *DEG_debug_name_get(struct Depsgraph *depsgraph)
+{
+	const DEG::Depsgraph *deg_graph =
+	        reinterpret_cast<const DEG::Depsgraph *>(depsgraph);
+	return deg_graph->debug_name.c_str();
+}
+
 bool DEG_debug_compare(const struct Depsgraph *graph1,
                        const struct Depsgraph *graph2)
 {
diff --git a/source/blender/depsgraph/intern/depsgraph_intern.h b/source/blender/depsgraph/intern/depsgraph_intern.h
index f69ddeed355..c048a7c1b93 100644
--- a/source/blender/depsgraph/intern/depsgraph_intern.h
+++ b/source/blender/depsgraph/intern/depsgraph_intern.h
@@ -117,14 +117,15 @@ void deg_editors_scene_update(const DEGEditorUpdateContext *update_ctx,
 #define DEG_DEBUG_PRINTF(depsgraph, type, ...) \
 	do { \
 		if (DEG_debug_flags_get(depsgraph) & G_DEBUG_DEPSGRAPH_ ## type) { \
-			fprintf(stderr, __VA_ARGS__); \
+			DEG_debug_print_begin(depsgraph); \
+			fprintf(stdout, __VA_ARGS__); \
 		} \
 	} while (0)
 
 #define DEG_GLOBAL_DEBUG_PRINTF(type, ...) \
 	do { \
 		if (G.debug & G_DEBUG_DEPSGRAPH_ ## type) { \
-			fprintf(stderr, __VA_ARGS__); \
+			fprintf(stdout, __VA_ARGS__); \
 		} \
 	} while (0)