Add syscall count benchmark for 002_hello.ts (#820)

* Add syscall count tracking for benchmark

* Add fetch_deps thread benchmark

* Switch to `strace -c` for syscall parsing

* Spawn http_server during benchmark (for fetch)

* Rename `benchmarks` to `exec_time_benchmarks`

* Update app_test.js

3 files changed, 140 insertions, 19 deletions

diff --git a/tools/benchmark.py b/tools/benchmark.py
index 837a86180..b3a6fd363 100755
--- a/tools/benchmark.py
+++ b/tools/benchmark.py
@@ -12,11 +12,17 @@ import time
 import shutil
 from util import run, run_output, root_path, build_path
 import tempfile
+import http_server
+
+try:
+    http_server.spawn()
+except:
+    "Warning: another http_server instance is running"
 
 # The list of the tuples of the benchmark name and arguments
-benchmarks = [("hello", ["tests/002_hello.ts", "--reload"]),
-              ("relative_import", ["tests/003_relative_import.ts",
-                                   "--reload"])]
+exec_time_benchmarks = [("hello", ["tests/002_hello.ts", "--reload"]),
+                        ("relative_import",
+                         ["tests/003_relative_import.ts", "--reload"])]
 
 gh_pages_data_file = "gh-pages/data.json"
 data_file = "website/data.json"
@@ -45,23 +51,67 @@ def import_data_from_gh_pages():
         write_json(data_file, [])  # writes empty json data
 
 
-# run strace with test_args and record times a syscall record appears in out file
-# based on syscall_line_matcher. Should be reusable
-def count_strace_syscall(syscall_name, syscall_line_matcher, test_args):
+def get_strace_summary_text(test_args):
     f = tempfile.NamedTemporaryFile()
-    run(["strace", "-f", "-o", f.name, "-e", "trace=" + syscall_name] +
-        test_args)
-    return len(filter(syscall_line_matcher, f))
+    run(["strace", "-c", "-f", "-o", f.name] + test_args)
+    return f.read()
+
+
+def strace_parse(summary_text):
+    summary = {}
+    # clear empty lines
+    lines = list(filter(lambda x: x and x != "\n", summary_text.split("\n")))
+    if len(lines) < 4:
+        return {}  # malformed summary
+    lines, total_line = lines[2:-2], lines[-1]
+    # data to dict for each line
+    for line in lines:
+        syscall_fields = line.split()
+        syscall_name = syscall_fields[-1]
+        syscall_dict = {}
+        if 5 <= len(syscall_fields) <= 6:
+            syscall_dict = {
+                "% time": float(syscall_fields[0]),
+                "seconds": float(syscall_fields[1]),
+                "usecs/call": int(syscall_fields[2]),
+                "calls": int(syscall_fields[3])
+            }
+            syscall_dict["errors"] = 0 if len(syscall_fields) < 6 else int(
+                syscall_fields[4])
+        summary[syscall_name] = syscall_dict
+    # record overall (total) data
+    total_fields = total_line.split()
+    summary["total"] = {
+        "% time": float(total_fields[0]),
+        "seconds": float(total_fields[1]),
+        "calls": int(total_fields[2]),
+        "errors": int(total_fields[3])
+    }
+    return summary
+
+
+def get_strace_summary(test_args):
+    return strace_parse(get_strace_summary_text(test_args))
 
 
 def run_thread_count_benchmark(deno_path):
     thread_count_map = {}
-    thread_count_map["set_timeout"] = count_strace_syscall(
-        "clone", lambda line: "clone(" in line,
-        [deno_path, "tests/004_set_timeout.ts", "--reload"]) + 1
+    thread_count_map["set_timeout"] = get_strace_summary([
+        deno_path, "tests/004_set_timeout.ts", "--reload"
+    ])["clone"]["calls"] + 1
+    thread_count_map["fetch_deps"] = get_strace_summary([
+        deno_path, "tests/fetch_deps.ts", "--reload", "--allow-net"
+    ])["clone"]["calls"] + 1
     return thread_count_map
 
 
+def run_syscall_count_benchmark(deno_path):
+    syscall_count_map = {}
+    syscall_count_map["hello"] = get_strace_summary(
+        [deno_path, "tests/002_hello.ts", "--reload"])["total"]["calls"]
+    return syscall_count_map
+
+
 def main(argv):
     if len(argv) == 2:
         build_dir = sys.argv[1]
@@ -77,8 +127,9 @@ def main(argv):
     os.chdir(root_path)
     import_data_from_gh_pages()
     # TODO: Use hyperfine in //third_party
-    run(["hyperfine", "--export-json", benchmark_file, "--warmup", "3"] +
-        [deno_path + " " + " ".join(args) for [_, args] in benchmarks])
+    run(["hyperfine", "--export-json", benchmark_file, "--warmup", "3"] + [
+        deno_path + " " + " ".join(args) for [_, args] in exec_time_benchmarks
+    ])
     all_data = read_json(data_file)
     benchmark_data = read_json(benchmark_file)
     sha1 = run_output(["git", "rev-parse", "HEAD"]).strip()
@@ -87,9 +138,11 @@ def main(argv):
         "sha1": sha1,
         "binary_size": os.path.getsize(deno_path),
         "thread_count": {},
+        "syscall_count": {},
         "benchmark": {}
     }
