From 7f6b1d227b35687f83985a3fdc51bfcbbf7af7cc Mon Sep 17 00:00:00 2001
From: Florian Fischer <florian.fischer@muhq.space>
Date: Fri, 27 Aug 2021 15:38:14 +0200
Subject: [PATCH] [eval.py] use logging instead of custom verbosity checks

---
 eval.py | 153 ++++++++++++++++++++++++++------------------------------
 1 file changed, 71 insertions(+), 82 deletions(-)

diff --git a/eval.py b/eval.py
index 4a448b4..62996f6 100755
--- a/eval.py
+++ b/eval.py
@@ -5,6 +5,7 @@ import datetime
 from enum import Enum
 import fnmatch
 import itertools
+import logging
 import os
 from pathlib import Path
 import platform
@@ -23,18 +24,7 @@ SERVER_DIR = ROOT_DIR / 'servers'
 ARTIFACT_DESC = subprocess.check_output(
     'git describe --dirty --always'.split(), cwd=ROOT_DIR, text=True)[:-1]
 
-
-def err(msg: str):
-    """print error message and exit with statsu 1"""
-    print(f'ERROR: {msg}', file=sys.stderr)
-    sys.exit(1)
-
-
-def emper_create_env_worker_count(worker_count):
-    return f'EMPER_WORKER_COUNT={worker_count}'
-
-
-EMPER_20_WORKER_ENV_CMD = f'env {emper_create_env_worker_count(20)}'
+EMPER_20_WORKER_ENV_CMD = 'env EMPER_WORKER_COUNT=20'
 GO_20_WORKER_ENV_CMD = 'env GOMAXPROCS=20'
 TOKIO_20_WORKER_ENV_CMD = 'env TOKIO_WORKER_COUNT=20'
 
@@ -221,7 +211,7 @@ EMPER_FLAVORS = {
         'patches': ['fix_free_vs_delete.patch', 'wakeup-condvar.patch'],
     },
     '4': {
-        'server_cmd_prefix': f'env {emper_create_env_worker_count(4)}'
+        'server_cmd_prefix': 'env EMPER_WORKER_COUNT=4'
     },
     '20': {
         'server_cmd_prefix': EMPER_20_WORKER_ENV_CMD
@@ -380,7 +370,7 @@ TERMINATION_CMD = 'nc {host} 12345'
 SERVER_KILL_CMD = 'pkill -9 {proc}'
 
 
-def write_desc(data_dir, verbose=False):
+def write_desc(data_dir):
     """Write a YAML description of the evaluation into result_dir"""
     desc_file_path = data_dir / 'desc.yml'
     with open(desc_file_path, 'w') as desc_file:
@@ -404,7 +394,7 @@ def write_desc(data_dir, verbose=False):
     # collect the uname of the host
     remote_cmd = REMOTE_CMD.format(host=HOST, ssh_port=SSH_PORT)
     uname_cmd = f'{remote_cmd} uname -a >> {desc_file_path}'
-    cmd_run(uname_cmd, verbose=verbose)
+    cmd_run(uname_cmd)
 
 
 def prepare_env(update_env: MutableMapping) -> Dict:
@@ -424,34 +414,34 @@ def emper_repo_add_muhq_remote():
     subprocess.run(cmd.split(), cwd=EMPER_REPO, check=True)
 
 
-def cmd_run(cmd: str, cwd=None, env=None, verbose=False, check=True):
+def cmd_run(cmd: str, cwd=None, env=None, check=True):
     """Run a verbosity aware subcommand"""
-    stdout = None if verbose else subprocess.DEVNULL
-    stderr = subprocess.PIPE
+    stdout = subprocess.DEVNULL
+    if logging.getLogger().getEffectiveLevel() <= logging.DEBUG:
+        stdout = None
 
-    if verbose:
-        print(f'Running subcommand: {cmd}')
+    log.debug('Running subcommand: %s', cmd)
 
     try:
         subprocess.run(cmd.split(),
                        stdout=stdout,
-                       stderr=stderr,
+                       stderr=subprocess.PIPE,
                        text=True,
                        env=env,
                        check=check,
                        cwd=cwd)
     except subprocess.CalledProcessError as run_err:
-        print(f'subcommand failed: {run_err}')
-        print(f'{run_err.stderr}')
+        log.critical('subcommand failed: %s', run_err)
+        log.debug('%s', run_err.stderr)
         raise run_err
 
 
-def checkout_emper_worktree(directory, checkout, verbose=False):
+def checkout_emper_worktree(directory, checkout):
     worktree_cmd = f'git worktree add {directory} {checkout}'
-    cmd_run(worktree_cmd, cwd=EMPER_REPO, verbose=verbose)
+    cmd_run(worktree_cmd, cwd=EMPER_REPO)
 
 
-def build_emper(emper_dir, meson_options='', build_env=None, verbose=False):
+def build_emper(emper_dir, meson_options='', build_env=None):
     if not build_env:
         build_env = {}
 
@@ -462,13 +452,13 @@ def build_emper(emper_dir, meson_options='', build_env=None, verbose=False):
     common_options = '-Dstats=true --buildtype=release --fatal-meson-warnings'
     build_cmd = f'meson build {common_options} {meson_options}'
 
-    cmd_run(build_cmd, cwd=emper_dir, env=meson_env, verbose=verbose)
+    cmd_run(build_cmd, cwd=emper_dir, env=meson_env)
 
     ninja_cmd = 'ninja -C build'
-    cmd_run(ninja_cmd, cwd=emper_dir, verbose=verbose)
+    cmd_run(ninja_cmd, cwd=emper_dir)
 
 
-def prepare_client(verbose=False):
+def prepare_client():
     client_checkout = get_commit_id(EMPER_REPO, CLIENT_CHECKOUT)
 
     with open(DATA_DIR / 'desc.yml', 'a') as desc_file:
@@ -480,9 +470,9 @@ def prepare_client(verbose=False):
 
     print("Preparing the client ...")
     if not CLIENT_DIR.exists():
-        checkout_emper_worktree(CLIENT_DIR, client_checkout, verbose)
+        checkout_emper_worktree(CLIENT_DIR, client_checkout)
 
-    build_emper(CLIENT_DIR, verbose=verbose)
+    build_emper(CLIENT_DIR)
 
 
 def run_local_client(client_cmd, client_out, client_err):
@@ -500,7 +490,7 @@ def run_local_client(client_cmd, client_out, client_err):
                            check=True)
 
         except subprocess.CalledProcessError as run_err:
