Only send final JSON benchmark result to stdout, move others to stderr (#247)

Summary:
Pull Request resolved: #247

In Benchpress's run command, let's only print the final benchmark result report (in JSON) to stdout and redirect all other messages to stderr and/or benchpress.log. This will enable other scripts to easily extract and parse the results.

Reviewed By: charles-typ

Differential Revision: D84308887

fbshipit-source-id: 41f1b60ae6aa42c0de254d8eeb5f33082e1adfd7

Author: excelle08

benchpress/cli/commands/run.py

@@ -119,7 +119,7 @@ def run(self, args, jobs) -> None:
 
         jobs = get_target_jobs(jobs, args.jobs).values()
 
-        click.echo("Will run {} job(s)".format(len(jobs)))
+        logger.info("Will run {} job(s)".format(len(jobs)))
 
         history = History(args.results)
         now = datetime.now(timezone.utc)
@@ -184,18 +184,19 @@ def run(self, args, jobs) -> None:
             try:
                 role_in = json.loads(args.role_input)
             except Exception:
-                click.echo("role_input must be json dictionary format")
-                click.echo("example input format for iperf:")
+                click.echo("role_input must be json dictionary format", err=True)
+                click.echo("example input format for iperf:", err=True)
                 click.echo(
-                    './benchpress run iperf --role client --role_input=\'{"server_hostname":"rtptest1234.prn1"}\''
+                    './benchpress run iperf --role client --role_input=\'{"server_hostname":"rtptest1234.prn1"}\'',
+                    err=True,
                 )
                 exit(1)
 
         for job in jobs:
             if not verify_install(job.install_script):
-                click.echo("Benchmark {} not installed".format(job.name))
+                logger.error("Benchmark {} not installed".format(job.name))
                 continue
-            click.echo('Running "{}": {}'.format(job.name, job.description))
+            click.echo('Running "{}": {}'.format(job.name, job.description), err=True)
 
             if args.dry_run:
                 job_cmd = job.dry_run(args.role, role_in)
@@ -218,7 +219,7 @@ def run(self, args, jobs) -> None:
                 job.hooks.append((hook, HookFactory.create(hook), hook_opts))
 
             if args.disable_hooks:
-                click.echo("Hooks globally disabled as requested")
+                logger.warning("Hooks globally disabled as requested")
             else:
                 job.start_hooks()
             metrics_dir = f"benchmark_metrics_{job.uuid}"
@@ -254,7 +255,7 @@ def run(self, args, jobs) -> None:
 
             final_metrics["metrics"] = metrics
             stdout_reporter = ReporterFactory.create("stdout")
-            click.echo("Results Report:")
+            click.echo("Results Report:", err=True)
             stdout_reporter.report(job, final_metrics)
 
             json_reporter.report(job, final_metrics)
@@ -265,7 +266,8 @@ def run(self, args, jobs) -> None:
             click.echo(
                 'Finished running "{}": {} with uuid: {}'.format(
                     job.name, job.description, job.uuid
-                )
+                ),
+                err=True,
             )
 
         json_reporter.close()

benchpress/cli/main.py

@@ -240,7 +240,8 @@ def parse_override_job_args(override_job_args):
             (
                 "Could not properly parse --override_job_args flag. "
                 "Run ./automark exec -h to see an example of what to pass in."
-            )
+            ),
+            err=True,
         )
         raise
 

benchpress/lib/job.py

@@ -205,7 +205,7 @@ def get_file_based_cmd(self, role=None, role_input=None, fp=None):
         """Dump the run command in a file and execute it."""
         logger.info('Starting "{}"'.format(self.name))
         cmd = self.dry_run(role, role_input)
-        click.echo("Job execution command: {}".format(cmd))
+        click.echo("Job execution command: {}".format(cmd), err=True)
         # add string to cmd so that it dumps the stdout and strerr to different files
         # cmd = cmd + " > benchpress_run_output.txt 2> benchpress_run_error.txt"
 
@@ -237,7 +237,7 @@ def run(self, role=None, role_input=None):
                 )
             else:
                 cmd = get_safe_cmd([self.binary] + self.args)
-                click.echo("Job execution command: {}".format(cmd))
+                click.echo("Job execution command: {}".format(cmd), err=True)
                 process = subprocess.Popen(
                     cmd,
                     stdout=subprocess.PIPE,
@@ -343,7 +343,7 @@ def _print_output_summary(self, stdout, stderr):
         if len(stderr) > TRIM_OUTPUT_LINES:
             output += f"\n[...trimmed to last {TRIM_OUTPUT_LINES} lines...]\n"
         output += "\t{}".format("\n\t".join(stderr[-TRIM_OUTPUT_LINES:]))
-        click.echo(output)
+        click.echo(output, err=True)
 
 
 class JobSuiteBuilder:

benchpress/plugins/hooks/perf_monitors/topdown.py

@@ -457,12 +457,12 @@ def install_if_not_available(self):
                 return False
             subprocess.run(["topdown-tool", "--help"], capture_output=True, check=True)
         except subprocess.CalledProcessError as e:
-            print(
+            logger.warning(
                 f"Failed to install topdown-tool. Command: {e.cmd}, exit code: {e.returncode}"
             )
             return False
         except OSError:
-            print("Unable to chdir telemetry-solution/tools/topdown_tool")
+            logger.warning("Unable to chdir telemetry-solution/tools/topdown_tool")
             return False
         return True
 

benchpress/plugins/parsers/clang.py

@@ -4,10 +4,13 @@
 # LICENSE file in the root directory of this source tree.
 
 # pyre-unsafe
+import logging
 import re
 
 from benchpress.lib.parser import Parser
 
+logger = logging.getLogger(__name__)
+
 
 class ClangParser(Parser):
     def parse(self, stdout, stderr, returncode):
@@ -65,6 +68,6 @@ def try_parse_time(self, line: str) -> float:
             minute = int(m.group(1))
             second = float(m.group(2))
         except ValueError:
-            print("Failed to parse clang build time")
+            logger.error("Failed to parse clang build time")
             return -1
         return minute * 60 + second

benchpress/plugins/parsers/multichase_pointer.py

@@ -60,5 +60,4 @@ def parse(self, stdout, stderr, returncode):
                     key = key + " thread count " + thread_count
                 key = key + " latency (ns)"
                 metrics[key] = float(v.strip())
-        print("metrics", metrics)
         return metrics

benchpress/plugins/parsers/small_locks_bench.py

@@ -33,5 +33,4 @@ def parse(self, stdout, stderr, returncode):
                 metrics[lock_name + " stddev in us"] = float(stddev_val)
                 max_val = re.findall(REGEX_VAL_AFTER_MAX, line)[0]
                 metrics[lock_name + " max in us"] = float(max_val)
-        print(metrics)
         return metrics