IQ.Pilot/tools/scripts/io_stall_repro.py

#!/usr/bin/env python3
"""
io_stall_repro.py — bench reproduction + fix-validation rig for the VW PQ EPS
HCA fault (control loop stalling on a /data read under eMMC write saturation).

The real fault chain (proven from rlog b29ee8c5a0a735d1/000000e4--8a8ba97b54):
  loggerd buffered writes saturate eMMC -> ext4 jbd2 journal commits ->
  controlsd's inline Params.get (util::read_file on /data) blocks ~300-630ms ->
  controlsd stops publishing carControl -> card's all_alive guard withholds
  HCA_1 -> EPS LH2_Sta_HCA 7->2.

This reproduces the *proximate* cause WITHOUT driving, WITHOUT the EPS, and
WITHOUT touching the real control stack. Two roles:

  --writer : emulate loggerd. Buffered (no-fsync) writes to /data at a target
             MB/s, with an optional periodic big flush to mimic 60s segment
             rotation. This is what saturates the eMMC.

  --probe  : emulate controlsd's I/O exposure. A 100Hz loop that every
             --param-period seconds reads a real param (util::read_file on
             /data). It records per-iteration loop gaps and param-read
             durations. A 300ms gap here == the stall that drops HCA.
             --threaded moves the param read to a background thread (the
             proposed fix, mirroring card.py's params_thread) so you can A/B it.

USAGE (run parked, ignition on, on the device):
  # 1) baseline: probe alone -> gaps should be tiny
  python3 io_stall_repro.py --probe --secs 120

  # 2) reproduce: writer in one shell, probe in another
  python3 io_stall_repro.py --writer --mbps 25 --rotate 60
  python3 io_stall_repro.py --probe --secs 180          # expect big gaps

  # 3) validate fix A (params off control thread):
  python3 io_stall_repro.py --probe --secs 180 --threaded   # gaps should vanish

  # 4) validate fix B (smoother writeback) — set before step 2, as root:
  #   echo 5  > /proc/sys/vm/dirty_background_ratio
  #   echo 10 > /proc/sys/vm/dirty_ratio
  #   then re-run step 2 inline probe and compare gap distribution.

Cleanup: writer deletes its scratch files on exit. Read-only wrt openpilot.
"""
import argparse, os, sys, time, threading, statistics, signal

SCRATCH_DEFAULT = "/data/media/0/io_repro_scratch"

# ----------------------------------------------------------------------------- writer
def run_writer(args):
  os.makedirs(args.scratch, exist_ok=True)
  chunk = os.urandom(1 << 20)  # 1 MiB
  bytes_per_s = int(args.mbps * (1 << 20))
  print(f"[writer] buffered no-fsync writes to {args.scratch} at ~{args.mbps} MB/s, "
        f"rotate every {args.rotate}s (big flush). Ctrl-C to stop.", file=sys.stderr)

  stop = {"v": False}
  signal.signal(signal.SIGINT, lambda *_: stop.update(v=True))
  signal.signal(signal.SIGTERM, lambda *_: stop.update(v=True))

  files = []
  seg = 0
  try:
    while not stop["v"]:
      seg_start = time.monotonic()
      path = os.path.join(args.scratch, f"seg_{seg}.bin")
      f = open(path, "wb", buffering=1 << 20)
      files.append(path)
      written = 0
      # write at target rate using buffered fwrite, NO fsync (exactly loggerd)
      while not stop["v"] and (time.monotonic() - seg_start) < args.rotate:
        t0 = time.monotonic()
        f.write(chunk)
        written += len(chunk)
        # pace to target MB/s
        target_t = written / bytes_per_s
        elapsed = time.monotonic() - seg_start
        if target_t > elapsed:
          time.sleep(min(0.1, target_t - elapsed))
      # "segment rotation": flush+close a big buffered file at once -> writeback burst
      f.flush()
      f.close()
      seg += 1
      # keep only a few recent files so we don't fill the disk
      while len(files) > 3:
        old = files.pop(0)
        try: os.remove(old)
        except OSError: pass
  finally:
    for p in files:
      try: os.remove(p)
      except OSError: pass
    print("[writer] stopped, scratch cleaned.", file=sys.stderr)

# ----------------------------------------------------------------------------- probe
def _get_param(key):
  # real /data read, same syscall path as controlsd's get_params_iq
  try:
    from openpilot.common.params import Params
    return Params().get_bool(key)
  except Exception:
    # fallback: plain file read of a param file if openpilot import unavailable
    p = os.path.join(os.getenv("PARAMS_ROOT", "/data/params"), "d", key)
    try:
      with open(p, "rb") as fh:
        return fh.read()
    except OSError:
      return None

