Some logging + fix for variant builds

benchmarks/scripts/cub/bench/bench.py

@@ -11,6 +11,7 @@
 from .config import *
 from .storage import Storage
 from .score import *
+from .logger import *
 
 
 class JsonCache:
@@ -375,6 +376,8 @@ def definitions(self):
         return definitions
 
     def do_run(self, point, timeout):
+        logger = Logger()
+
         try:
             result_path = 'result.json'
             if os.path.exists(result_path):
@@ -402,6 +405,8 @@ def do_run(self, point, timeout):
             cmd.append("-d")
             cmd.append("0")
 
+            logger.info("starting benchmark {} with {}: {}".format(self.label(), point, " ".join(cmd)))
+
             begin = time.time()
             p = subprocess.Popen(cmd,
                                  start_new_session=True,
@@ -410,8 +415,11 @@ def do_run(self, point, timeout):
             p.wait(timeout=timeout)
             elapsed = time.time() - begin
 
+            logger.info("finished benchmark {} with {} ({}) in {}s".format(self.label(), point, p.returncode, elapsed))
+
             return read_samples(result_path), elapsed
         except subprocess.TimeoutExpired:
+            logger.info("benchmark {} with {} reached timeout of {}s".format(self.label(), point, timeout))
             os.killpg(os.getpgid(p.pid), signal.SIGTERM)
             return np.array([], dtype=np.float32), float('inf')
 
@@ -443,13 +451,16 @@ def elapsed(self, workload_point, estimator):
 
 
     def run(self, workload_point, estimator):
+        logger = Logger()
+
         if not self.build():
             return float('inf')
 
         cache = BenchCache()
         cached_center = cache.pull_center(self, workload_point)
 
         if cached_center:
+            logger.info("found benchmark {} ({}) in cache".format(self.label(), workload_point))
             return float(cached_center[0])
 
         timeout = None

benchmarks/scripts/cub/bench/cmake.py

@@ -6,6 +6,7 @@
 from .build import Build
 from .config import Config
 from .storage import Storage
+from .logger import *
 
 
 def create_builds_table(conn):
@@ -62,12 +63,15 @@ def __init__(self):
     pass 
 
   def do_build(self, bench, timeout):
+      logger = Logger()
+
       try:
           if not bench.is_base():
               with open(bench.exe_name() + ".h", "w") as f:
                   f.writelines(bench.definitions())
 
           cmd = ["cmake", "--build", ".", "--target", bench.exe_name()]
+          logger.info("starting build for {}: {}".format(bench.label(), " ".join(cmd)))
 
           begin = time.time()
           p = subprocess.Popen(cmd,
@@ -76,26 +80,32 @@ def do_build(self, bench, timeout):
                               stderr=subprocess.DEVNULL)
           p.wait(timeout=timeout)
           elapsed = time.time() - begin
+          logger.info("finished build for {} ({}) in {}s".format(bench.label(), p.returncode, elapsed))
 
           return Build(p.returncode, elapsed)
       except subprocess.TimeoutExpired:
+          logger.info("build for {} reached timeout of {}s".format(bench.label(), timeout))
           os.killpg(os.getpgid(p.pid), signal.SIGTERM)
           return Build(424242, float('inf'))
 
   def build(self, bench):
-      cache = CMakeCache()
-      build = cache.pull_build(bench)
+      logger = Logger()
+      timeout = None
 
-      if build:
-          if bench.is_base():
-              if not os.path.exists("bin/{}".format(bench.exe_name())):
-                  self.do_build(bench, None)
+      cache = CMakeCache()
 
-          return build
+      if bench.is_base():
+          # Only base build can be pulled from cache
+          build = cache.pull_build(bench)
 
-      timeout = None
+          if build:
+              logger.info("found cached base build for {}".format(bench.label()))
+              if bench.is_base():
+                  if not os.path.exists("bin/{}".format(bench.exe_name())):
+                      self.do_build(bench, None)
 
-      if not bench.is_base():
+              return build
+      else:
           base_build = self.build(bench.get_base())
 
           if base_build.code != 0:

benchmarks/scripts/cub/bench/logger.py

@@ -0,0 +1,19 @@
+import logging
+
+class Logger:
+    _instance = None
+
+    def __new__(cls, *args, **kwargs):
+        if cls._instance is None:
+            cls._instance = super().__new__(cls, *args, **kwargs)
+            logger = logging.getLogger()
+            logger.setLevel(logging.DEBUG)
+            file_handler = logging.FileHandler('cub_bench_meta.log')
+            file_handler.setFormatter(logging.Formatter('%(asctime)s: %(message)s'))
+            logger.addHandler(file_handler)
+            cls._instance.logger = logger
+
+        return cls._instance
+
+    def info(self, message):
+        self.logger.info(message)