Cycles: Add sample-based runtime profiler that measures time spent in various parts of the CPU kernel

This commit adds a sample-based profiler that runs during CPU rendering and collects statistics on time spent in different parts of the kernel (ray intersection, shader evaluation etc.) as well as time spent per material and object.

The results are currently not exposed in the user interface or per Python yet, to see the stats on the console pass the "--cycles-print-stats" argument to Cycles (e.g. "./blender -- --cycles-print-stats").

Unfortunately, there is no clear way to extend this functionality to CUDA or OpenCL, so it is CPU-only for now.

Reviewers: brecht, sergey, swerner

Reviewed By: brecht, swerner

Differential Revision: https://developer.blender.org/D3892

1 files changed, 194 insertions, 0 deletions

diff --git a/intern/cycles/render/stats.cpp b/intern/cycles/render/stats.cpp
index 101d33fcf65..71d9353ad3d 100644
--- a/intern/cycles/render/stats.cpp
+++ b/intern/cycles/render/stats.cpp
@@ -15,6 +15,7 @@
  */
 
 #include "render/stats.h"
+#include "render/object.h"
 #include "util/util_algorithm.h"
 #include "util/util_foreach.h"
 #include "util/util_string.h"
@@ -33,6 +34,16 @@ bool namedSizeEntryComparator(const NamedSizeEntry& a, const NamedSizeEntry& b)
 	return a.size > b.size;
 }
 
+bool namedTimeSampleEntryComparator(const NamedNestedSampleStats& a, const NamedNestedSampleStats& b)
+{
+	return a.sum_samples > b.sum_samples;
+}
+
+bool namedSampleCountPairComparator(const NamedSampleCountPair& a, const NamedSampleCountPair& b)
+{
+	return a.samples > b.samples;
+}
+
 }  // namespace
 
 NamedSizeEntry::NamedSizeEntry()
@@ -77,6 +88,113 @@ string NamedSizeStats::full_report(int indent_level)
 	return result;
 }
 
