perf: measure set benchmarks with user and system time

new_version/direct_hash/benchmark.py

@@ -3,15 +3,19 @@ import argparse
 import ctypes
 import gc
 import os
+import shutil
 import statistics
 import subprocess
-import time
+import sys
+import tempfile
 from pathlib import Path
 
 HERE = Path(__file__).resolve().parent
 BUILD = HERE / "build"
 LIBC = ctypes.CDLL(None)
 LIBC.free.argtypes = [ctypes.c_void_p]
+TIME_COMMAND = os.environ.get("TIME_COMMAND") or shutil.which("time") or "/usr/bin/time"
+TIME_FORMAT = "%U\t%S"
 
 
 class SetAPI:
@@ -49,108 +53,132 @@ class SetAPI:
         return encoded
 
 
-def median_fini(api, symbols, bpp, calls, rounds):
+def make_symbols(args):
-    samples = []
+    symbols = tuple(
-    for _ in range(rounds):
+        f"symbol_{i:08d}_version_ALT_{i % 97}".encode() for i in range(args.symbols)
-        sets = [api.new_with_symbols(symbols) for _ in range(calls)]
+    )
-        results = []
+    required = (
-        start = time.perf_counter_ns()
+        symbols[::2]
-        for value in sets:
+        if args.required is None
-            results.append(api.lib.set_fini(value, bpp))
+        else tuple(symbols[i * args.symbols // args.required] for i in range(args.required))
-        samples.append((time.perf_counter_ns() - start) / calls)
+    )
-        if not all(results):
+    return symbols, required
-            raise RuntimeError("set_fini returned NULL")
-        encoded = [ctypes.string_at(result) for result in results]
-        if len(set(encoded)) != 1:
-            raise RuntimeError("set_fini is not deterministic")
-        for value, result in zip(sets, results):
-            api.release(value, result)
-    return statistics.median(samples)
 
 
-def median_build(api, symbols, bpp, calls, rounds):
+def api_for(name):
-    samples = []
+    if name == "set9":
-    for _ in range(rounds):
+        return SetAPI(BUILD / "libset9.so")
-        sets = []
+    if name == "direct":
-        results = []
+        return SetAPI(BUILD / "libdirect-hash.so")
-        start = time.perf_counter_ns()
+    raise ValueError(f"unknown implementation: {name}")
-        for _ in range(calls):
+
+
+def child_main(args):
+    symbols, required = make_symbols(args)
+    api = api_for(args.time_child_impl)
+    checksum = 0
+
+    if args.time_child_operation == "fini":
+        # Measured by /usr/bin/time around this child process.  The repeated work
+        # is set construction plus set_fini; keeping construction in the same
+        # child avoids Python-side subsection timers while still reporting CPU
+        # user/system time from the external time utility.
+        for _ in range(args.fini_calls):
             value = api.new_with_symbols(symbols)
-            result = api.lib.set_fini(value, bpp)
+            result = api.lib.set_fini(value, args.bpp)
-            sets.append(value)
+            if not result:
-            results.append(result)
-        samples.append((time.perf_counter_ns() - start) / calls)
-        if not all(results):
                 raise RuntimeError("set_fini returned NULL")
-        for value, result in zip(sets, results):
+            checksum ^= len(ctypes.string_at(result))
             api.release(value, result)
-    return statistics.median(samples)
+    elif args.time_child_operation == "add":
-
+        for _ in range(args.fini_calls):
-
+            value = api.new_with_symbols(symbols)
-def median_add(api, symbols, calls, rounds):
+            checksum ^= int(value)
-    samples = []
-    for _ in range(rounds):
-        values = []
-        start = time.perf_counter_ns()
-        for _ in range(calls):
-            values.append(api.new_with_symbols(symbols))
-        samples.append((time.perf_counter_ns() - start) / calls)
-        for value in values:
             api.lib.set_free(value)
-    return statistics.median(samples)
+    elif args.time_child_operation == "build":
-
+        for _ in range(args.fini_calls):
-
+            value = api.new_with_symbols(symbols)
-def median_cmp(api, provider, requirement, calls, rounds):
+            result = api.lib.set_fini(value, args.bpp)
+            if not result:
+                raise RuntimeError("set_fini returned NULL")
+            checksum ^= len(ctypes.string_at(result))
+            api.release(value, result)
+    elif args.time_child_operation == "cmp-cold":
+        provider = api.encode(symbols, args.bpp)
+        requirement = api.encode(required, args.bpp)
+        for _ in range(args.cold_calls):
+            pid = os.fork()
+            if pid == 0:
+                result = api.lib.rpmsetcmp(provider, requirement)
+                os._exit(0 if result == 1 else 1)
+            _, status = os.waitpid(pid, 0)
+            if status != 0:
+                raise RuntimeError(f"cold rpmsetcmp child failed: status={status}")
+            checksum += 1
+    elif args.time_child_operation == "cmp-warm":
+        provider = api.encode(symbols, args.bpp)
+        requirement = api.encode(required, args.bpp)
         expected = api.lib.rpmsetcmp(provider, requirement)
         if expected != 1 or api.lib.rpmsetcmp(provider, provider) != 0:
             raise RuntimeError(f"unexpected rpmsetcmp result: {expected}")
         for _ in range(100):
             api.lib.rpmsetcmp(provider, requirement)
-
+        for _ in range(args.cmp_calls):
-    samples = []
-    for _ in range(rounds):
-        checksum = 0
-        start = time.perf_counter_ns()
-        for _ in range(calls):
             checksum += api.lib.rpmsetcmp(provider, requirement)
-        samples.append((time.perf_counter_ns() - start) / calls)
+        if checksum != args.cmp_calls:
-        if checksum != calls:
             raise RuntimeError("rpmsetcmp result changed during benchmark")
-    return statistics.median(samples)
+    else:
+        raise RuntimeError(f"unknown timed operation: {args.time_child_operation}")
+
+    # Keep a small observable side effect so timed loops are not optimized away
+    # inside the C library or by future wrappers.
+    print(checksum, file=sys.stderr)
 
 
-def cold_cmp_once(api, provider, requirement):
+def measure_with_time(args, implementation, operation, calls):
-    read_fd, write_fd = os.pipe()
-    pid = os.fork()
-    if pid == 0:
-        os.close(read_fd)
-        start = time.perf_counter_ns()
-        result = api.lib.rpmsetcmp(provider, requirement)
-        elapsed = time.perf_counter_ns() - start
-        os.write(write_fd, f"{elapsed} {result}".encode())
-        os.close(write_fd)
-        os._exit(0)
-
-    os.close(write_fd)
-    payload = b""
-    while chunk := os.read(read_fd, 128):
-        payload += chunk
-    os.close(read_fd)
-    _, status = os.waitpid(pid, 0)
-    if status != 0:
-        raise RuntimeError(f"cold rpmsetcmp child failed: status={status}")
-    elapsed, result = map(int, payload.split())
-    if result != 1:
-        raise RuntimeError(f"unexpected cold rpmsetcmp result: {result}")
-    return elapsed
-
-
-def median_cmp_cold(api, provider, requirement, calls, rounds):
     samples = []
-    for _ in range(rounds):
+    for _ in range(args.rounds):
-        total = sum(cold_cmp_once(api, provider, requirement) for _ in range(calls))
+        with tempfile.NamedTemporaryFile(prefix="arsv-time-", delete=False) as handle:
-        samples.append(total / calls)
+            time_path = Path(handle.name)
-    return statistics.median(samples)
+        command = [
+            TIME_COMMAND,
+            "-f",
+            TIME_FORMAT,
+            "-o",
+            str(time_path),
+            "--",
+            sys.executable,
+            str(Path(__file__).resolve()),
+            "--skip-build",
+            "--time-child",
+            "--time-child-impl",
+            implementation,
+            "--time-child-operation",
+            operation,
+            "--symbols",
+            str(args.symbols),
+            "--bpp",
+            str(args.bpp),
+            "--rounds",
+            "1",
+            "--fini-calls",
+            str(args.fini_calls),
+            "--cmp-calls",
+            str(args.cmp_calls),
+            "--cold-calls",
+            str(args.cold_calls),
+        ]
+        if args.required is not None:
+            command.extend(["--required", str(args.required)])
+        try:
+            subprocess.run(command, check=True, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
+            user_text, system_text = time_path.read_text().split()
+        finally:
+            time_path.unlink(missing_ok=True)
+        samples.append((float(user_text) / calls, float(system_text) / calls))
+    users = [sample[0] for sample in samples]
+    systems = [sample[1] for sample in samples]
+    return statistics.median(users), statistics.median(systems)
 
 
 def verify_complete_decoding(api, provider, requirement):
@@ -167,11 +195,17 @@ def verify_complete_decoding(api, provider, requirement):
         raise RuntimeError("second operand was not decoded and validated completely")
 
 
-def format_time(ns):
+def format_cpu_time(seconds):
-    return f"{ns / 1000:.2f} us"
+    return f"{seconds * 1_000_000:.2f} us"
 
 
-def main():
+def format_ratio(new, old):
+    if old == 0:
+        return "n/a"
+    return f"{new / old:.2f}x"
+
+
+def build_parser():
     parser = argparse.ArgumentParser(description="Compare set9 and direct-hash set APIs")
     parser.add_argument("--symbols", type=int, default=1000)
     parser.add_argument(
@@ -185,6 +219,18 @@ def main():
     parser.add_argument("--cmp-calls", type=int, default=2000)
     parser.add_argument("--cold-calls", type=int, default=20)
     parser.add_argument("--skip-build", action="store_true")
+    parser.add_argument("--time-child", action="store_true", help=argparse.SUPPRESS)
+    parser.add_argument("--time-child-impl", choices=("set9", "direct"), help=argparse.SUPPRESS)
+    parser.add_argument(
+        "--time-child-operation",
+        choices=("fini", "add", "build", "cmp-cold", "cmp-warm"),
+        help=argparse.SUPPRESS,
+    )
+    return parser
+
+
+def main():
+    parser = build_parser()
     args = parser.parse_args()
     if args.symbols < 2 or not 10 <= args.bpp <= 32:
         parser.error("symbols must be >= 2 and bpp must be in 10..32")
@@ -192,26 +238,27 @@ def main():
         parser.error("required must be in 1..symbols-1")
     if min(args.rounds, args.fini_calls, args.cmp_calls, args.cold_calls) < 1:
         parser.error("rounds and call counts must be positive")
+    if args.time_child and not (args.time_child_impl and args.time_child_operation):
+        parser.error("--time-child requires --time-child-impl and --time-child-operation")
 
     if not args.skip_build:
         subprocess.run([str(HERE / "build.sh")], check=True)
 
-    symbols = tuple(
+    if args.time_child:
-        f"symbol_{i:08d}_version_ALT_{i % 97}".encode() for i in range(args.symbols)
+        child_main(args)
-    )
+        return
-    required = (
+
-        symbols[::2]
+    if not Path(TIME_COMMAND).is_file():
-        if args.required is None
+        raise RuntimeError(f"time executable not found: {TIME_COMMAND}")
-        else tuple(symbols[i * args.symbols // args.required] for i in range(args.required))
+
-    )
+    symbols, required = make_symbols(args)
     apis = {
-        "set9": SetAPI(BUILD / "libset9.so"),
+        "set9": api_for("set9"),
-        "direct": SetAPI(BUILD / "libdirect-hash.so"),
+        "direct": api_for("direct"),
     }
 
     gc.disable()
     try:
-        timings = {name: [[] for _ in range(5)] for name in apis}
         lengths = {}
         encoded = {}
         for name, api in apis.items():
@@ -221,31 +268,20 @@ def main():
             wire_format = "D1/base64" if provider.startswith(b"D1") else "golomb/base62"
             lengths[name] = (len(provider), wire_format)
 
-        operations = (
-            lambda name, api: median_fini(api, symbols, args.bpp, args.fini_calls, 1),
-            lambda name, api: median_add(api, symbols, args.fini_calls, 1),
-            lambda name, api: median_build(api, symbols, args.bpp, args.fini_calls, 1),
-            lambda name, api: median_cmp_cold(
-                api, encoded[name][0], encoded[name][1], args.cold_calls, 1
-            ),
-            lambda name, api: median_cmp(
-                api, encoded[name][0], encoded[name][1], args.cmp_calls, 1
-            ),
-        )
-        names = tuple(apis)
-        for operation_index, operation in enumerate(operations):
-            for round_index in range(args.rounds):
-                order = names if round_index % 2 == 0 else tuple(reversed(names))
-                for name in order:
-                    timings[name][operation_index].append(operation(name, apis[name]))
-        timings = {
-            name: tuple(statistics.median(samples) for samples in operation_samples)
-            for name, operation_samples in timings.items()
-        }
-        # Run validation after timing: forked cold samples must inherit an empty
-        # decoded-set cache from the parent process.
         for name, api in apis.items():
             verify_complete_decoding(api, *encoded[name])
+
+        operations = (
+            ("set_fini child", "fini", args.fini_calls),
+            ("new+add child", "add", args.fini_calls),
+            ("new+add+fini child", "build", args.fini_calls),
+            ("rpmsetcmp cold", "cmp-cold", args.cold_calls),
+            ("rpmsetcmp warm", "cmp-warm", args.cmp_calls),
+        )
+        timings = {name: [] for name in apis}
+        for label, operation, calls in operations:
+            for name in apis:
+                timings[name].append(measure_with_time(args, name, operation, calls))
     finally:
         gc.enable()
 
@@ -253,18 +289,15 @@ def main():
     print("implementation  set_chars  format")
     for name in apis:
         print(f"{name:<14} {lengths[name][0]:>9}  {lengths[name][1]}")
-    print("\noperation                 set9       direct   direct/set9")
+    print("\noperation                 set9_user  set9_sys direct_user direct_sys  user_ratio sys_ratio")
-    labels = (
+    for index, (label, _operation, _calls) in enumerate(operations):
-        "set_fini only",
+        old_user, old_sys = timings["set9"][index]
-        "new+add (ctypes)",
+        new_user, new_sys = timings["direct"][index]
-        "new+add+fini (ctypes)",
+        print(
-        "rpmsetcmp cold",
+            f"{label:<22} {format_cpu_time(old_user):>10} {format_cpu_time(old_sys):>9} "
-        "rpmsetcmp warm",
+            f"{format_cpu_time(new_user):>11} {format_cpu_time(new_sys):>10} "
+            f"{format_ratio(new_user, old_user):>10} {format_ratio(new_sys, old_sys):>9}"
         )
-    for index, label in enumerate(labels):
-        old = timings["set9"][index]
-        new = timings["direct"][index]
-        print(f"{label:<22} {format_time(old):>10} {format_time(new):>10} {new / old:>12.2f}x")
 
 
 if __name__ == "__main__":

scripts/run-setc-bench.sh

@@ -16,6 +16,7 @@ PERF_EVENTS='task-clock,context-switches,cpu-migrations,page-faults,minor-faults
 PACKAGER='krosh <gudovdo@my.msu.ru>'
 APT_SOURCE=/etc/apt/sources.list.d/alt.list
 APT_GET=/usr/lib/apt/apt-get
+TIME_COMMAND=/usr/bin/time
 RPM_BUILD_GIT=https://git.altlinux.org/gears/r/rpm-build.git
 RPM_GIT=https://git.altlinux.org/gears/r/rpm.git
 
@@ -93,7 +94,7 @@ operation_label()
 
 run_once()
 {
-    local operation=$1 variant=$2 run=$3 start end status perf_stat
+    local operation=$1 variant=$2 run=$3 status perf_stat time_file
     local libdir="$variant/lib/usr/lib64"
     local root="$COMMON/root"
     local raw="$variant/raw"
@@ -117,8 +118,9 @@ run_once()
         )
     fi
 
-    start=$(date +%s%N)
+    time_file="$raw/$operation.$run.time.tsv"
-    if env LC_ALL=C APT_CONFIG="$COMMON/apt.conf" \
+    if "$TIME_COMMAND" -f $'%U\t%S' -o "$time_file" -- \
+        env LC_ALL=C APT_CONFIG="$COMMON/apt.conf" \
         LD_LIBRARY_PATH="$libdir" \
         taskset -c "$CPU" "${command[@]}" \
         >"$raw/$operation.$run.stdout" \
@@ -127,10 +129,7 @@ run_once()
     else
         status=$?
     fi
-    end=$(date +%s%N)
+    read -r RUN_USER_TIME RUN_SYSTEM_TIME <"$time_file"
-
-    RUN_TIME=$(awk -v start="$start" -v end="$end" \
-        'BEGIN { printf "%.6f", (end - start) / 1000000000 }')
     RUN_STATUS=$status
 }
 
@@ -228,8 +227,8 @@ benchmark_variant()
 {
     local variant=$1 result=$2 debug_file=$3 debuginfo_rpm=$4
     local runtime_file=$5 dso_name=$6
-    local operation run average label status_text perf_result perf_dir
+    local operation run average_user average_system label status_text perf_result perf_dir
-    local -a times statuses
+    local -a user_times system_times statuses
     local -a operations=(
         check
         autoremove
@@ -241,7 +240,7 @@ benchmark_variant()
     )
 
     mkdir -p "$variant/raw/perf-stat"
-    printf 'command\taverage_seconds\trun1_seconds\trun2_seconds\trun3_seconds\texit_status\n' \
+    printf 'command\taverage_user_seconds\taverage_system_seconds\trun1_user_seconds\trun1_system_seconds\trun2_user_seconds\trun2_system_seconds\trun3_user_seconds\trun3_system_seconds\texit_status\n' \
         >"$result"
     perf_result=${result%.tsv}.perf-stat.tsv
     perf_dir=${result%.tsv}.perf
@@ -257,22 +256,27 @@ benchmark_variant()
     fi
 
     for operation in "${operations[@]}"; do
-        times=()
+        user_times=()
+        system_times=()
         statuses=()
 
         for ((run = 1; run <= RUNS; ++run)); do
             run_once "$operation" "$variant" "$run"
-            times+=("$RUN_TIME")
+            user_times+=("$RUN_USER_TIME")
+            system_times+=("$RUN_SYSTEM_TIME")
             statuses+=("$RUN_STATUS")
             if ((COLLECT_PERF)); then
                 append_perf_stat "$operation" "$run" \
                     "$variant/raw/perf-stat/$operation.$run.tsv" "$perf_result"
             fi
-            printf '%s: run %d/%d: %ss, status=%s\n' \
+            printf '%s: run %d/%d: user=%ss system=%ss status=%s\n' \
-                "$operation" "$run" "$RUNS" "$RUN_TIME" "$RUN_STATUS"
+                "$operation" "$run" "$RUNS" \
+                "$RUN_USER_TIME" "$RUN_SYSTEM_TIME" "$RUN_STATUS"
         done
 
-        average=$(printf '%s\n' "${times[@]}" | \
+        average_user=$(printf '%s\n' "${user_times[@]}" | \
+            awk '{ total += $1 } END { printf "%.6f", total / NR }')
+        average_system=$(printf '%s\n' "${system_times[@]}" | \
             awk '{ total += $1 } END { printf "%.6f", total / NR }')
 
         status_text=${statuses[0]}
@@ -284,9 +288,11 @@ benchmark_variant()
         done
 
         label=$(operation_label "$operation")
-        printf '%s\t%s\t%s\t%s\t%s\t%s\n' \
+        printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \
-            "$label" "$average" \
+            "$label" "$average_user" "$average_system" \
-            "${times[0]}" "${times[1]}" "${times[2]}" "$status_text" \
+            "${user_times[0]}" "${system_times[0]}" \
+            "${user_times[1]}" "${system_times[1]}" \
+            "${user_times[2]}" "${system_times[2]}" "$status_text" \
             >>"$result"
 
         if ((COLLECT_PERF && PERF_RECORD)); then
@@ -300,6 +306,7 @@ for command in git gear-hsh hsh rpm rpmquery rpm2cpio cpio apt-get apt-cache \
     taskset awk sed date sha256sum ldd readelf readlink eu-unstrip; do
     command -v "$command" >/dev/null || fail "required command not found: $command"
 done
+[[ -x $TIME_COMMAND ]] || fail "time executable not found: $TIME_COMMAND"
 if ((COLLECT_PERF)); then
     command -v perf >/dev/null || \
         fail "perf is not installed; install the ALT package: apt-get install perf"