285 lines
15 KiB
Python
Executable File
285 lines
15 KiB
Python
Executable File
#!/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())
|