Added a VERBOSE mode to debug performance: now prints details about compilation and kernel execution to screen

3 files changed, 41 insertions, 0 deletions

diff --git a/src/clpp11.hpp b/src/clpp11.hpp
index 2b21e1e1..fcb71e38 100644
--- a/src/clpp11.hpp
+++ b/src/clpp11.hpp
@@ -664,6 +664,16 @@ class Kernel {
     return result;
   }
 
+  // Retrieves the name of the kernel
+  std::string GetFunctionName() {
+    auto bytes = size_t{0};
+    CheckError(clGetKernelInfo(*kernel_, CL_KERNEL_FUNCTION_NAME, 0, nullptr, &bytes));
+    auto result = std::string{};
+    result.resize(bytes);
+    CheckError(clGetKernelInfo(*kernel_, CL_KERNEL_FUNCTION_NAME, bytes, &result[0], nullptr));
+    return std::string{result.c_str()}; // Removes any trailing '\0'-characters
+  }
+
   // Launches a kernel onto the specified queue
   void Launch(const Queue &queue, const std::vector<size_t> &global,
               const std::vector<size_t> &local, EventPointer event) {
diff --git a/src/routine.cpp b/src/routine.cpp
index d3590896..3c3343da 100644
--- a/src/routine.cpp
+++ b/src/routine.cpp
@@ -13,6 +13,7 @@
 
 #include <string>
 #include <vector>
+#include <chrono>
 
 #include "routine.hpp"
 
@@ -103,6 +104,13 @@ StatusCode Routine::SetUp() {
   // Combines everything together into a single source string
   const auto source_string = defines + common_header + source_string_;
 
+  // Prints details of the routine to compile in case of debugging in verbose mode
+  #ifdef VERBOSE
+    printf("[DEBUG] Compiling routine '%s-%s' for device '%s'\n",
+           routine_name_.c_str(), ToString(precision_).c_str(), device_name_.c_str());
+    const auto start_time = std::chrono::steady_clock::now();
+  #endif
+
   // Compiles the kernel
   try {
     auto program = Program(context_, source_string);
@@ -123,6 +131,13 @@ StatusCode Routine::SetUp() {
     StoreProgramToCache(program, context_, precision_, routine_name_);
   } catch (...) { return StatusCode::kBuildProgramFailure; }
 
+  // Prints the elapsed compilation time in case of debugging in verbose mode
+  #ifdef VERBOSE
+    const auto elapsed_time = std::chrono::steady_clock::now() - start_time;
+    const auto timing = std::chrono::duration<double,std::milli>(elapsed_time).count();
+    printf("[DEBUG] Completed compilation in %.2lf ms\n", timing);
+  #endif
+
   // No errors, normal termination of this function
   return StatusCode::kSuccess;
 }
diff --git a/src/routines/common.cpp b/src/routines/common.cpp
index c378df28..2e82e04d 100644
--- a/src/routines/common.cpp
+++ b/src/routines/common.cpp
@@ -12,6 +12,7 @@
 // =================================================================================================
 
 #include <vector>
+#include <chrono>
 
 #include "routines/common.hpp"
 
@@ -44,11 +45,26 @@ StatusCode RunKernel(Kernel &kernel, Queue &queue, const Device &device,
   const auto local_mem_usage = kernel.LocalMemUsage(device);
   if (!device.IsLocalMemoryValid(local_mem_usage)) { return StatusCode::kInvalidLocalMemUsage; }
 
+  // Prints the name of the kernel to launch in case of debugging in verbose mode
+  #ifdef VERBOSE
+    queue.Finish();
+    printf("[DEBUG] Running kernel '%s'\n", kernel.GetFunctionName().c_str());
+    const auto start_time = std::chrono::steady_clock::now();
+  #endif
+
   // Launches the kernel (and checks for launch errors)
   try {
     kernel.Launch(queue, global, local, event, waitForEvents);
   } catch (...) { return StatusCode::kKernelLaunchError; }
 
+  // Prints the elapsed execution time in case of debugging in verbose mode
+  #ifdef VERBOSE
+    queue.Finish();
+    const auto elapsed_time = std::chrono::steady_clock::now() - start_time;
+    const auto timing = std::chrono::duration<double,std::milli>(elapsed_time).count();
+    printf("[DEBUG] Completed kernel in %.2lf ms\n", timing);
+  #endif
+
   // No errors, normal termination of this function
   return StatusCode::kSuccess;
 }