-            print(f'Client terminated unsuccessful: {run_err}', file=cerr)
+            log.error('Client terminated unsuccessful: %s', run_err)
             ret = BenchResult.FAIL
 
         except subprocess.TimeoutExpired:
@@ -529,22 +519,22 @@ def save_client_results(clients_out, bench_dir, client_out_suffix,
             shutil.copyfileobj(client_out.stderr, cerr)
 
 
-def update_emper_flavor(flavor_dir, checkout, verbose=False):
+def update_emper_flavor(flavor_dir, checkout):
     """Reset and update a emper worktree"""
     # reset patches
     git_reset_cmd = 'git reset --hard'
-    cmd_run(git_reset_cmd, cwd=flavor_dir, verbose=verbose)
+    cmd_run(git_reset_cmd, cwd=flavor_dir)
 
     # update the worktree
     git_checkout_cmd = f'git checkout {checkout}'
-    cmd_run(git_checkout_cmd, cwd=flavor_dir, verbose=verbose)
+    cmd_run(git_checkout_cmd, cwd=flavor_dir)
 
     # remove the old build directory
     rm_build_cmd = 'rm -r build'
-    cmd_run(rm_build_cmd, cwd=flavor_dir, verbose=verbose)
+    cmd_run(rm_build_cmd, cwd=flavor_dir)
 
 
-def prepare_emper_flavors(flavors, verbose=False):
+def prepare_emper_flavors(flavors):
     emper_server_cmd = SERVER_CMDS['emper']
     del SERVER_CMDS['emper']
 
@@ -581,19 +571,18 @@ def prepare_emper_flavors(flavors, verbose=False):
 
         else:
             print(f'preparing {flavor_checkout}...')
-            checkout_emper_worktree(flavor_checkout, checkout, verbose)
+            checkout_emper_worktree(flavor_checkout, checkout)
 
         for patch in desc.get('patches', []):
             patch_cmd = f'git apply {ROOT_DIR}/patches/{patch}'
-            cmd_run(patch_cmd, cwd=flavor_checkout, verbose=verbose)
+            cmd_run(patch_cmd, cwd=flavor_checkout)
 
         build_emper(flavor_checkout,
                     meson_options=meson_options,
-                    build_env=desc.get('build_env', {}),
-                    verbose=verbose)
+                    build_env=desc.get('build_env', {}))
 
 
-def shutdown_server(server: subprocess.Popen, verbose=False):
+def shutdown_server(server: subprocess.Popen):
     """Terminate a running sever command"""
     # server is not running
     if server.poll() is not None:
