diff --git a/new_version/direct_hash/benchmark.py b/new_version/direct_hash/benchmark.py index 7bb1b94..47cb284 100755 --- a/new_version/direct_hash/benchmark.py +++ b/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): - samples = [] - for _ in range(rounds): - sets = [api.new_with_symbols(symbols) for _ in range(calls)] - results = [] - start = time.perf_counter_ns() - for value in sets: - results.append(api.lib.set_fini(value, bpp)) - samples.append((time.perf_counter_ns() - start) / calls) - if not all(results): - 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 make_symbols(args): + symbols = tuple( + f"symbol_{i:08d}_version_ALT_{i % 97}".encode() for i in range(args.symbols) + ) + required = ( + symbols[::2] + if args.required is None + else tuple(symbols[i * args.symbols // args.required] for i in range(args.required)) + ) + return symbols, required -def median_build(api, symbols, bpp, calls, rounds): - samples = [] - for _ in range(rounds): - sets = [] - results = [] - start = time.perf_counter_ns() - for _ in range(calls): +def api_for(name): + if name == "set9": + return SetAPI(BUILD / "libset9.so") + if name == "direct": + return SetAPI(BUILD / "libdirect-hash.so") + raise ValueError(f"unknown implementation: {name}") + + +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) - sets.append(value) - 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): + 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) - return statistics.median(samples) - - -def median_add(api, symbols, calls, rounds): - 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: + elif args.time_child_operation == "add": + for _ in range(args.fini_calls): + value = api.new_with_symbols(symbols) + checksum ^= int(value) api.lib.set_free(value) - return statistics.median(samples) - - -def median_cmp(api, provider, requirement, calls, rounds): - 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) - - samples = [] - for _ in range(rounds): - checksum = 0 - start = time.perf_counter_ns() - for _ in range(calls): + elif args.time_child_operation == "build": + for _ in range(args.fini_calls): + value = api.new_with_symbols(symbols) + 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): checksum += api.lib.rpmsetcmp(provider, requirement) - samples.append((time.perf_counter_ns() - start) / calls) - if checksum != calls: + if checksum != args.cmp_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): - 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): +def measure_with_time(args, implementation, operation, calls): samples = [] - for _ in range(rounds): - total = sum(cold_cmp_once(api, provider, requirement) for _ in range(calls)) - samples.append(total / calls) - return statistics.median(samples) + for _ in range(args.rounds): + with tempfile.NamedTemporaryFile(prefix="arsv-time-", delete=False) as handle: + time_path = Path(handle.name) + 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): - return f"{ns / 1000:.2f} us" +def format_cpu_time(seconds): + 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( - f"symbol_{i:08d}_version_ALT_{i % 97}".encode() for i in range(args.symbols) - ) - required = ( - symbols[::2] - if args.required is None - else tuple(symbols[i * args.symbols // args.required] for i in range(args.required)) - ) + if args.time_child: + child_main(args) + return + + if not Path(TIME_COMMAND).is_file(): + raise RuntimeError(f"time executable not found: {TIME_COMMAND}") + + symbols, required = make_symbols(args) apis = { - "set9": SetAPI(BUILD / "libset9.so"), - "direct": SetAPI(BUILD / "libdirect-hash.so"), + "set9": api_for("set9"), + "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") - labels = ( - "set_fini only", - "new+add (ctypes)", - "new+add+fini (ctypes)", - "rpmsetcmp cold", - "rpmsetcmp warm", - ) - 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") + print("\noperation set9_user set9_sys direct_user direct_sys user_ratio sys_ratio") + for index, (label, _operation, _calls) in enumerate(operations): + old_user, old_sys = timings["set9"][index] + new_user, new_sys = timings["direct"][index] + print( + f"{label:<22} {format_cpu_time(old_user):>10} {format_cpu_time(old_sys):>9} " + 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}" + ) if __name__ == "__main__": diff --git a/scripts/run-setc-bench.sh b/scripts/run-setc-bench.sh index 6935513..bb550fe 100755 --- a/scripts/run-setc-bench.sh +++ b/scripts/run-setc-bench.sh @@ -16,6 +16,7 @@ PERF_EVENTS='task-clock,context-switches,cpu-migrations,page-faults,minor-faults PACKAGER='krosh ' 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) - if env LC_ALL=C APT_CONFIG="$COMMON/apt.conf" \ + time_file="$raw/$operation.$run.time.tsv" + 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) - - RUN_TIME=$(awk -v start="$start" -v end="$end" \ - 'BEGIN { printf "%.6f", (end - start) / 1000000000 }') + read -r RUN_USER_TIME RUN_SYSTEM_TIME <"$time_file" 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 -a times statuses + local operation run average_user average_system label status_text perf_result perf_dir + 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' \ - "$operation" "$run" "$RUNS" "$RUN_TIME" "$RUN_STATUS" + printf '%s: run %d/%d: user=%ss system=%ss status=%s\n' \ + "$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' \ - "$label" "$average" \ - "${times[0]}" "${times[1]}" "${times[2]}" "$status_text" \ + printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \ + "$label" "$average_user" "$average_system" \ + "${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"