class ThreadedParam:
  """Mirror card.py params_thread: refresh the param on a bg thread, control
  loop reads the cached value (non-blocking)."""
  def __init__(self, key, period):
    self.key = key; self.period = period; self.val = None
    self.stop = False
    self.t = threading.Thread(target=self._loop, daemon=True); self.t.start()
  def _loop(self):
    while not self.stop:
      self.val = _get_param(self.key)
      time.sleep(self.period)
  def read(self):  # O(1), no I/O on the control thread
    return self.val

def run_probe(args):
  # pin like controlsd (core 4) so we share the same iowait domain if possible
  try:
    os.sched_setaffinity(0, {args.core})
  except (OSError, AttributeError):
    pass

  interval = 0.01  # 100Hz, like the control loop
  gaps = []          # ms, per-iteration loop overrun beyond 10ms
  read_ms = []       # ms, time spent in the param read on the control thread
  worst = 0.0
  threaded = ThreadedParam(args.param_key, args.param_period) if args.threaded else None

  print(f"[probe] 100Hz loop for {args.secs}s, param '{args.param_key}' every "
        f"{args.param_period}s, threaded={args.threaded}, core={args.core}", file=sys.stderr)
  t_end = time.monotonic() + args.secs
  next_t = time.monotonic()
  last_param = 0.0
  while time.monotonic() < t_end:
    loop_start = time.monotonic()

    # the I/O exposure: read param on the control thread (inline) every period
    if loop_start - last_param >= args.param_period:
      r0 = time.monotonic()
      if threaded is not None:
        _ = threaded.read()            # cached, no I/O on this thread (the FIX)
      else:
        _ = _get_param(args.param_key)  # inline /data read (current behavior)
      dr = (time.monotonic() - r0) * 1000
      read_ms.append(dr)
      last_param = loop_start

    # measure scheduling/lag: how late did this iteration actually fire?
    next_t += interval
    lag = (time.monotonic() - next_t) * 1000  # ms behind schedule
    if lag > 5:
      gaps.append(lag)
      worst = max(worst, lag)
    sleep = next_t - time.monotonic()
    if sleep > 0:
      time.sleep(sleep)
    else:
      next_t = time.monotonic()  # don't spiral after a big stall

  if threaded:
    threaded.stop = True

  def pct(xs, p):
    return sorted(xs)[int(p/100*(len(xs)-1))] if xs else 0.0
  print("\n================ PROBE RESULT ================")
  print(f"loop-lag events >5ms : {len(gaps)}")
  print(f"loop-lag p50/p99/max : {pct(gaps,50):.0f} / {pct(gaps,99):.0f} / {worst:.0f} ms")
  print(f"param-read p50/p99/max: {pct(read_ms,50):.1f} / {pct(read_ms,99):.1f} / {max(read_ms+[0]):.1f} ms  (n={len(read_ms)})")
  hca_class = max(gaps + [0])
  verdict = ("FAULT-CLASS STALL REPRODUCED (>250ms -> would drop HCA)" if hca_class > 250
             else "marginal (100-250ms)" if hca_class > 100
             else "clean (<100ms)")
  print(f"VERDICT: {verdict}")
  print("=============================================")

# ----------------------------------------------------------------------------- main
def main():
  ap = argparse.ArgumentParser()
  ap.add_argument("--writer", action="store_true", help="emulate loggerd eMMC saturation")
  ap.add_argument("--probe", action="store_true", help="emulate controlsd I/O exposure")
  ap.add_argument("--mbps", type=float, default=25.0, help="writer target MB/s (loggerd ~10-30)")
  ap.add_argument("--rotate", type=float, default=60.0, help="writer segment/flush period s")
  ap.add_argument("--scratch", default=SCRATCH_DEFAULT)
  ap.add_argument("--secs", type=float, default=180.0, help="probe duration s")
  ap.add_argument("--param-key", default="IsMetric", help="a real param key to read")
  ap.add_argument("--param-period", type=float, default=3.0, help="controlsd reads every 3s")
  ap.add_argument("--threaded", action="store_true", help="probe: read param off control thread (the FIX)")
  ap.add_argument("--core", type=int, default=4, help="probe cpu affinity (control core)")
  args = ap.parse_args()
  if args.writer == args.probe:
    ap.error("pick exactly one of --writer / --probe (run them in separate shells)")
  run_writer(args) if args.writer else run_probe(args)

if __name__ == "__main__":
  main()