@@ -604,8 +593,7 @@ def shutdown_server(server: subprocess.Popen, verbose=False):
     try:
         subprocess.run(termination_cmd.split(), input=b'quit\n', check=True)
     except subprocess.CalledProcessError as run_err:
-        if verbose:
-            print(f'{termination_cmd} terminated unsuccessful: {run_err}')
+        log.warning('%s terminated unsuccessful: %s', termination_cmd, run_err)
 
     # wait for the server to terminate
     try:
@@ -625,7 +613,7 @@ def shutdown_server(server: subprocess.Popen, verbose=False):
         server_bin = server.args.split()[0]
 
     kill_cmd += SERVER_KILL_CMD.format(proc=server_bin)
-    cmd_run(kill_cmd, verbose=verbose, check=False)
+    cmd_run(kill_cmd, check=False)
 
     server.wait(TERMINATION_TIME)
 
@@ -657,7 +645,7 @@ def summarize(results: Mapping[str, Sequence[Sequence[BenchResult]]]):
         print(summary, file=summary_file)
 
 
-def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
+def bench() -> Dict[str, List[List[BenchResult]]]:
     results = {
         server: [[BenchResult.SKIP] * len(ARGS) for r in range(RUNS)]
         for server in SERVER_CMDS
@@ -683,7 +671,7 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
                 remote_cmd = REMOTE_CMD.format(host=HOST, ssh_port=SSH_PORT)
                 # make sure the benchdir is available on the HOST
                 remote_prepare_cmd = f'{remote_cmd} mkdir -p {bench_dir}'
-                cmd_run(remote_prepare_cmd, verbose=verbose)
+                cmd_run(remote_prepare_cmd)
 
                 cmd = f'{remote_cmd} '
 
@@ -691,8 +679,7 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
             cmd += f'{measure_cmd} {server_cmd}'
 
             print(f'benchmarking {server} ...')
-            if verbose:
-                print(cmd)
+            log.debug('server command:\n%s', cmd)
 
             server_out = bench_dir / SERVER_OUT.format(run=run)
             server_err = bench_dir / SERVER_ERR.format(run=run)
@@ -717,9 +704,9 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
 
                     # skip naive-multithreaded for cons > 10000
                     if server == 'naive-multithreaded' and cons > 10000:
-                        if verbose:
-                            print(('Skipping naive-multithreaded '
-                                   f'for cons ({cons}) > 10000'))
+                        log.debug(
+                            'Skipping naive-multithreaded for cons (%d) > 10000',
+                            cons)
                         continue
 
                     measure_io_proc = None
@@ -734,7 +721,11 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
                             stderr=subprocess.DEVNULL,
                             cwd=bench_dir)
 