+/* Named time sample statistics. */
+
+NamedNestedSampleStats::NamedNestedSampleStats()
+ : name(""), self_samples(0), sum_samples(0)
+{}
+
+NamedNestedSampleStats::NamedNestedSampleStats(const string& name, uint64_t samples)
+ : name(name), self_samples(samples), sum_samples(samples)
+{}
+
+NamedNestedSampleStats& NamedNestedSampleStats::add_entry(const string& name_, uint64_t samples_)
+{
+	entries.push_back(NamedNestedSampleStats(name_, samples_));
+	return entries[entries.size()-1];
+}
+
+void NamedNestedSampleStats::update_sum()
+{
+	sum_samples = self_samples;
+	foreach(NamedNestedSampleStats& entry, entries) {
+		entry.update_sum();
+		sum_samples += entry.sum_samples;
+	}
+}
+
+string NamedNestedSampleStats::full_report(int indent_level, uint64_t total_samples)
+{
+	update_sum();
+
+	if(total_samples == 0) {
+		total_samples = sum_samples;
+	}
+
+	const string indent(indent_level * kIndentNumSpaces, ' ');
+
+	const double sum_percent = 100*((double) sum_samples) / total_samples;
+	const double sum_seconds = sum_samples * 0.001;
+	const double self_percent = 100*((double) self_samples) / total_samples;
+	const double self_seconds = self_samples * 0.001;
+	string info = string_printf("%-32s: Total %3.2f%% (%.2fs), Self %3.2f%% (%.2fs)\n",
+	                            name.c_str(),
+	                            sum_percent,
+	                            sum_seconds,
+	                            self_percent,
+	                            self_seconds);
+	string result = indent + info; 
+
+	sort(entries.begin(), entries.end(), namedTimeSampleEntryComparator);
+	foreach(NamedNestedSampleStats& entry, entries) {
+		result += entry.full_report(indent_level + 1, total_samples);
+	}
+	return result;
+}
+
+/* Named sample count pairs. */
+
+NamedSampleCountPair::NamedSampleCountPair(const ustring& name, uint64_t samples, uint64_t hits)
+ : name(name), samples(samples), hits(hits)
+{}
+
+NamedSampleCountStats::NamedSampleCountStats()
+{}
+
+void NamedSampleCountStats::add(const ustring& name, uint64_t samples, uint64_t hits)
+{
+	entry_map::iterator entry = entries.find(name);
+	if(entry != entries.end()) {
+		entry->second.samples += samples;
+		entry->second.hits += hits;
+		return;
+	}
+	entries.emplace(name, NamedSampleCountPair(name, samples, hits));
+}
+
+string NamedSampleCountStats::full_report(int indent_level)
+{
+	const string indent(indent_level * kIndentNumSpaces, ' ');
+
+	vector<NamedSampleCountPair> sorted_entries;
+	sorted_entries.reserve(entries.size());
+
+	uint64_t total_hits = 0, total_samples = 0;
+	foreach(entry_map::const_reference entry, entries) {
+		const NamedSampleCountPair &pair = entry.second;
+
+		total_hits += pair.hits;
+		total_samples += pair.samples;
+
+		sorted_entries.push_back(pair);
+	}
+	const double avg_samples_per_hit = ((double) total_samples) / total_hits;
+
+	sort(sorted_entries.begin(), sorted_entries.end(), namedSampleCountPairComparator);
+
+	string result = "";
+	foreach(const NamedSampleCountPair& entry, sorted_entries) {
+		const double seconds = entry.samples * 0.001;
+		const double relative = ((double) entry.samples) / (entry.hits * avg_samples_per_hit);
+
+		result += indent + string_printf("%-32s: %.2fs (Relative cost: %.2f)\n",
+		                                 entry.name.c_str(),
+		                                 seconds,
+		                                 relative);
+	}
+	return result;
+}
+
 /* Mesh statistics. */
 
 MeshStats::MeshStats() {
@@ -106,6 +224,74 @@ string ImageStats::full_report(int indent_level)
 /* Overall statistics. */
 
 RenderStats::RenderStats() {
+	has_profiling = false;
+}
+
+void RenderStats::collect_profiling(Scene *scene, Stats *stats)
+{
+	has_profiling = true;
+
+	Profiler &prof = stats->profiler;
+
+	kernel = NamedNestedSampleStats("Total render time", prof.get_event(PROFILING_UNKNOWN));
+
+	kernel.add_entry("Ray setup", prof.get_event(PROFILING_RAY_SETUP));
+	kernel.add_entry("Result writing", prof.get_event(PROFILING_WRITE_RESULT));
+
+	NamedNestedSampleStats &integrator = kernel.add_entry("Path integration", prof.get_event(PROFILING_PATH_INTEGRATE));
+	integrator.add_entry("Scene intersection", prof.get_event(PROFILING_SCENE_INTERSECT));
+	integrator.add_entry("Indirect emission", prof.get_event(PROFILING_INDIRECT_EMISSION));
+	integrator.add_entry("Volumes", prof.get_event(PROFILING_VOLUME));
+
+	NamedNestedSampleStats &shading = integrator.add_entry("Shading", 0);
+	shading.add_entry("Shader Setup", prof.get_event(PROFILING_SHADER_SETUP));
+	shading.add_entry("Shader Eval", prof.get_event(PROFILING_SHADER_EVAL));
+	shading.add_entry("Shader Apply", prof.get_event(PROFILING_SHADER_APPLY));
+	shading.add_entry("Ambient Occlusion", prof.get_event(PROFILING_AO));
+	shading.add_entry("Subsurface", prof.get_event(PROFILING_SUBSURFACE));
+
+	integrator.add_entry("Connect Light", prof.get_event(PROFILING_CONNECT_LIGHT));
+	integrator.add_entry("Surface Bounce", prof.get_event(PROFILING_SURFACE_BOUNCE));
+
+	NamedNestedSampleStats &intersection = kernel.add_entry("Intersection", 0);
+	intersection.add_entry("Full Intersection", prof.get_event(PROFILING_INTERSECT));
+	intersection.add_entry("Local Intersection", prof.get_event(PROFILING_INTERSECT_LOCAL));
+	intersection.add_entry("Shadow All Intersection", prof.get_event(PROFILING_INTERSECT_SHADOW_ALL));
+	intersection.add_entry("Volume Intersection", prof.get_event(PROFILING_INTERSECT_VOLUME));
+	intersection.add_entry("Volume All Intersection", prof.get_event(PROFILING_INTERSECT_VOLUME_ALL));
+
+	NamedNestedSampleStats &closure = kernel.add_entry("Closures", 0);
+	closure.add_entry("Surface Closure Evaluation", prof.get_event(PROFILING_CLOSURE_EVAL));
+	closure.add_entry("Surface Closure Sampling", prof.get_event(PROFILING_CLOSURE_SAMPLE));
+	closure.add_entry("Volume Closure Evaluation", prof.get_event(PROFILING_CLOSURE_VOLUME_EVAL));
+	closure.add_entry("Volume Closure Sampling", prof.get_event(PROFILING_CLOSURE_VOLUME_SAMPLE));
+
+	NamedNestedSampleStats &denoising = kernel.add_entry("Denoising", prof.get_event(PROFILING_DENOISING));
+	denoising.add_entry("Construct Transform", prof.get_event(PROFILING_DENOISING_CONSTRUCT_TRANSFORM));
+	denoising.add_entry("Reconstruct", prof.get_event(PROFILING_DENOISING_RECONSTRUCT));
+
+	NamedNestedSampleStats &prefilter = denoising.add_entry("Prefiltering", 0);
+	prefilter.add_entry("Divide Shadow", prof.get_event(PROFILING_DENOISING_DIVIDE_SHADOW));
+	prefilter.add_entry("Non-Local means", prof.get_event(PROFILING_DENOISING_NON_LOCAL_MEANS));
+	prefilter.add_entry("Get Feature", prof.get_event(PROFILING_DENOISING_GET_FEATURE));
+	prefilter.add_entry("Detect Outliers", prof.get_event(PROFILING_DENOISING_DETECT_OUTLIERS));
+	prefilter.add_entry("Combine Halves", prof.get_event(PROFILING_DENOISING_COMBINE_HALVES));
+
+	shaders.entries.clear();
+	foreach(Shader *shader, scene->shaders) {
+		uint64_t samples, hits;
+		if(prof.get_shader(shader->id, samples, hits)) {
+			shaders.add(shader->name, samples, hits);
+		}
+	}
+
+	objects.entries.clear();
+	foreach(Object *object, scene->objects) {
+		uint64_t samples, hits;
+		if(prof.get_object(object->get_device_index(), samples, hits)) {
+			objects.add(object->name, samples, hits);
+		}
+	}
 }
 
 string RenderStats::full_report()
@@ -113,6 +299,14 @@ string RenderStats::full_report()
 	string result = "";
 	result += "Mesh statistics:\n" + mesh.full_report(1);
 	result += "Image statistics:\n" + image.full_report(1);
+	if(has_profiling) {
+		result += "Kernel statistics:\n" + kernel.full_report(1);
+		result += "Shader statistics:\n" + shaders.full_report(1);
+		result += "Object statistics:\n" + objects.full_report(1);
+	}
+	else {
+		result += "Profiling information not available (only works with CPU rendering)";
+	}
 	return result;
 }