Cycles: Add timing information to the SVM compiler stats

intern/cycles/render/svm.cpp

@@ -718,20 +718,31 @@ void SVMCompiler::compile(Scene *scene,
 	ShaderNode *node = shader->graph->output();
 	int start_num_svm_nodes = global_svm_nodes.size();
 
+	const double time_total_start = time_dt();
+	double time_finalize = 0.0, time_finalize_bump = 0.0;
+	double time_generate_surface = 0.0,
+	       time_generate_bump = 0.0,
+	       time_generate_volume = 0.0,
+	       time_generate_displacement = 0.0;
+
 	if(node->input("Surface")->link && node->input("Displacement")->link)
 		if(!shader->graph_bump)
 			shader->graph_bump = shader->graph->copy();
 
 	/* finalize */
+	double time_start = time_dt();
 	shader->graph->finalize(scene,
 	                        false,
 	                        false,
 	                        shader->has_integrator_dependency);
+	time_finalize = time_dt() - time_start;
 	if(shader->graph_bump) {
+		time_start = time_dt();
 		shader->graph_bump->finalize(scene,
 		                             true,
 		                             false,
 		                             shader->has_integrator_dependency);
+		time_finalize_bump = time_dt() - time_start;
 	}
 
 	current_shader = shader;
@@ -748,31 +759,47 @@ void SVMCompiler::compile(Scene *scene,
 	shader->has_integrator_dependency = false;
 
 	/* generate surface shader */
+	/* TODO(sergey): Add some utility to evaluate time of a scope. */
+	time_start = time_dt();
 	compile_type(shader, shader->graph, SHADER_TYPE_SURFACE);
 	global_svm_nodes[index*2 + 0].y = global_svm_nodes.size();
 	global_svm_nodes[index*2 + 1].y = global_svm_nodes.size();
 	global_svm_nodes.insert(global_svm_nodes.end(), svm_nodes.begin(), svm_nodes.end());
+	time_generate_surface = time_dt() - time_start;
 
 	if(shader->graph_bump) {
+		time_start = time_dt();
 		compile_type(shader, shader->graph_bump, SHADER_TYPE_SURFACE);
 		global_svm_nodes[index*2 + 1].y = global_svm_nodes.size();
 		global_svm_nodes.insert(global_svm_nodes.end(), svm_nodes.begin(), svm_nodes.end());
+		time_generate_bump = time_dt() - time_start;
 	}
 
 	/* generate volume shader */
+	time_start = time_dt();
 	compile_type(shader, shader->graph, SHADER_TYPE_VOLUME);
 	global_svm_nodes[index*2 + 0].z = global_svm_nodes.size();
 	global_svm_nodes[index*2 + 1].z = global_svm_nodes.size();
 	global_svm_nodes.insert(global_svm_nodes.end(), svm_nodes.begin(), svm_nodes.end());
+	time_generate_volume = time_dt() - time_start;
 
 	/* generate displacement shader */
+	time_start = time_dt();
 	compile_type(shader, shader->graph, SHADER_TYPE_DISPLACEMENT);
 	global_svm_nodes[index*2 + 0].w = global_svm_nodes.size();
 	global_svm_nodes[index*2 + 1].w = global_svm_nodes.size();
 	global_svm_nodes.insert(global_svm_nodes.end(), svm_nodes.begin(), svm_nodes.end());
+	time_generate_displacement = time_dt() - time_start;
 
 	/* Fill in summary information. */
 	if(summary != NULL) {
+		summary->time_total = time_dt() - time_total_start;
+		summary->time_finalize = time_finalize;
+		summary->time_finalize_bump = time_finalize_bump;
+		summary->time_generate_surface = time_generate_surface;
+		summary->time_generate_bump = time_generate_bump;
+		summary->time_generate_volume = time_generate_volume;
+		summary->time_generate_displacement = time_generate_displacement;
 		summary->peak_stack_usage = max_stack_use;
 		summary->num_svm_nodes = global_svm_nodes.size() - start_num_svm_nodes;
 	}
@@ -782,7 +809,14 @@ void SVMCompiler::compile(Scene *scene,
 
 SVMCompiler::Summary::Summary()
 	: num_svm_nodes(0),
-	  peak_stack_usage(0)
+	  peak_stack_usage(0),
+	  time_finalize(0.0),
+	  time_finalize_bump(0.0),
+	  time_generate_surface(0.0),
+	  time_generate_bump(0.0),
+	  time_generate_volume(0.0),
+	  time_generate_displacement(0.0),
+	  time_total(0.0)
 {
 }
 
@@ -790,7 +824,23 @@ string SVMCompiler::Summary::full_report() const
 {
 	string report = "";
 	report += string_printf("Number of SVM nodes: %d\n", num_svm_nodes);
-	report += string_printf("Peak stack usage:    %d", peak_stack_usage);
+	report += string_printf("Peak stack usage:    %d\n", peak_stack_usage);
+
+	report += string_printf("Time (in seconds):\n");
+	report += string_printf("  Finalize:          %f\n", time_finalize);
+	report += string_printf("  Bump finalize:     %f\n", time_finalize_bump);
+	report += string_printf("Finalize:            %f\n", time_finalize +
+	                                                     time_finalize_bump);
+	report += string_printf("  Surface:           %f\n", time_generate_surface);
+	report += string_printf("  Bump:              %f\n", time_generate_bump);
+	report += string_printf("  Volume:            %f\n", time_generate_volume);
+	report += string_printf("  Displacement:      %f\n", time_generate_displacement);
+	report += string_printf("Generate:            %f\n", time_generate_surface +
+	                                                     time_generate_bump +
+	                                                     time_generate_volume +
+	                                                     time_generate_displacement);
+	report += string_printf("Total:               %f\n", time_total);
+
 	return report;
 }
 

intern/cycles/render/svm.h

@@ -61,6 +61,27 @@ public:
 		/* Peak stack usage during shader evaluation. */
 		int peak_stack_usage;
 
+		/* Time spent on surface graph finalization. */
+		double time_finalize;
+
+		/* Time spent on bump graph finalization. */
+		double time_finalize_bump;
+
+		/* Time spent on generating SVM nodes for surface shader. */
+		double time_generate_surface;
+
+		/* Time spent on generating SVM nodes for bump shader. */
+		double time_generate_bump;
+
+		/* Time spent on generating SVM nodes for volume shader. */
+		double time_generate_volume;
+
+		/* Time spent on generating SVM nodes for displacement shader. */
+		double time_generate_displacement;
+
+		/* Total time spent on all routines. */
+		double time_total;
+
 		/* A full multiline description of the state of the compiler after
 		 * compilation.
 		 */