-                    outfile = bench_dir / CLIENT_CSV.format(
+                    client_csv = CLIENT_CSV
+                    if CLIENTS:
+                        client_csv = f'%s-{CLIENT_CSV}'
+
+                    outfile = bench_dir / client_csv.format(
                         cons=cons, size=size, run=run)
 
                     client_cmd = CLIENT_CMD.format(cons=cons,
@@ -750,23 +741,14 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
                                                           size=size,
                                                           run=run)
                     if not CLIENTS:
-                        if verbose:
-                            print('run local echo client')
+                        log.debug('run local echo client')
 
                         bench_results[i] = run_local_client(
                             client_cmd, bench_dir / client_out_suffix,
                             bench_dir / client_err_suffix)
                     else:
-                        # prepare client_cmd to take host args
-                        client_cmd = client_cmd.replace('-f ', '-f %s-')
-
-                        if verbose:
-                            print(
-                                f'run multiple echo client per pssh using\n{client_cmd}'
-                            )
-                            print(
-                                f'start coordinator on {COORDINATOR} using\n{COORDINATOR_CMD}'
-                            )
+                        log.debug('start coordinator on %s using:\n%s',
+                                  COORDINATOR, COORDINATOR_CMD)
 
                         # start coordinator
                         with subprocess.Popen(COORDINATOR_CMD.split(),
@@ -776,7 +758,10 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
                             clients_out = ssh_client.run_command(
                                 client_cmd, host_args=CLIENTS)
                             try:
-                                ssh_client.join(timeout=CLIENT_TIMEOUT)
+                                log.debug('await clients with timeout: %s',
+                                          CLIENT_TIMEOUT)
+                                ssh_client.join(clients_out,
+                                                timeout=CLIENT_TIMEOUT)
                                 save_client_results(clients_out, bench_dir,
                                                     client_out_suffix,
                                                     client_err_suffix)
@@ -799,16 +784,12 @@ def bench(verbose=False) -> Dict[str, List[List[BenchResult]]]:
 
                     sleep(CLIENT_SEPARATION_TIME)
 
-                shutdown_server(server_popen, verbose=verbose)
+                shutdown_server(server_popen)
     return results
 
 
 if __name__ == '__main__':
     parser = argparse.ArgumentParser()
-    parser.add_argument('-v',
-                        '--verbose',
-                        help='show build output',
-                        action='store_true')
     parser.add_argument('-l',
                         '--local',
                         help='run benchmark on localhost',
@@ -853,6 +834,7 @@ if __name__ == '__main__':
         '--data-root',
         help='path where the experiment results should be saved',
         type=str)
+    parser.add_argument('--log', help='Log level to use', type=str)
     parser.add_argument(
         '--additional-client-args',
         help='additional arguments appended to the echo client command',
@@ -875,6 +857,12 @@ if __name__ == '__main__':
 
     args = parser.parse_args()
 
+    numeric_loglevel = getattr(logging, args.log.upper(), None)
+    if not isinstance(numeric_loglevel, int):
+        raise ValueError(f'Invalid log level: {args.log}')
+    logging.basicConfig(level=numeric_loglevel)
+    log = logging.getLogger(Path(__file__).name)
+
     if args.time:
         TERMINATION_FLAG = f'-t {args.time}'
         CLIENT_TIMEOUT = int(args.time) * CLIENT_TIMEOUT_FACTOR
@@ -897,8 +885,7 @@ if __name__ == '__main__':
     if CLIENTS:
         ssh_client = ParallelSSHClient(CLIENTS, port=SSH_PORT)
         CLIENT_CMD += f'--coordinator {COORDINATOR}'
-        if args.verbose:
-            print(f'Using clients: {CLIENTS}')
+        log.debug('Using clients: %s', CLIENTS)
 
         COORDINATOR_CMD = f'{COORDINATOR_EXE} {len(CLIENTS)}'
 
@@ -932,9 +919,8 @@ if __name__ == '__main__':
 
     if args.host:
         if HOST == 'localhost':
-            print(
-                'ERROR: host optioan and local option can not be passed at once'
-            )
+            log.critical(
+                'host option and local option can not be passed at once')
             sys.exit(1)
 
         HOST = args.host
@@ -962,14 +948,17 @@ if __name__ == '__main__':
                                         selected_flavor)
             }
             if not selection:
-                err(f'{selected_flavor} does not select any available flavor')
+                log.critical('%s does not select any available flavor',
+                             selected_flavor)
+                sys.exit(1)
+
             filtered_flavors.update(selection)
 
         selected_flavors = filtered_flavors
 
     print("Building the artifact ...")
     make_cmd = ['make']
-    if not args.verbose:
+    if numeric_loglevel <= logging.DEBUG:
         make_cmd.append('-s')
     subprocess.run(make_cmd, check=True, cwd=ROOT_DIR)
 
@@ -987,12 +976,12 @@ if __name__ == '__main__':
 
     print(f"Storing results at {DATA_DIR}")
 
-    write_desc(DATA_DIR, verbose=args.verbose)
-    prepare_client(args.verbose)
+    write_desc(DATA_DIR)
+    prepare_client()
 
     # generate emper flavors
     if 'emper' in SERVER_CMDS:
-        prepare_emper_flavors(selected_flavors, args.verbose)
+        prepare_emper_flavors(selected_flavors)
 
     RUNS = args.runs
 
@@ -1000,4 +989,4 @@ if __name__ == '__main__':
         sys.exit(0)
 
     print()
-    summarize(bench(args.verbose))
+    summarize(bench())
-- 
GitLab