From 5ab3a97dbbcfe2cb2bc7093f5e18a195eb31f080 Mon Sep 17 00:00:00 2001
From: Sergey Sharybin <sergey.vfx@gmail.com>
Date: Mon, 4 Apr 2016 13:43:19 +0200
Subject: Cycles: Log overall time spent on building object's BVH

We had per-tree statistics already, but it's a bit tricky to see overall
time because trees could be building in parallel.

In fact, we can now print statistics for any TaskPool.
---
 intern/cycles/render/mesh.cpp    |  6 +++++-
 intern/cycles/util/util_task.cpp | 21 ++++++++++++++++++++-
 intern/cycles/util/util_task.h   | 24 +++++++++++++++++++++++-
 3 files changed, 48 insertions(+), 3 deletions(-)

diff --git a/intern/cycles/render/mesh.cpp b/intern/cycles/render/mesh.cpp
index e565b25e193..6466d719859 100644
--- a/intern/cycles/render/mesh.cpp
+++ b/intern/cycles/render/mesh.cpp
@@ -1317,7 +1317,11 @@ void MeshManager::device_update(Device *device, DeviceScene *dscene, Scene *scen
 		}
 	}
 
-	pool.wait_work();
+	TaskPool::Summary summary;
+	pool.wait_work(&summary);
+	VLOG(2) << "Objects BVH build pool statistics:\n"
+	        << summary.full_report();
+
 	foreach(Shader *shader, scene->shaders)
 		shader->need_update_attributes = false;
 
diff --git a/intern/cycles/util/util_task.cpp b/intern/cycles/util/util_task.cpp
index 28bbc8856c6..d3aef6c7496 100644
--- a/intern/cycles/util/util_task.cpp
+++ b/intern/cycles/util/util_task.cpp
@@ -18,6 +18,7 @@
 #include "util_foreach.h"
 #include "util_system.h"
 #include "util_task.h"
+#include "util_time.h"
 
 //#define THREADING_DEBUG_ENABLED
 
@@ -34,6 +35,7 @@ CCL_NAMESPACE_BEGIN
 
 TaskPool::TaskPool()
 {
+	num_tasks_handled = 0;
 	num = 0;
 	do_cancel = false;
 }
@@ -58,7 +60,7 @@ void TaskPool::push(const TaskRunFunction& run, bool front)
 	push(new Task(run), front);
 }
 
-void TaskPool::wait_work()
+void TaskPool::wait_work(Summary *stats)
 {
 	thread_scoped_lock num_lock(num_mutex);
 
@@ -108,6 +110,11 @@ void TaskPool::wait_work()
 			THREADING_DEBUG("num==%d, condition wait done in TaskPool::wait_work !found_entry\n", num);
 		}
 	}
+
+	if(stats != NULL) {
+		stats->time_total = time_dt() - start_time;
+		stats->num_tasks_handled = num_tasks_handled;
+	}
 }
 
 void TaskPool::cancel()
@@ -158,7 +165,11 @@ void TaskPool::num_decrease(int done)
 void TaskPool::num_increase()
 {
 	thread_scoped_lock num_lock(num_mutex);
+	if(num_tasks_handled == 0) {
+		start_time = time_dt();
+	}
 	num++;
+	num_tasks_handled++;
 	THREADING_DEBUG("num==%d, notifying all in TaskPool::num_increase\n", num);
 	num_cond.notify_all();
 }
@@ -450,5 +461,13 @@ void DedicatedTaskPool::clear()
 	num_decrease(done);
 }
 
+string TaskPool::Summary::full_report() const
+{
+	string report = "";
+	report += string_printf("Total time:    %f\n", time_total);
+	report += string_printf("Tasks handled: %d\n", num_tasks_handled);
+	return report;
+}
+
 CCL_NAMESPACE_END
 
diff --git a/intern/cycles/util/util_task.h b/intern/cycles/util/util_task.h
index 2ce26fa7103..d697ebf35a4 100644
--- a/intern/cycles/util/util_task.h
+++ b/intern/cycles/util/util_task.h
@@ -18,6 +18,7 @@
 #define __UTIL_TASK_H__
 
 #include "util_list.h"
+#include "util_string.h"
 #include "util_thread.h"
 #include "util_vector.h"
 
@@ -70,13 +71,26 @@ public:
 class TaskPool
 {
 public:
+	struct Summary {
+		/* Time spent to handle all tasks. */
+		double time_total;
+
+		/* Number of all tasks handled by this pool. */
+		int num_tasks_handled;
+
+		/* A full multiline description of the state of the pool after
+		 * all work is done.
+		 */
+		string full_report() const;
+	};
+
 	TaskPool();
 	~TaskPool();
 
 	void push(Task *task, bool front = false);
 	void push(const TaskRunFunction& run, bool front = false);
 
-	void wait_work();	/* work and wait until all tasks are done */
+	void wait_work(Summary *stats = NULL);	/* work and wait until all tasks are done */
 	void cancel();		/* cancel all tasks, keep worker threads running */
 	void stop();		/* stop all worker threads */
 
@@ -93,6 +107,14 @@ protected:
 
 	int num;
 	bool do_cancel;
+
+	/* ** Statistics ** */
+
+	/* Time time stamp of first task pushed. */
+	double start_time;
+
+	/* Number of all tasks handled by this pool. */
+	int num_tasks_handled;
 };
 
 /* Task Scheduler
-- 
cgit v1.2.3