From 846b95b8bc3eab1bfcebb8ff1c85d344056e2f8c Mon Sep 17 00:00:00 2001
From: Andreas Kloeckner <inform@tiker.net>
Date: Fri, 2 Jun 2017 19:36:29 -0400
Subject: [PATCH] Add build time accounting with higher information density

---
 pyopencl/__init__.py | 28 +++++++++++++++++++++++++++-
 pyopencl/cache.py    | 20 ++++++++++++--------
 2 files changed, 39 insertions(+), 9 deletions(-)

diff --git a/pyopencl/__init__.py b/pyopencl/__init__.py
index a8a694cd..07688d1d 100644
--- a/pyopencl/__init__.py
+++ b/pyopencl/__init__.py
@@ -30,6 +30,9 @@ from six.moves import input
 
 from pyopencl.version import VERSION, VERSION_STATUS, VERSION_TEXT  # noqa
 
+import logging
+logger = logging.getLogger(__name__)
+
 try:
     import pyopencl.cffi_cl as _cl
 except ImportError:
@@ -279,6 +282,8 @@ class Program(object):
             self._context = context
             self._prg = _cl._Program(context, device, binaries)
 
+        self._build_duration_info = None
+
     def _get_prg(self):
         if self._prg is not None:
             return self._prg
@@ -317,6 +322,13 @@ class Program(object):
             # but this will give an error if the kernel is invalid.
             knl.num_args
             knl._source = getattr(self, "_source", None)
+
+            if self._build_duration_info is not None:
+                was_cached, what, duration = self._build_duration_info
+                if duration > 0.2:
+                    logger.info("build program: kernel '%s' was part of a "
+                            "lengthy %s (%.2f s)" % (attr, what, duration))
+
             return knl
         except LogicError:
             raise AttributeError("'%s' was not found as a program "
@@ -422,9 +434,14 @@ class Program(object):
         if os.environ.get("PYOPENCL_NO_CACHE") and self._prg is None:
             self._prg = _cl._Program(self._context, self._source)
 
+        from time import time
+        start_time = time()
+        was_cached = False
+
         if self._prg is not None:
             # uncached
 
+            what = "uncached source build"
             self._build_and_catch_errors(
                     lambda: self._prg.build(options_bytes, devices),
                     options_bytes=options_bytes)
@@ -433,14 +450,23 @@ class Program(object):
             # cached
 
             from pyopencl.cache import create_built_program_from_source_cached
-            self._prg = self._build_and_catch_errors(
+            self._prg, was_cached = self._build_and_catch_errors(
                     lambda: create_built_program_from_source_cached(
                         self._context, self._source, options_bytes, devices,
                         cache_dir=cache_dir, include_path=include_path),
                     options_bytes=options_bytes, source=self._source)
 
+            if was_cached:
+                what = "cache retrieval"
+            else:
+                what = "source build resulting from a binary cache miss"
+
             del self._context
 
+        end_time = time()
+
+        self._build_duration_info = (was_cached, what, end_time-start_time)
+
         return self
 
     def _build_and_catch_errors(self, build_func, options_bytes, source=None):
diff --git a/pyopencl/cache.py b/pyopencl/cache.py
index 3d8f8fa9..a5af74ca 100644
--- a/pyopencl/cache.py
+++ b/pyopencl/cache.py
@@ -356,7 +356,7 @@ def _create_built_program_from_source_cached(ctx, src, options_bytes,
         cache_result = retrieve_from_cache(cache_dir, cache_key)
 
         if cache_result is None:
-            logger.info("build program: binary cache miss (key: %s)" % cache_key)
+            logger.debug("build program: binary cache miss (key: %s)" % cache_key)
 
             to_be_built_indices.append(i)
             binaries.append(None)
@@ -383,6 +383,7 @@ def _create_built_program_from_source_cached(ctx, src, options_bytes,
 
     result = None
     already_built = False
+    was_cached = not to_be_built_indices
 
     if to_be_built_indices:
         # defeat implementation caches:
@@ -390,13 +391,13 @@ def _create_built_program_from_source_cached(ctx, src, options_bytes,
         src = src + "\n\n__constant int pyopencl_defeat_cache_%s = 0;" % (
                 uuid4().hex)
 
-        logger.info("build program: start building program from source on %s"
+        logger.debug("build program: start building program from source on %s"
                 % ", ".join(str(devices[i]) for i in to_be_built_indices))
 
         prg = _cl._Program(ctx, src)
         prg.build(options_bytes, [devices[i] for i in to_be_built_indices])
 
-        logger.info("build program: from-source build complete")
+        logger.debug("build program: from-source build complete")
 
         prg_devs = prg.get_info(_cl.program_info.DEVICES)
         prg_bins = prg.get_info(_cl.program_info.BINARIES)
@@ -462,18 +463,20 @@ def _create_built_program_from_source_cached(ctx, src, options_bytes,
 
     # }}}
 
-    return result, already_built
+    return result, already_built, was_cached
 
 
 def create_built_program_from_source_cached(ctx, src, options_bytes, devices=None,
         cache_dir=None, include_path=None):
     try:
         if cache_dir is not False:
-            prg, already_built = _create_built_program_from_source_cached(
-                    ctx, src, options_bytes, devices, cache_dir,
-                    include_path=include_path)
+            prg, already_built, was_cached = \
+                    _create_built_program_from_source_cached(
+                            ctx, src, options_bytes, devices, cache_dir,
+                            include_path=include_path)
         else:
             prg = _cl._Program(ctx, src)
+            was_cached = False
             already_built = False
 
     except Exception as e:
@@ -491,12 +494,13 @@ def create_built_program_from_source_cached(ctx, src, options_bytes, devices=Non
                 % format_exc())
 
         prg = _cl._Program(ctx, src)
+        was_cached = False
         already_built = False
 
     if not already_built:
         prg.build(options_bytes, devices)
 
-    return prg
+    return prg, was_cached
 
 # }}}
 
-- 
GitLab