Depsgraph: Bring timing statistics to the new dependency graph

This statistics is only collected when debug_value is different from 0.

Stored in depsgraph node itself, so we can always have access to average data
and other stats which requires persistent storage. This way we also don't waste
time trying to find stats from a separately stored hash map.

9 files changed, 333 insertions, 9 deletions

diff --git a/source/blender/depsgraph/CMakeLists.txt b/source/blender/depsgraph/CMakeLists.txt
index 04fbbbf0915..af2c2ecb67f 100644
--- a/source/blender/depsgraph/CMakeLists.txt
+++ b/source/blender/depsgraph/CMakeLists.txt
@@ -52,8 +52,10 @@ set(SRC
 	intern/builder/deg_builder_relations_scene.cc
 	intern/builder/deg_builder_transitive.cc
 	intern/debug/deg_debug_relations_graphviz.cc
+	intern/debug/deg_debug_stats_gnuplot.cc
 	intern/eval/deg_eval.cc
 	intern/eval/deg_eval_flush.cc
+	intern/eval/deg_eval_stats.cc
 	intern/nodes/deg_node.cc
 	intern/nodes/deg_node_component.cc
 	intern/nodes/deg_node_id.cc
@@ -82,6 +84,7 @@ set(SRC
 	intern/builder/deg_builder_transitive.h
 	intern/eval/deg_eval.h
 	intern/eval/deg_eval_flush.h
+	intern/eval/deg_eval_stats.h
 	intern/nodes/deg_node.h
 	intern/nodes/deg_node_component.h
 	intern/nodes/deg_node_id.h
diff --git a/source/blender/depsgraph/DEG_depsgraph_debug.h b/source/blender/depsgraph/DEG_depsgraph_debug.h
index e920e34dad3..bc93fcc94cb 100644
--- a/source/blender/depsgraph/DEG_depsgraph_debug.h
+++ b/source/blender/depsgraph/DEG_depsgraph_debug.h
@@ -55,6 +55,11 @@ void DEG_debug_relations_graphviz(const struct Depsgraph *graph,
                                   FILE *stream,
                                   const char *label);
 
+void DEG_debug_stats_gnuplot(const struct Depsgraph *graph,
+                             FILE *stream,
+                             const char *label,
+                             const char *output_filename);
+
 /* ************************************************ */
 
 /* Compare two dependency graphs. */
diff --git a/source/blender/depsgraph/intern/debug/deg_debug_stats_gnuplot.cc b/source/blender/depsgraph/intern/debug/deg_debug_stats_gnuplot.cc
new file mode 100644
index 00000000000..ecef4ff55a7
--- /dev/null
+++ b/source/blender/depsgraph/intern/debug/deg_debug_stats_gnuplot.cc
@@ -0,0 +1,126 @@
+/*
+ * ***** BEGIN GPL LICENSE BLOCK *****
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public License
+ * as published by the Free Software Foundation; either version 2
+ * of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ *
+ * The Original Code is Copyright (C) 2017 Blender Foundation.
+ * All rights reserved.
+ *
+ * Original Author: Sergey Sharybin
+ * Contributor(s): None Yet
+ *
+ * ***** END GPL LICENSE BLOCK *****
+ */
+
+/** \file blender/depsgraph/intern/debug/deg_debug_stats_gnuplot.cc
+ *  \ingroup depsgraph
+ */
+
+#include "DEG_depsgraph_debug.h"
+
+#include <stdarg.h>
+
+#include "BLI_compiler_attrs.h"
+
+#include "intern/depsgraph.h"
+#include "intern/nodes/deg_node_id.h"
+
+#include "util/deg_util_foreach.h"
+
+extern "C" {
+#include "DNA_ID.h"
+} /* extern "C" */
+
+#define NL "\r\n"
+
+namespace DEG {
+namespace {
+
+struct DebugContext {
+	FILE *file;
+	const Depsgraph *graph;
+	const char *label;
+	const char *output_filename;
+};
+
+/* TODO(sergey): De-duplicate with graphviz relation debugger. */
+static void deg_debug_fprintf(const DebugContext &ctx,
+                              const char *fmt,
+                              ...) ATTR_PRINTF_FORMAT(2, 3);
+static void deg_debug_fprintf(const DebugContext &ctx, const char *fmt, ...)
+{
+	va_list args;
+	va_start(args, fmt);
+	vfprintf(ctx.file, fmt, args);
+	va_end(args);
+}
+
+void write_stats_data(const DebugContext& ctx)
+{
+	deg_debug_fprintf(ctx, "$data << EOD" NL);
+	// TODO(sergey): Sort nodes by time.
+	foreach (const IDDepsNode *id_node, ctx.graph->id_nodes) {
+		// TODO(sergey): Figure out a nice way to define which exact time
+		// we want to show.
+		const double time = id_node->stats.current_time;
+		if (time == 0.0) {
+			continue;
+		}
+		deg_debug_fprintf(ctx, "\"%s\",%f" NL,
+		                  id_node->id->name + 2,
+		                  time);
+	}
+	deg_debug_fprintf(ctx, "EOD" NL);
+}
+
+void deg_debug_stats_gnuplot(const DebugContext& ctx)
+{
+	// Data itself.
+	write_stats_data(ctx);
+	// Optional label.
+	if (ctx.label && ctx.label[0]) {
+		deg_debug_fprintf(ctx, "set title \"%s\"" NL, ctx.label);
+	}
+	// Rest of the commands.
+	// TODO(sergey): Need to decide on the resolution somehow.
+	deg_debug_fprintf(ctx, "set terminal pngcairo size 1920,1080" NL);
+	deg_debug_fprintf(ctx, "set output \"%s\"" NL, ctx.output_filename);
+	deg_debug_fprintf(ctx, "set grid" NL);
+	deg_debug_fprintf(ctx, "set datafile separator ','" NL);
+	deg_debug_fprintf(ctx, "set style fill solid" NL);
+	deg_debug_fprintf(ctx, "plot \"$data\" using " \
+	                       "($2*0.5):0:($2*0.5):(0.2):yticlabels(1) "
+	                       "with boxxyerrorbars t '' lt rgb \"#406090\"" NL);
+
+}
+
+}  // namespace
+}  // namespace DEG
+
+void DEG_debug_stats_gnuplot(const Depsgraph *depsgraph,
+                             FILE *f,
+                             const char *label,
+                             const char *output_filename)
+{
+	if (depsgraph == NULL) {
+		return;
+	}
+	DEG::DebugContext ctx;
+	ctx.file = f;
+	ctx.graph = (DEG::Depsgraph *)depsgraph;
+	ctx.label = label;
+	ctx.output_filename = output_filename;
+	DEG::deg_debug_stats_gnuplot(ctx);
+}
diff --git a/source/blender/depsgraph/intern/eval/deg_eval.cc b/source/blender/depsgraph/intern/eval/deg_eval.cc
index c5100856e83..09d25be41d6 100644
--- a/source/blender/depsgraph/intern/eval/deg_eval.cc
+++ b/source/blender/depsgraph/intern/eval/deg_eval.cc
@@ -48,6 +48,7 @@ extern "C" {
 #include "atomic_ops.h"
 
 #include "intern/eval/deg_eval_flush.h"
+#include "intern/eval/deg_eval_stats.h"
 #include "intern/nodes/deg_node.h"
 #include "intern/nodes/deg_node_component.h"
 #include "intern/nodes/deg_node_id.h"
@@ -74,6 +75,7 @@ struct DepsgraphEvalState {
 	EvaluationContext *eval_ctx;
 	Depsgraph *graph;
 	unsigned int layers;
+	bool do_stats;
 };
 
 static void deg_task_run_func(TaskPool *pool,
@@ -86,7 +88,14 @@ static void deg_task_run_func(TaskPool *pool,
 	/* Sanity checks. */
 	BLI_assert(!node->is_noop() && "NOOP nodes should not actually be scheduled");
 	/* Perform operation. */
-	node->evaluate(state->eval_ctx);
+	if (state->do_stats) {
+		const double start_time = PIL_check_seconds_timer();
+		node->evaluate(state->eval_ctx);
+		node->stats.current_time += PIL_check_seconds_timer() - start_time;
+	}
+	else {
+		node->evaluate(state->eval_ctx);
+	}
 	/* Schedule children. */
 	BLI_task_pool_delayed_push_begin(pool, thread_id);
 	schedule_children(pool, state->graph, node, state->layers, thread_id);
@@ -145,10 +154,14 @@ static void calculate_pending_parents(Depsgraph *graph, unsigned int layers)
 
 static void initialize_execution(DepsgraphEvalState *state, Depsgraph *graph)
 {
+	const bool do_stats = state->do_stats;
 	calculate_pending_parents(graph, state->layers);
 	/* Clear tags and other things which needs to be clear. */
 	foreach (OperationDepsNode *node, graph->operations) {
 		node->done = 0;
+		if (do_stats) {
+			node->stats.reset_current();
+		}
 	}
 }
 
@@ -250,6 +263,7 @@ void deg_evaluate_on_refresh(EvaluationContext *eval_ctx,
 	state.eval_ctx = eval_ctx;
 	state.graph = graph;
 	state.layers = layers;
+	state.do_stats = (G.debug_value != 0);
 	/* Set up task scheduler and pull for threaded evaluation. */
 	TaskScheduler *task_scheduler;
 	bool need_free_scheduler;
@@ -268,6 +282,13 @@ void deg_evaluate_on_refresh(EvaluationContext *eval_ctx,
 	schedule_graph(task_pool, graph, layers);
 	BLI_task_pool_work_and_wait(task_pool);
 	BLI_task_pool_free(task_pool);
+	/* Finalize statistics gathering. This is because we only gather single
+	 * operation timing here, without aggregating anything to avoid any extra
+	 * synchronization.
+	 */
+	if (state.do_stats) {
+		deg_eval_stats_aggregate(graph);
+	}
 	/* Clear any uncleared tags - just in case. */
 	deg_graph_clear_tags(graph);
 	if (need_free_scheduler) {
diff --git a/source/blender/depsgraph/intern/eval/deg_eval_stats.cc b/source/blender/depsgraph/intern/eval/deg_eval_stats.cc
new file mode 100644
index 00000000000..52ce744cc0a
--- /dev/null
+++ b/source/blender/depsgraph/intern/eval/deg_eval_stats.cc
@@ -0,0 +1,70 @@
+/*
+ * ***** BEGIN GPL LICENSE BLOCK *****
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public License
+ * as published by the Free Software Foundation; either version 2
+ * of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ *
+ * The Original Code is Copyright (C) 2017 Blender Foundation.
+ * All rights reserved.
+ *
+ * Original Author: Sergey Sharybin
+ * Contributor(s): None Yet
+ *
+ * ***** END GPL LICENSE BLOCK *****
+ */
+
+/** \file blender/depsgraph/intern/eval/deg_eval_stats.cc
+ *  \ingroup depsgraph
+ */
+
+#include "intern/eval/deg_eval_stats.h"
+
+#include "BLI_utildefines.h"
+#include "BLI_ghash.h"
+
+#include "intern/depsgraph.h"
+
+#include "intern/nodes/deg_node.h"
+#include "intern/nodes/deg_node_component.h"
+#include "intern/nodes/deg_node_id.h"
+#include "intern/nodes/deg_node_operation.h"
+
+#include "util/deg_util_foreach.h"
+
+namespace DEG {
+
+void deg_eval_stats_aggregate(Depsgraph *graph)
+{
+	/* Reset current evaluation stats for ID and component nodes.
+	 * Those are not filled in by the evaluation engine.
+	 */
+	foreach (DepsNode *node, graph->id_nodes) {
+		IDDepsNode *id_node = (IDDepsNode *)node;
+		GHASH_FOREACH_BEGIN(ComponentDepsNode *, comp_node, id_node->components)
+		{
+			comp_node->stats.reset_current();
+		}
+		GHASH_FOREACH_END();
+		id_node->stats.reset_current();
+	}
+	/* Now accumulate operation timings to components and IDs. */
+	foreach (OperationDepsNode *op_node, graph->operations) {
+		ComponentDepsNode *comp_node = op_node->owner;
+		IDDepsNode *id_node = comp_node->owner;
+		id_node->stats.current_time += op_node->stats.current_time;
+		comp_node->stats.current_time += op_node->stats.current_time;
+	}
+}
+
+}  // namespace DEG
diff --git a/source/blender/depsgraph/intern/eval/deg_eval_stats.h b/source/blender/depsgraph/intern/eval/deg_eval_stats.h
new file mode 100644
index 00000000000..8a7272ac89c
--- /dev/null
+++ b/source/blender/depsgraph/intern/eval/deg_eval_stats.h
@@ -0,0 +1,40 @@
+/*
+ * ***** BEGIN GPL LICENSE BLOCK *****
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public License
+ * as published by the Free Software Foundation; either version 2
+ * of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
+ *
+ * The Original Code is Copyright (C) 2017 Blender Foundation.
+ * All rights reserved.
+ *
+ * Original Author: Sergey Sharybin
+ * Contributor(s): None Yet
+ *
+ * ***** END GPL LICENSE BLOCK *****
+ */
+
+/** \file blender/depsgraph/intern/eval/deg_eval_stats.h
+ *  \ingroup depsgraph
+ */
+
+#pragma once
+
+namespace DEG {
+
+struct Depsgraph;
+
+/* Aggregate operation timings to overall component and ID nodes timing. */
+void deg_eval_stats_aggregate(Depsgraph *graph);
+
+}  // namespace DEG
diff --git a/source/blender/depsgraph/intern/nodes/deg_node.cc b/source/blender/depsgraph/intern/nodes/deg_node.cc
index e561c9b236e..d72ca384044 100644
--- a/source/blender/depsgraph/intern/nodes/deg_node.cc
+++ b/source/blender/depsgraph/intern/nodes/deg_node.cc
@@ -44,10 +44,9 @@
 
 namespace DEG {
 
-/* *************** */
-/* Node Management */
-
-/* Add ------------------------------------------------ */
+/*******************************************************************************
+ * Type information.
+ */
 
 DepsNode::TypeInfo::TypeInfo(eDepsNode_Type type,
                              const char *tname,
@@ -58,6 +57,29 @@ DepsNode::TypeInfo::TypeInfo(eDepsNode_Type type,
 {
 }
 
+/*******************************************************************************
+ * Evaluation statistics.
+ */
+
+DepsNode::Stats::Stats()
+{
+	reset();
+}
+
+void DepsNode::Stats::reset()
+{
+	current_time = 0.0;
+}
+
+void DepsNode::Stats::reset_current()
+{
+	current_time = 0.0;
+}
+
+/*******************************************************************************
+ * Node itself.
+ */
+
 DepsNode::DepsNode()
 {
 	name = "";
@@ -97,8 +119,10 @@ eDepsNode_Class DepsNode::get_class() const {
 	}
 }
 
-/* Generic Nodes */
-
+/*******************************************************************************
+ * Generic nodes definition.
+ */
+\
 DEG_DEPSNODE_DEFINE(TimeSourceDepsNode, DEG_NODE_TYPE_TIMESOURCE, "Time Source");
 static DepsNodeFactoryImpl<TimeSourceDepsNode> DNTI_TIMESOURCE;
 
diff --git a/source/blender/depsgraph/intern/nodes/deg_node.h b/source/blender/depsgraph/intern/nodes/deg_node.h
index cc741224c71..603a6be7ceb 100644
--- a/source/blender/depsgraph/intern/nodes/deg_node.h
+++ b/source/blender/depsgraph/intern/nodes/deg_node.h
@@ -56,6 +56,19 @@ struct DepsNode {
 		const char *tname;
 		int id_recalc_tag;
 	};
+	struct Stats {
+		Stats();
+		/* Reset all the counters. Including all stats needed for average
+		 * evaluation time calculation.
+		 */
+		void reset();
+		/* Reset counters needed for the current graph evaluation, does not
+		 * touch averaging accumulators.
+		 */
+		void reset_current();
+		/* Time spend on this node during current graph evaluation. */
+		double current_time;
+	};
 	/* Relationships between nodes
 	 * The reason why all depsgraph nodes are descended from this type (apart
 	 * from basic serialization benefits - from the typeinfo) is that we can have
@@ -67,7 +80,8 @@ struct DepsNode {
 	eDepsNode_Type type;  /* Structural type of node. */
 	Relations inlinks;    /* Nodes which this one depends on. */
 	Relations outlinks;   /* Nodes which depend on this one. */
-	int done;    /* Generic tags for traversal algorithms. */
+	int done;     /* Generic tags for traversal algorithms. */
+	Stats stats;  /* Evaluation statistics. */
 
 	/* Methods. */
 	DepsNode();
diff --git a/source/blender/makesrna/intern/rna_depsgraph.c b/source/blender/makesrna/intern/rna_depsgraph.c
index 041f01b6543..1091239805f 100644
--- a/source/blender/makesrna/intern/rna_depsgraph.c
+++ b/source/blender/makesrna/intern/rna_depsgraph.c
@@ -45,7 +45,8 @@
 #include "DEG_depsgraph_build.h"
 #include "DEG_depsgraph_debug.h"
 
-static void rna_Depsgraph_debug_relations_graphviz(Depsgraph *graph, const char *filename)
+static void rna_Depsgraph_debug_relations_graphviz(Depsgraph *graph,
+                                                   const char *filename)
 {
 	FILE *f = fopen(filename, "w");
 	if (f == NULL) {
@@ -55,6 +56,18 @@ static void rna_Depsgraph_debug_relations_graphviz(Depsgraph *graph, const char
 	fclose(f);
 }
 
+static void rna_Depsgraph_debug_stats_gnuplot(Depsgraph *graph,
+                                              const char *filename,
+                                              const char *output_filename)
+{
+	FILE *f = fopen(filename, "w");
+	if (f == NULL) {
+		return;
+	}
+	DEG_debug_stats_gnuplot(graph, f, "Timing Statistics", output_filename);
+	fclose(f);
+}
+
 static void rna_Depsgraph_debug_tag_update(Depsgraph *graph)
 {
 	DEG_graph_tag_relations_update(graph);
@@ -85,6 +98,14 @@ static void rna_def_depsgraph(BlenderRNA *brna)
 	                                "File in which to store graphviz debug output");
 	RNA_def_parameter_flags(parm, 0, PARM_REQUIRED);
 
+	func = RNA_def_function(srna, "debug_stats_gnuplot", "rna_Depsgraph_debug_stats_gnuplot");
+	parm = RNA_def_string_file_path(func, "filename", NULL, FILE_MAX, "File Name",
+	                                "File in which to store graphviz debug output");
+	RNA_def_parameter_flags(parm, 0, PARM_REQUIRED);
+	parm = RNA_def_string_file_path(func, "output_filename", NULL, FILE_MAX, "Output File Name",
+	                                "File name where gnuplot script will save the result");
+	RNA_def_parameter_flags(parm, 0, PARM_REQUIRED);
+
 	func = RNA_def_function(srna, "debug_tag_update", "rna_Depsgraph_debug_tag_update");
 
 	func = RNA_def_function(srna, "debug_stats", "rna_Depsgraph_debug_stats");