v0.33.8

scripts/performance/profile_syscalls.py

@@ -0,0 +1,284 @@
+#!/usr/bin/env python3
+"""Profile selected server syscalls separately from throughput measurements.
+
+Runs each RustProxy binary sequentially against a disposable loopback fixture.
+The measured operation is one persistent HTTP/1.1 connection requesting the
+64-KiB static file with cache disabled and Accept-Encoding: identity.
+Every response is validated; syscall counts include background server work.
+strace elapsed/CPU times must not be interpreted as uninstrumented performance.
+"""
+from __future__ import annotations
+
+import argparse
+import hashlib
+from http.client import HTTPConnection
+import json
+import os
+from pathlib import Path
+import platform
+import re
+import shutil
+import signal
+import subprocess
+import sys
+import time
+import traceback
+
+from common import Fixture, seal_results, sha256, write_json
+from resources import descendants
+
+
+SYSCALLS = ("read", "pread64", "write", "writev", "openat", "close", "fcntl", "lseek", "futex")
+REQUEST_PATH = "/large.bin"
+
+
+def thread_tracers(pid: int) -> dict[int, int]:
+    result = {}
+    for task in Path(f"/proc/{pid}/task").iterdir():
+        try:
+            status = (task / "status").read_text()
+        except FileNotFoundError:
+            continue  # A thread may exit between the directory read and status.
+        match = re.search(r"^TracerPid:\s+(\d+)$", status, re.MULTILINE)
+        if match:
+            result[int(task.name)] = int(match.group(1))
+    return result
+
+
+def wait_attached(tracer, server, timeout=10):
+    deadline = time.monotonic() + timeout
+    while time.monotonic() < deadline:
+        if tracer.poll() is not None:
+            raise RuntimeError("strace exited before attachment; see strace diagnostic log (ptrace may be unavailable)")
+        if server.poll() is not None:
+            raise RuntimeError("server exited during strace attachment")
+        traced = thread_tracers(server.pid)
+        if traced and all(traced.values()):
+            return sorted(traced)
+        time.sleep(.01)
+    raise RuntimeError("strace did not attach to every server thread within 10 seconds")
+
+
+def detach(tracer, server):
+    # Do not signal the process group: only the independently started tracer.
+    if tracer.poll() is None:
+        tracer.send_signal(signal.SIGINT)
+        try:
+            tracer.wait(timeout=10)
+        except subprocess.TimeoutExpired:
+            tracer.terminate()
+            try:
+                tracer.wait(timeout=3)
+            except subprocess.TimeoutExpired:
+                tracer.kill()
+                tracer.wait(timeout=3)
+            raise RuntimeError("strace failed to finish on SIGINT; profile is incomplete")
+    if server.poll() is not None:
+        raise RuntimeError("server exited while the tracer was detached")
+    traced = thread_tracers(server.pid)
+    if not traced or any(traced.values()):
+        raise RuntimeError("server still has traced threads after strace exited")
+    return {"signal": "SIGINT to strace PID only", "strace_returncode": tracer.returncode,
+            "server_alive": True, "remaining_traced_threads": 0}
+
+
+def parse_summary(path: Path, requests: int):
+    rows = {name: {"calls": 0, "errors": 0, "calls_per_request": 0.0}
+            for name in SYSCALLS}
+    total = None
+    for line in path.read_text().splitlines():
+        fields = line.split()
+        if len(fields) not in (5, 6) or fields[-1] not in (*SYSCALLS, "total"):
+            continue
+        percent, seconds, usecs, calls = map(float, fields[:4])
+        errors = int(fields[4]) if len(fields) == 6 else 0
+        row = {"calls": int(calls), "errors": errors,
+               "calls_per_request": int(calls) / requests,
+               "strace_system_seconds": seconds, "strace_percent_time": percent,
+               "strace_us_per_call": usecs}
+        if fields[-1] == "total":
+            total = row
+        else:
+            rows[fields[-1]] = row
+    if total is None:
+        raise RuntimeError(f"no complete strace summary found in {path}")
+    if sum(row["calls"] for row in rows.values()) != total["calls"]:
+        raise RuntimeError("parsed syscall counts do not match the raw strace total")
+    return {"selected_syscalls": rows, "selected_total": total}
+
+
+def request_checked(connection, expected_socket, expected_sha, phase, sequence, evidence):
+    if connection.sock is not expected_socket:
+        raise RuntimeError("keepalive connection was replaced before the next request")
+    connection.request("GET", REQUEST_PATH,
+                       headers={"Accept-Encoding": "identity", "Connection": "keep-alive"})
+    response = connection.getresponse()
+    payload = response.read()
+    digest = hashlib.sha256(payload).hexdigest()
+    headers = {key.lower(): value for key, value in response.getheaders()}
+    valid = (response.status == 200 and len(payload) == 65536 and digest == expected_sha
+             and headers.get("content-length") == "65536"
+             and headers.get("content-encoding", "identity") == "identity"
+             and connection.sock is expected_socket and not response.will_close)
+    result = {"phase": phase, "sequence": sequence, "status": response.status,
+              "bytes": len(payload), "sha256": digest,
+              "content_length": headers.get("content-length"),
+              "content_encoding": headers.get("content-encoding"),
+              "connection_reused": connection.sock is expected_socket,
+              "will_close": response.will_close, "passed": valid}
+    evidence.write(json.dumps(result, sort_keys=True) + "\n")
+    evidence.flush()
+    if not valid:
+        raise RuntimeError(f"response verification failed in {phase} request {sequence}: {result}")
+
+
+def profile_variant(fixture, label, binary, args):
+    rust = fixture.rust(binary, label)
+    rust.login()
+    rust.wait_quiescent()
+    raw = args.out / "raw"
+    raw.mkdir(exist_ok=True)
+    summary_path = raw / f"{label}.strace.txt"
+    diagnostic_path = raw / f"{label}.strace.log"
+    responses_path = raw / f"{label}.responses.jsonl"
+    expected_sha = sha256(fixture.site / "large.bin")
+    quiescence_path = fixture.results / f"{label}-quiescence.json"
+    config_path = fixture.results / "configs" / f"{label}-base.json"
+    config_sha = sha256(config_path)
+    if config_sha != rust.applies[-1]["sha256"]:
+        raise RuntimeError("saved fixture configuration differs from the applied configuration")
+    command = [str(args.strace), "-f", "-c", "-e", "trace=" + ",".join(SYSCALLS),
+               "-p", str(rust.process.pid), "-o", str(summary_path)]
+    connection = HTTPConnection("127.0.0.1", rust.static_port, timeout=args.timeout)
+    tracer = None
+    result = {"variant": label, "binary": str(binary), "binary_sha256": sha256(binary),
+              "config": str(config_path.relative_to(args.out)), "config_sha256": config_sha,
+              "quiescence": str(quiescence_path.relative_to(args.out)),
+              "quiescence_sha256": sha256(quiescence_path),
+              "pid": rust.process.pid, "request_path": REQUEST_PATH, "payload_bytes": 65536,
+              "payload_sha256": expected_sha, "cache_enabled": False,
+              "request_encoding": "identity", "concurrency": 1,
+              "warmup_requests": args.warmup, "profile_requests": args.requests,
+              "strace_command": command, "raw_summary": str(summary_path.relative_to(args.out)),
+              "raw_diagnostics": str(diagnostic_path.relative_to(args.out)),
+              "responses": str(responses_path.relative_to(args.out)), "passed": False}
+    try:
+        with responses_path.open("w") as responses, diagnostic_path.open("w") as diagnostics:
+            connection.connect()
+            expected_socket = connection.sock
+            result["client_local_address"] = expected_socket.getsockname()
+            for index in range(args.warmup):
+                request_checked(connection, expected_socket, expected_sha, "warmup", index + 1, responses)
+            result["processes_before_attach"] = descendants(rust.process.pid)
+            if result["processes_before_attach"] != [rust.process.pid]:
+                raise RuntimeError("server spawned a child after quiescence; refusing contaminated syscall trace")
+            environment = os.environ.copy()
+            environment["LC_ALL"] = "C"
+            tracer = subprocess.Popen(command, stdout=diagnostics, stderr=diagnostics,
+                                      env=environment, start_new_session=True)
+            result["initial_traced_threads"] = wait_attached(tracer, rust.process)
+            started = time.monotonic()
+            try:
+                for index in range(args.requests):
+                    request_checked(connection, expected_socket, expected_sha, "profile", index + 1, responses)
+                    if tracer.poll() is not None:
+                        raise RuntimeError("strace exited before all profile requests completed")
+            finally:
+                result["instrumented_request_loop_seconds"] = time.monotonic() - started
+                result["detach"] = detach(tracer, rust.process)
+                tracer = None
+            # An actual HTTP response after detaching proves the server stayed usable.
+            request_checked(connection, expected_socket, expected_sha, "after_detach", 1, responses)
+            result["processes_after_detach"] = descendants(rust.process.pid)
+            if result["processes_after_detach"] != [rust.process.pid]:
+                raise RuntimeError("server has a child after profiling; syscall trace needs review")
+        result.update(parse_summary(summary_path, args.requests))
+        result["verified_responses"] = args.requests + args.warmup + 1
+        result["passed"] = True
+        return result
+    finally:
+        if tracer is not None:
+            detach(tracer, rust.process)
+        connection.close()
+        fixture.stop(rust.process)
+        write_json(args.out / f"{label}.json", result)
+
+
+def main():
+    parser = argparse.ArgumentParser(description=__doc__)
+    parser.add_argument("--binary", action="append", required=True, metavar="LABEL=/ABS/PATH")
+    parser.add_argument("--nginx", type=Path, required=True, help="nginx executable for the shared fixture origin")
+    parser.add_argument("--strace", type=Path, default=shutil.which("strace"))
+    parser.add_argument("--out", type=Path, required=True)
+    parser.add_argument("--requests", type=int, default=500)
+    parser.add_argument("--warmup", type=int, default=20)
+    parser.add_argument("--workers", type=int, default=4)
+    parser.add_argument("--origin-workers", type=int, default=4)
+    parser.add_argument("--server-cpus")
+    parser.add_argument("--origin-cpus")
+    parser.add_argument("--timeout", type=float, default=20)
+    args = parser.parse_args()
+    if args.requests < 1 or args.warmup < 0 or args.workers < 1 or args.origin_workers < 1 or args.timeout <= 0:
+        parser.error("requests/workers/timeout must be positive, warmup must be nonnegative")
+    if args.strace is None:
+        parser.error("strace is required; pass --strace /absolute/path")
+    if args.out.exists() and (not args.out.is_dir() or any(args.out.iterdir())):
+        parser.error("--out must be a new or empty directory; existing evidence is never overwritten")
+    variants = {}
+    for value in args.binary:
+        label, separator, filename = value.partition("=")
+        if not separator or not re.fullmatch(r"[A-Za-z][A-Za-z0-9_-]{0,48}", label) or label in variants:
+            parser.error("each --binary must use a unique filesystem-safe LABEL=/ABS/PATH")
+        binary = Path(filename).resolve()
+        if not binary.is_file():
+            parser.error(f"binary does not exist: {binary}")
+        variants[label] = binary
+    args.out, args.nginx, args.strace = args.out.resolve(), args.nginx.resolve(), args.strace.resolve()
+    for executable in (args.nginx, args.strace):
+        if not executable.is_file() or not os.access(executable, os.X_OK):
+            parser.error(f"executable is missing or is not executable: {executable}")
+    args.out.mkdir(parents=True, exist_ok=True)
+    version = subprocess.run([str(args.strace), "-V"], capture_output=True, text=True, timeout=10)
+    environment = {"kind": "selected syscall counts with ptrace instrumentation", "simulation": False,
+        "platform": platform.platform(), "python": sys.version, "strace_version": version.stdout + version.stderr,
+        "strace_sha256": sha256(args.strace), "nginx_sha256": sha256(args.nginx),
+        "variant_order": list(variants), "selected_syscalls": SYSCALLS,
+        "started_utc": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()),
+        "settings": {key: str(value) if isinstance(value, Path) else value for key, value in vars(args).items()},
+        "limitations": ["strace changes scheduling and latency; do not use instrumented times as RPS evidence",
+                        "Counts cover selected syscalls in every traced server thread, including background work",
+                        "Normalized counts divide the whole trace by verified profile requests; they do not isolate per-request causality",
+                        "This is a warm-file-cache, c1, HTTP/1.1 plaintext static-file scenario; no general capacity inference",
+                        "Syscall counts do not directly count Tokio task dispatches or memory allocations"]}
+    for path in ("/proc/sys/kernel/yama/ptrace_scope", "/sys/fs/cgroup/cpu.max", "/sys/fs/cgroup/memory.max"):
+        try:
+            environment[path] = Path(path).read_text().strip()
+        except OSError:
+            environment[path] = None
+    write_json(args.out / "environment.json", environment)
+    rows, error = [], None
+    try:
+        with Fixture(args.out / "fixture", workers=args.workers, server_cpus=args.server_cpus,
+                     origin_cpus=args.origin_cpus, origin_workers=args.origin_workers) as fixture:
+            fixture.nginx(args.nginx, frontend=False)
+            for label, binary in variants.items():
+                result = profile_variant(fixture, label, binary, args)
+                rows.append(result)
+                write_json(args.out / "profiles.json", rows)
+                print(json.dumps({"variant": label, "requests": args.requests, "passed": result["passed"],
+                                  "selected_syscall_calls": result["selected_total"]["calls"]}), flush=True)
+    except Exception as exc:
+        error = {"error": str(exc), "traceback": traceback.format_exc()}
+        write_json(args.out / "failure.json", error)
+        print(json.dumps(error), flush=True)
+    finally:
+        write_json(args.out / "profiles.json", rows)
+        write_json(args.out / "completion.json", {"completed": error is None, "profiles": len(rows),
+            "simulation": False, "throughput_measurement": False,
+            "finished_utc": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime())})
+        seal_results(args.out)
+    return 1 if error else 0
+
+
+if __name__ == "__main__":
+    sys.exit(main())