-    for [[name, _], data] in zip(benchmarks, benchmark_data["results"]):
+    for [[name, _], data] in zip(exec_time_benchmarks,
+                                 benchmark_data["results"]):
         new_data["benchmark"][name] = {
             "mean": data["mean"],
             "stddev": data["stddev"],
@@ -102,6 +155,7 @@ def main(argv):
     if "linux" in sys.platform:
         # Thread count test, only on linux
         new_data["thread_count"] = run_thread_count_benchmark(deno_path)
+        new_data["syscall_count"] = run_syscall_count_benchmark(deno_path)
 
     all_data.append(new_data)
     write_json(data_file, all_data)
diff --git a/tools/benchmark_test.py b/tools/benchmark_test.py
index 017314fbb..cdaad1e1f 100644
--- a/tools/benchmark_test.py
+++ b/tools/benchmark_test.py
@@ -1,10 +1,38 @@
 import sys
 import os
-from benchmark import run_thread_count_benchmark
+import benchmark
+
+
+def strace_parse_test():
+    with open(os.path.join(sys.path[0], "testdata/strace_summary.out"),
+              "r") as f:
+        summary = benchmark.strace_parse(f.read())
+        # first syscall line
+        assert summary["munmap"]["calls"] == 60
+        assert summary["munmap"]["errors"] == 0
+        # line with errors
+        assert summary["mkdir"]["errors"] == 2
+        # last syscall line
+        assert summary["prlimit64"]["calls"] == 2
+        assert summary["prlimit64"]["% time"] == 0
+        # summary line
+        assert summary["total"]["calls"] == 704
+
+
+def thread_count_test(deno_path):
+    thread_count_dict = benchmark.run_thread_count_benchmark(deno_path)
+    assert "set_timeout" in thread_count_dict
+    assert thread_count_dict["set_timeout"] > 1
+
+
+def syscall_count_test(deno_path):
+    syscall_count_dict = benchmark.run_syscall_count_benchmark(deno_path)
+    assert "hello" in syscall_count_dict
+    assert syscall_count_dict["hello"] > 1
 
 
 def benchmark_test(deno_path):
+    strace_parse_test()
     if "linux" in sys.platform:
-        thread_count_dict = run_thread_count_benchmark(deno_path)
-        assert "set_timeout" in thread_count_dict
-        assert thread_count_dict["set_timeout"] > 1
+        thread_count_test(deno_path)
+        syscall_count_test(deno_path)
diff --git a/tools/testdata/strace_summary.out b/tools/testdata/strace_summary.out
new file mode 100644
index 000000000..7984b175a
--- /dev/null
+++ b/tools/testdata/strace_summary.out
@@ -0,0 +1,39 @@
+% time     seconds  usecs/call     calls    errors syscall
+------ ----------- ----------- --------- --------- ----------------
+ 65.76    0.005881          98        60           munmap
+ 13.79    0.001233           2       462           mprotect
+  7.13    0.000638          11        56           mmap
+  3.57    0.000319          22        14           openat
+  1.65    0.000148          10        14           fstat
+  1.58    0.000141           7        20           read
+  1.53    0.000137           7        18           close
+  1.49    0.000133          16         8           madvise
+  1.10    0.000098          98         1           execve
+  0.30    0.000027           9         3           prctl
+  0.29    0.000026          26         1         1 access
+  0.25    0.000022          11         2         2 mkdir
+  0.23    0.000021           7         3           write
+  0.18    0.000016           4         4           set_robust_list
+  0.16    0.000014           7         2           brk
+  0.15    0.000013          13         1           pipe2
+  0.11    0.000010           3         3           clone
+  0.11    0.000010           3         3           sigaltstack
+  0.10    0.000009           4         2           stat
+  0.10    0.000009           9         1           arch_prctl
+  0.10    0.000009           9         1           epoll_create1
+  0.09    0.000008           8         1           epoll_ctl
+  0.08    0.000007           3         2           getrandom
+  0.04    0.000004           4         1           getcwd
+  0.04    0.000004           2         2           sched_getaffinity
+  0.03    0.000003           3         1         1 ioctl
+  0.03    0.000003           1         3           futex
+  0.00    0.000000           0         1           open
+  0.00    0.000000           0         5           rt_sigaction
+  0.00    0.000000           0         1           rt_sigprocmask
+  0.00    0.000000           0         1           fcntl
+  0.00    0.000000           0         1         1 readlink
+  0.00    0.000000           0         1           set_tid_address
+  0.00    0.000000           0         3           epoll_wait
+  0.00    0.000000           0         2           prlimit64
+------ ----------- ----------- --------- --------- ----------------
+100.00    0.008943                   704         5 total