Cycles: Add logging to OSL and CUDA initialization/compilation

This is what was handy troubleshooting issues in the studio,
plus this is exactly the same thing which would be helpful
when solving issues with paths to compiled shaders and cubins
for standalone repository.

4 files changed, 51 insertions, 10 deletions

diff --git a/intern/cycles/app/cycles_server.cpp b/intern/cycles/app/cycles_server.cpp
index f471c2d0972..3d5b237eec1 100644
--- a/intern/cycles/app/cycles_server.cpp
+++ b/intern/cycles/app/cycles_server.cpp
@@ -29,13 +29,14 @@ using namespace ccl;
 
 int main(int argc, const char **argv)
 {
+	util_logging_init(argv[0]);
 	path_init();
 
 	/* device types */
 	string devicelist = "";
 	string devicename = "cpu";
-	bool list = false;
-	int threads = 0;
+	bool list = false, debug = false;
+	int threads = 0, verbosity = 1;
 
 	vector<DeviceType>& types = Device::available_types();
 
@@ -53,6 +54,10 @@ int main(int argc, const char **argv)
 		"--device %s", &devicename, ("Devices to use: " + devicelist).c_str(),
 		"--list-devices", &list, "List information about all available devices",
 		"--threads %d", &threads, "Number of threads to use for CPU device",
+#ifdef WITH_CYCLES_LOGGING
+		"--debug", &debug, "Enable debug logging",
+		"--verbose %d", &verbosity, "Set verbosity of the logger",
+#endif
 		NULL);
 
 	if(ap.parse(argc, argv) < 0) {
@@ -60,7 +65,13 @@ int main(int argc, const char **argv)
 		ap.usage();
 		exit(EXIT_FAILURE);
 	}
-	else if(list) {
+
+	if (debug) {
+		util_logging_start();
+		util_logging_verbosity_set(verbosity);
+	}
+
+	if(list) {
 		vector<DeviceInfo>& devices = Device::available_devices();
 
 		printf("Devices:\n");
diff --git a/intern/cycles/app/cycles_standalone.cpp b/intern/cycles/app/cycles_standalone.cpp
index ce3fb966b8c..c2daa8f0b1a 100644
--- a/intern/cycles/app/cycles_standalone.cpp
+++ b/intern/cycles/app/cycles_standalone.cpp
@@ -320,6 +320,11 @@ static void options_parse(int argc, const char **argv)
 
 	vector<DeviceType>& types = Device::available_types();
 
+	/* TODO(sergey): Here's a feedback loop happens: on the one hand we want
+	 * the device list to be printed in help message, on the other hand logging
+	 * is not initialized yet so we wouldn't have debug log happening in the
+	 * device initialization.
+	 */
 	foreach(DeviceType type, types) {
 		if(device_names != "")
 			device_names += ", ";
diff --git a/intern/cycles/device/device_cuda.cpp b/intern/cycles/device/device_cuda.cpp
index 1e008f45c07..bda967c1de3 100644
--- a/intern/cycles/device/device_cuda.cpp
+++ b/intern/cycles/device/device_cuda.cpp
@@ -25,6 +25,7 @@
 
 #include "cuew.h"
 #include "util_debug.h"
+#include "util_logging.h"
 #include "util_map.h"
 #include "util_opengl.h"
 #include "util_path.h"
@@ -209,8 +210,11 @@ public:
 			cubin = path_get(string_printf("lib/kernel_experimental_sm_%d%d.cubin", major, minor));
 		else
 			cubin = path_get(string_printf("lib/kernel_sm_%d%d.cubin", major, minor));
-		if(path_exists(cubin))
+		VLOG(1) << "Testing for pre-compiled kernel " << cubin;
+		if(path_exists(cubin)) {
+			VLOG(1) << "Using precompiled kernel";
 			return cubin;
+		}
 
 		/* not found, try to use locally compiled kernel */
 		string kernel_path = path_get("kernel");
@@ -221,10 +225,12 @@ public:
 		else
 			cubin = string_printf("cycles_kernel_sm%d%d_%s.cubin", major, minor, md5.c_str());
 		cubin = path_user_get(path_join("cache", cubin));
-
+		VLOG(1) << "Testing for locally compiled kernel " << cubin;
 		/* if exists already, use it */
-		if(path_exists(cubin))
+		if(path_exists(cubin)) {
+			VLOG(1) << "Using locally compiled kernel";
 			return cubin;
+		}
 
 #ifdef _WIN32
 		if(have_precompiled_kernels()) {
@@ -245,6 +251,7 @@ public:
 		}
 
 		int cuda_version = cuewCompilerVersion();
+		VLOG(1) << "Found nvcc " << nvcc << ", CUDA version " << cuda_version;
 
 		if(cuda_version == 0) {
 			cuda_error_message("CUDA nvcc compiler version could not be parsed.");
@@ -1026,15 +1033,30 @@ bool device_cuda_init(void)
 		return result;
 
 	initialized = true;
-
-	if (cuewInit() == CUEW_SUCCESS) {
-		if(CUDADevice::have_precompiled_kernels())
+	int cuew_result = cuewInit();
+	if (cuew_result == CUEW_SUCCESS) {
+		VLOG(1) << "CUEW initialization succeeded";
+		if(CUDADevice::have_precompiled_kernels()) {
+			VLOG(1) << "Found precompiled  kernels";
 			result = true;
+		}
 #ifndef _WIN32
-		else if(cuewCompilerPath() != NULL)
+		else if(cuewCompilerPath() != NULL) {
+			VLOG(1) << "Found CUDA compiled " << cuewCompilerPath();
 			result = true;
+		}
+		else {
+			VLOG(1) << "Neither precompiled kernels nor CUDA compiler wad found,"
+			        << " unable to use CUDA";
+		}
 #endif
 	}
+	else {
+		VLOG(1) << "CUEW initialization failed: "
+		        << ((cuew_result == CUEW_ERROR_ATEXIT_FAILED)
+		            ? "Error setting up atexit() handler"
+		            : "Error opening the library");
+	}
 
 	return result;
 }
diff --git a/intern/cycles/render/osl.cpp b/intern/cycles/render/osl.cpp
index 96ea203213a..08d69386724 100644
--- a/intern/cycles/render/osl.cpp
+++ b/intern/cycles/render/osl.cpp
@@ -30,6 +30,7 @@
 #include "osl_shader.h"
 
 #include "util_foreach.h"
+#include "util_logging.h"
 #include "util_md5.h"
 #include "util_path.h"
 #include "util_progress.h"
@@ -194,6 +195,8 @@ void OSLShaderManager::shading_system_init()
 		ss_shared->attribute("searchpath:shader", path_get("shader"));
 		//ss_shared->attribute("greedyjit", 1);
 
+		VLOG(1) << "Using shader search path: " << path_get("shader");
+
 		/* our own ray types */
 		static const char *raytypes[] = {
 			"camera",			/* PATH_RAY_CAMERA */