Cleanup and improvements of the compositor debug output.

Debug code for graphviz output moved to a dedicated file COM_Debug.h/cpp.

The DebugInfo class has only static functions, which are called from a number of places to keep track of what is happening in the compositor. If debugging is disabled these are just inline stubs, so we
don't need #ifdefs everywhere and don't get any overhead.

The graphviz output is much more useful now. DebugInfo keeps track of node names in a static string map for meaningful names. It uses a number of colors for various special operation classes.
ExecutionGroups are indicated in graphviz with clusters.

Currently the graphviz .dot files are stored in the BLI_temporary_dir() folder. A separate dot file is generated for each stage of the ExecutionGroup scheduling, this is intended to give some idea of the
compositor progress, but could still be improved.

1 files changed, 413 insertions, 0 deletions

diff --git a/source/blender/compositor/intern/COM_Debug.cpp b/source/blender/compositor/intern/COM_Debug.cpp
new file mode 100644
index 00000000000..c0610448f58
--- /dev/null
+++ b/source/blender/compositor/intern/COM_Debug.cpp
@@ -0,0 +1,413 @@
+/*
+ * Copyright 2013, Blender Foundation.
+ *
+ * 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.
+ *
+ * Contributor: 
+ *		Lukas Toenne
+ */
+
+#include "COM_Debug.h"
+
+#ifdef COM_DEBUG
+
+#include <typeinfo>
+#include <map>
+#include <vector>
+
+extern "C" {
+#include "BLI_fileops.h"
+#include "BLI_path_util.h"
+#include "BLI_string.h"
+#include "DNA_node_types.h"
+#include "BKE_node.h"
+}
+
+#include "COM_Node.h"
+#include "COM_ExecutionSystem.h"
+#include "COM_ExecutionGroup.h"
+
+#include "COM_ReadBufferOperation.h"
+#include "COM_ViewerOperation.h"
+#include "COM_WriteBufferOperation.h"
+
+
+int DebugInfo::m_file_index = 0;
+DebugInfo::NodeNameMap DebugInfo::m_node_names;
+std::string DebugInfo::m_current_node_name;
+DebugInfo::GroupStateMap DebugInfo::m_group_states;
+
+std::string DebugInfo::node_name(NodeBase *node)
+{
+	NodeNameMap::const_iterator it = m_node_names.find(node);
+	if (it != m_node_names.end())
+		return it->second;
+	else
+		return "";
+}
+
+void DebugInfo::convert_started()
+{
+	m_node_names.clear();
+}
+
+void DebugInfo::execute_started(ExecutionSystem *system)
+{
+	m_file_index = 1;
+	m_group_states.clear();
+	for (int i = 0; i < system->getExecutionGroups().size(); ++i)
+		m_group_states[system->getExecutionGroups()[i]] = EG_WAIT;
+}
+
+void DebugInfo::node_added(Node *node)
+{
+	m_node_names[node] = std::string(node->getbNode() ? node->getbNode()->name : "");
+}
+
+void DebugInfo::node_to_operations(Node *node)
+{
+	m_current_node_name = m_node_names[node];
+}
+
+void DebugInfo::operation_added(NodeOperation *operation)
+{
+	m_node_names[operation] = m_current_node_name;
+}
+
+void DebugInfo::operation_read_write_buffer(NodeOperation *operation)
+{
+	m_current_node_name = m_node_names[operation];
+}
+
+void DebugInfo::execution_group_started(ExecutionGroup *group)
+{
+	m_group_states[group] = EG_RUNNING;
+}
+
+void DebugInfo::execution_group_finished(ExecutionGroup *group)
+{
+	m_group_states[group] = EG_FINISHED;
+}
+
+int DebugInfo::graphviz_operation(ExecutionSystem *system, NodeOperation *operation, ExecutionGroup *group, char *str, int maxlen)
+{
+	int len = 0;
+	
+	std::string fillcolor = "gainsboro";
+	if (operation->isViewerOperation()) {
+		ViewerOperation *viewer = (ViewerOperation *)operation;
+		if (viewer->isActiveViewerOutput()) {
+			fillcolor = "lightskyblue1";
+		}
+		else {
+			fillcolor = "lightskyblue3";
+		}
+	}
+	else if (operation->isOutputOperation(system->getContext().isRendering())) {
+		fillcolor = "dodgerblue1";
+	}
+	else if (operation->isSetOperation()) {
+		fillcolor = "khaki1";
+	}
+	else if (operation->isReadBufferOperation()) {
+		fillcolor = "darkolivegreen3";
+	}
+	else if (operation->isWriteBufferOperation()) {
+		fillcolor = "darkorange";
+	}
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "// OPERATION: %p\r\n", operation);
+	if (group)
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\"O_%p_%p\"", operation, group);
+	else
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\"O_%p\"", operation);
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, " [fillcolor=%s,style=filled,shape=record,label=\"{", fillcolor.c_str());
+	
+	int totinputs = operation->getNumberOfInputSockets();
+	if (totinputs != 0) {
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "{");
+		for (int k = 0; k < totinputs; k++) {
+			InputSocket *socket = operation->getInputSocket(k);
+			if (k != 0) {
+				len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "|");
+			}
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<IN_%p>", socket);
+			switch (socket->getDataType()) {
+				case COM_DT_VALUE:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Value");
+					break;
+				case COM_DT_VECTOR:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Vector");
+					break;
+				case COM_DT_COLOR:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Color");
+					break;
+			}
+		}
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}");
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "|");
+	}
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "%s\\n(%s)", m_node_names[operation].c_str(), typeid(*operation).name());
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, " (%d,%d)", operation->getWidth(), operation->getHeight());
+	
+	int totoutputs = operation->getNumberOfOutputSockets();
+	if (totoutputs != 0) {
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "|");
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "{");
+		for (int k = 0; k < totoutputs; k++) {
+			OutputSocket *socket = operation->getOutputSocket(k);
+			if (k != 0) {
+				len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "|");
+			}
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<OUT_%p>", socket);
+			switch (socket->getDataType()) {
+				case COM_DT_VALUE:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Value");
+					break;
+				case COM_DT_VECTOR:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Vector");
+					break;
+				case COM_DT_COLOR:
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Color");
+					break;
+			}
+		}
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}");
+	}
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}\"]");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\r\n");
+	
+	return len;
+}
+
+int DebugInfo::graphviz_legend_color(const char *name, const char *color, char *str, int maxlen)
+{
+	int len = 0;
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<TR><TD>%s</TD><TD BGCOLOR=\"%s\"></TD></TR>\r\n", name, color);
+	return len;
+}
+
+int DebugInfo::graphviz_legend_line(const char *name, const char *color, const char *style, char *str, int maxlen)
+{
+	/* XXX TODO */
+	int len = 0;
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\r\n");
+	return len;
+}
+
+int DebugInfo::graphviz_legend_group(const char *name, const char *color, const char *style, char *str, int maxlen)
+{
+	int len = 0;
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<TR><TD>%s</TD><TD CELLPADDING=\"4\"><TABLE BORDER=\"1\" CELLBORDER=\"0\" CELLSPACING=\"0\" CELLPADDING=\"0\"><TR><TD BGCOLOR=\"%s\"></TD></TR></TABLE></TD></TR>\r\n", name, color);
+	return len;
+}
+
+int DebugInfo::graphviz_legend(char *str, int maxlen)
+{
+	int len = 0;
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "{\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "rank = sink;\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "Legend [shape=none, margin=0, label=<\r\n");
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "  <TABLE BORDER=\"0\" CELLBORDER=\"1\" CELLSPACING=\"0\" CELLPADDING=\"4\">\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<TR><TD COLSPAN=\"2\"><B>Legend</B></TD></TR>\r\n");
+	
+	len += graphviz_legend_color("Operation", "gainsboro", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Output", "dodgerblue1", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Viewer", "lightskyblue3", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Active Viewer", "lightskyblue1", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Write Buffer", "darkorange", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Read Buffer", "darkolivegreen3", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_color("Input Value", "khaki1", str+len, maxlen>len ? maxlen-len : 0);
+
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "<TR><TD></TD></TR>\r\n");
+
+	len += graphviz_legend_group("Group Waiting", "white", "dashed", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_group("Group Running", "firebrick1", "solid", str+len, maxlen>len ? maxlen-len : 0);
+	len += graphviz_legend_group("Group Finished", "chartreuse4", "solid", str+len, maxlen>len ? maxlen-len : 0);
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "</TABLE>\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, ">];\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}\r\n");
+
+	return len;
+}
+
+bool DebugInfo::graphviz_system(ExecutionSystem *system, char *str, int maxlen)
+{
+	char strbuf[64];
+	int len = 0;
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "digraph compositorexecution {\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "ranksep=1.5\r\n");
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "splines=false\r\n");
+	
+	int totnodes = system->getNodes().size();
+	for (int i = 0; i < totnodes; i++) {
+		Node *node = system->getNodes()[i];
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "// NODE: %s\r\n", node->getbNode()->typeinfo->ui_name);
+	}
+	
+	int totgroups = system->getExecutionGroups().size();
+	int totops = system->getOperations().size();
+	std::map<NodeOperation *, std::vector<std::string> > op_groups;
+	for (int i = 0; i < totgroups; ++i) {
+		ExecutionGroup *group = system->getExecutionGroups()[i];
+		
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "// GROUP: %d\r\n", i);
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "subgraph cluster_%d{\r\n", i);
+		/* used as a check for executing group */
+		if (m_group_states[group] == EG_WAIT) {
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "style=dashed\r\n");
+		}
+		else if (m_group_states[group] == EG_RUNNING) {
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "style=filled\r\n");
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "color=black\r\n");
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "fillcolor=firebrick1\r\n");
+		}
+		else if (m_group_states[group] == EG_FINISHED) {
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "style=filled\r\n");
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "color=black\r\n");
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "fillcolor=chartreuse4\r\n");
+		}
+		
+		for (int j = 0; j < totops; ++j) {
+			NodeOperation *operation = system->getOperations()[j];
+			if (!group->containsOperation(operation))
+				continue;
+			
+			sprintf(strbuf, "_%p", group);
+			op_groups[operation].push_back(std::string(strbuf));
+			
+			len += graphviz_operation(system, operation, group, str+len, maxlen>len ? maxlen-len : 0);
+		}
+		
+//		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "//  OUTPUTOPERATION: %p\r\n", group->getOutputNodeOperation());
+//		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, " O_%p\r\n", group->getOutputNodeOperation());
+		len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}\r\n");
+	}
+	
+	/* operations not included in any group */
+	for (int j = 0; j < totops; ++j) {
+		NodeOperation *operation = system->getOperations()[j];
+		if (op_groups.find(operation) != op_groups.end())
+			continue;
+		
+		op_groups[operation].push_back(std::string(""));
+		
+		len += graphviz_operation(system, operation, 0, str+len, maxlen>len ? maxlen-len : 0);
+	}
+	
+	for (int i = 0; i < totops; i++) {
+		NodeOperation *operation = system->getOperations()[i];
+		
+		if (operation->isReadBufferOperation()) {
+			ReadBufferOperation *read = (ReadBufferOperation *)operation;
+			WriteBufferOperation *write = read->getMemoryProxy()->getWriteBufferOperation();
+			std::vector<std::string> &read_groups = op_groups[read];
+			std::vector<std::string> &write_groups = op_groups[write];
+			
+			for (int k = 0; k < write_groups.size(); ++k) {
+				for (int l = 0; l < read_groups.size(); ++l) {
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\"O_%p%s\" -> \"O_%p%s\" [style=dotted]\r\n", write, write_groups[k].c_str(), read, read_groups[l].c_str());
+				}
+			}
+		}
+	}
+	
+	int totcon = system->getConnections().size();
+	for (int i = 0; i < totcon; i++) {
+		SocketConnection *connection = system->getConnections()[i];
+		
+		std::string color;
+		if (!connection->isValid()) {
+			color = "red";
+		}
+		else {
+			switch (connection->getFromSocket()->getDataType()) {
+				case COM_DT_VALUE:
+					color = "grey";
+					break;
+				case COM_DT_VECTOR:
+					color = "blue";
+					break;
+				case COM_DT_COLOR:
+					color = "orange";
+					break;
+			}
+		}
+		
+		NodeBase *from_node = connection->getFromNode();
+		NodeBase *to_node = connection->getToNode();
+		OutputSocket *from_sock = connection->getFromSocket();
+		InputSocket *to_sock = connection->getToSocket();
+		if (from_node->isOperation() && to_node->isOperation()) {
+			NodeOperation *from_op = (NodeOperation *)from_node;
+			NodeOperation *to_op = (NodeOperation *)to_node;
+			std::vector<std::string> &from_groups = op_groups[from_op];
+			std::vector<std::string> &to_groups = op_groups[to_op];
+			
+			len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "// CONNECTION: %p.%p -> %p.%p\r\n", from_op, from_sock, to_op, to_sock);
+			for (int k = 0; k < from_groups.size(); ++k) {
+				for (int l = 0; l < to_groups.size(); ++l) {
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\"O_%p%s\":\"OUT_%p\":s -> \"O_%p%s\":\"IN_%p\":n", from_op, from_groups[k].c_str(), from_sock, to_op, to_groups[l].c_str(), to_sock);
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, " [color=%s]", color.c_str());
+					len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "\r\n");
+				}
+			}
+		}
+	}
+	
+	len += graphviz_legend(str+len, maxlen>len ? maxlen-len : 0);
+	
+	len += snprintf(str+len, maxlen>len ? maxlen-len : 0, "}\r\n");
+	
+	return (len < maxlen);
+}
+
+void DebugInfo::graphviz(ExecutionSystem *system)
+{
+	char str[1000000];
+	if (graphviz_system(system, str, sizeof(str)-1)) {
+		char basename[FILE_MAX];
+		char filename[FILE_MAX];
+		
+		BLI_snprintf(basename, sizeof(basename), "compositor_%d.dot", m_file_index);
+		BLI_join_dirfile(filename, sizeof(filename), BLI_temporary_dir(), basename);
+		++m_file_index;
+		
+		FILE *fp = BLI_fopen(filename, "wb");
+		fputs(str, fp);
+		fclose(fp);
+	}
+}
+
+#else
+
+std::string DebugInfo::node_name(NodeBase */*node*/) { return ""; }
+void DebugInfo::convert_started() {}
+void DebugInfo::execute_started(ExecutionSystem */*system*/) {}
+void DebugInfo::node_added(Node */*node*/) {}
+void DebugInfo::node_to_operations(Node */*node*/) {}
+void DebugInfo::operation_added(NodeOperation */*operation*/) {}
+void DebugInfo::operation_read_write_buffer(NodeOperation */*operation*/) {}
+void DebugInfo::execution_group_started(ExecutionGroup */*group*/) {}
+void DebugInfo::execution_group_finished(ExecutionGroup */*group*/) {}
+void DebugInfo::graphviz(ExecutionSystem */*system*/) {}
+
+#endif