introduce logging to allocbench

Introduce root logger "allocbench" and add custom level "Status".
Change print_* to logger.* calls.

1 files changed, 68 insertions, 48 deletions

diff --git a/bench.py b/bench.py
index 6360db5..2bd00f8 100755
--- a/bench.py
+++ b/bench.py
@@ -4,6 +4,7 @@ import argparse
 import atexit
 import datetime
 import importlib
+import logging
 import os
 import pickle
 import subprocess
@@ -12,7 +13,7 @@ import traceback
 
 import src.facter
 import src.globalvars
-from src.util import *
+from src.util import find_cmd
 
 
 parser = argparse.ArgumentParser(description="benchmark memory allocators")
@@ -22,8 +23,6 @@ parser.add_argument("-l", "--load", help="load benchmark results from directory"
 parser.add_argument("--analyse", help="analyse benchmark behaviour using malt", action="store_true")
 parser.add_argument("-r", "--runs", help="how often the benchmarks run", default=3, type=int)
 parser.add_argument("-v", "--verbose", help="more output", action='count')
-parser.add_argument("-vdebug", "--verbose-debug", help="debug output",
-                    action='store_true', dest="verbose_debug")
 parser.add_argument("-b", "--benchmarks", help="benchmarks to run", nargs='+')
 parser.add_argument("-xb", "--exclude-benchmarks", help="explicitly excluded benchmarks", nargs='+')
 parser.add_argument("-a", "--allocators", help="allocators to test", type=str, nargs='+')
@@ -31,13 +30,26 @@ parser.add_argument("-ns", "--nosum", help="don't produce plots", action='store_
 parser.add_argument("-rd", "--resultdir", help="directory where all results go", type=str)
 parser.add_argument("--license", help="print license info and exit", action='store_true')
 
+logging.STATUS = 25
+logging.addLevelName(logging.STATUS, "STATUS")
+
+def status(self, message, *args, **kws):
+    """Log 'msg % args' with severity 'STATUS'."""
+    if self.isEnabledFor(logging.STATUS):
+        # Yes, logger takes its '*args' as 'args'.
+        self._log(logging.STATUS, message, args, **kws)
+
+logging.Logger.status = status
+
+# Allocbench root logger
+logger = logging.getLogger("allocbench")
 
 def epilog():
     """Run tasks on exit"""
     # After early errors resdir may not be set
     if src.globalvars.resdir is not None:
         if os.listdir(src.globalvars.resdir) == []:
-            print_warn("Remove empty resultdir")
+            logger.warning("Remove empty resultdir")
             os.removedirs(src.globalvars.resdir)
         else:
             endtime = datetime.datetime.now().isoformat()
@@ -75,26 +87,27 @@ def main():
     atexit.register(epilog)
 
     # Set global verbosity
-    # quiet | -1: Don't output to stdout
-    # default | 0: Only print status and errors
-    # 1: Print warnings and some infos
-    # 2: Print all infos
-    # debug | 99: Print all awailable infos
-    if args.verbose_debug:
-        src.globalvars.verbosity = 99
-    elif args.verbose:
-        src.globalvars.verbosity = args.verbose
-
-    print_info2("Arguments:", args)
+    # 0: logging.STATUS (default)
+    # 1: logging.INFO
+    # 2: logging.DEBUG
+    # 99: Don't log any thing (not implemented)
+    src.globalvars.verbosity = logging.STATUS
+    if args.verbose:
+        src.globalvars.verbosity -= args.verbose * 10
+
+    # TODO: understand python logging
+    logging.debug("Foo! This is so that our derived logger can log.")
+    logger.setLevel(src.globalvars.verbosity)
+
+    logger.info("Arguments: %s", args)
 
     # Prepare allocbench
-    print_status("Building allocbench ...")
+    logger.status("Building allocbench ...")
     make_cmd = ["make"]
-    if src.globalvars.verbosity < 1:
+
+    if src.globalvars.verbosity >= logging.DEBUG:
         make_cmd.append("-s")
-    else:
-        # Flush stdout so the color reset from print_status works
-        print("", end="", flush=True)
+
     subprocess.run(make_cmd)
 
     # collect facts about benchmark environment
@@ -115,14 +128,14 @@ def main():
             # file exists -> interpret as python file with a global variable allocators
             if os.path.isfile(name):
                 with open(name, "r") as f:
-                    print_status("Sourcing allocators definitions at", name, "...")
+                    logger.status("Sourcing allocators definitions at %s ...", name)
                     g = {}
                     exec(f.read(), g)
 
                 if "allocators" in g:
                     allocators.update(g["allocators"])
                 else:
-                    print_error("No global dictionary 'allocators' in", name)
+                    logger.error("No global dictionary 'allocators' in %s", name)
 
             # file is one of our allocator definitions import it
             elif os.path.isfile("src/allocators/" + name + ".py"):
@@ -135,25 +148,31 @@ def main():
                 elif issubclass(getattr(module, name).__class__, src.allocator.Allocator):
                     allocators[name] = getattr(module, name).build()
             else:
-                print_error(name, "is neither a python file or a known allocator definition.")
+                logger.error("%s is neither a python file or a known allocator definition.", name)
     else:
-        print_status("Using system-wide installed allocators ...")
+        logger.status("Using system-wide installed allocators ...")
         importlib.import_module('src.allocators.installed_allocators')
         allocators = src.allocators.installed_allocators.allocators
 
     # set colors
-    explicit_colors = [v["color"] for k, v in allocators.items() if v["color"] is not None]
-    print_debug("Explicit colors:", explicit_colors)
-    avail_colors = [color for color in ["C" + str(i) for i in range(0,16)] if color not in explicit_colors]
-    print_debug("available colors:", avail_colors)
+    explicit_colors = [v["color"]
+                       for k, v in allocators.items()
+                       if v["color"] is not None]
+
+    logger.debug("Explicit colors: %s", explicit_colors)
+    avail_colors = [color for color in ["C" + str(i)
+                                        for i in range(0, 16)]
+                                        if color not in explicit_colors]
+
+    logger.debug("available colors: %s", avail_colors)
 
-    for k, v in allocators.items():
+    for _, v in allocators.items():
         if v["color"] is None:
             v["color"] = avail_colors.pop()
 
     src.globalvars.allocators = allocators
-    print_info("Allocators:", *src.globalvars.allocators.keys())
-    print_debug("Allocators:", *src.globalvars.allocators.items())
+    logger.info("Allocators: %s", list(src.globalvars.allocators.keys()))
+    logger.debug("Allocators: %s", list(src.globalvars.allocators.items()))
 
     # Load old results
     if args.load:
@@ -161,8 +180,8 @@ def main():
             old_facts = pickle.load(f)
 
         if old_facts != src.globalvars.facts and args.runs > 0:
-            print_error("Can't combine benchmarks with different facts")
-            print_error("Aborting.")
+            logger.critical("Can't combine benchmarks with different facts")
+            logger.critical("Aborting.")
             exit(1)
         # We are just summarizing old results -> use their facts
         else:
@@ -184,7 +203,7 @@ def main():
         # Make resdir globally available
         src.globalvars.resdir = resdir
 
-        print_info2("Creating result dir:", resdir)
+        logger.info("Creating result dir: %s", resdir)
         os.makedirs(resdir, exist_ok=True)
 
     # Run actual benchmarks
@@ -199,12 +218,13 @@ def main():
         # Create result dir for this benchmark
         if args.analyse or not args.nosum:
             bench_res_dir = os.path.join(resdir, bench)
-            print_info2("Creating benchmark result dir:", bench_res_dir)
+            logger.info("Creating benchmark result dir: %s", bench_res_dir)
             os.makedirs(bench_res_dir, exist_ok=True)
 
         try:
             bench_module = importlib.import_module(f"src.benchmarks.{bench}")
             if not hasattr(bench_module, bench):
+                logger.warning("%s not defined in src.benchmarks.%s.py\nSkipping %s!", bench, bench, bench)
                 continue
 
             bench = getattr(bench_module, bench)
@@ -213,12 +233,12 @@ def main():
                 bench.load(path=args.load)
 
             if args.runs > 0 or args.analyse:
-                print_status("Preparing", bench.name, "...")
+                logger.status("Preparing %s ...", bench.name)
                 bench.prepare()
 
             if args.analyse:
                 if find_cmd("malt") is not None:
-                    print_status("Analysing {} ...".format(bench))
+                    logger.status("Analysing %s ...", bench.name)
 
                     malt_cmd = "malt -o output:name={}/malt.{}.%3"
                     malt_cmd = malt_cmd.format(bench_res_dir, "{perm}")
@@ -231,27 +251,27 @@ def main():
                     try:
                         bench.run(runs=1)
                     except Exception:
-                        print_error(traceback.format_exc())
-                        print_error("Skipping analysis of", bench, "!")
+                        logger.error(traceback.format_exc())
+                        logger.error("Skipping analysis of %s!", bench)
 
                     # Remove malt from results
                     if "malt" in bench.results:
-                        del(bench.results["malt"])
+                        del bench.results["malt"]
                     if "stats" in bench.results and "malt" in bench.results["stats"]:
-                        del(bench.results["stats"]["malt"])
+                        del bench.results["stats"]["malt"]
 
                     # restore allocs
                     bench.allocators = old_allocs
 
                 else:
-                    print_error("malt not found. Skipping analyse.")
+                    logger.error("malt not found. Skipping analyse.")
 
             if args.runs > 1:
-                print_status("Running", bench.name, "...")
+                logger.status("Running %s ...", bench.name)
             bench.run(runs=args.runs)
 
             if need_resultdir:
-                print_info2("Changing cwd to:", resdir)
+                logger.info("Changing cwd to: %s", resdir)
                 os.chdir(resdir)
 
                 # Save results in resultdir
@@ -261,21 +281,21 @@ def main():
                 # Summarize benchmark in benchmark specific resultdir
                 if not args.nosum:
                     os.chdir(bench.name)
-                    print_status("Summarizing", bench.name, "...")
+                    logger.status("Summarizing %s ...", bench.name)
                     bench.summary()
 
                 os.chdir(cwd)
 
             if args.runs > 0 and hasattr(bench, "cleanup"):
-                print_status("Cleaning up", bench.name, "...")
+                logger.status("Cleaning up", bench.name, "...")
                 bench.cleanup()
 
         except Exception:
             # Reset cwd
             os.chdir(cwd)
 
-            print_error(traceback.format_exc())
-            print_error("Skipping", bench, "!")
+            logger.error(traceback.format_exc())
+            logger.error("Skipping %s!", bench)
 
             continue