#!/usr/bin/env python3 """ io_stall_tracer.py — continuous low-overhead per-process disk-I/O tracer. WHY: the VW PQ EPS HCA faults are caused by a control process (controlsd/card) blocking ~300-630ms in disk I/O (iowait) on /data, which stops HCA_1 TX. The stall is far too short to catch with a manual `iostat`/`iotop` run. This sampler runs for the whole drive at 100ms cadence and records, per process: - write_bytes (/proc//io) -> identifies the WRITER saturating eMMC - delayacct_blkio (/proc//stat) -> per-process cumulative block-I/O wait - state (/proc//stat) -> catches 'D' (uninterruptible disk wait) plus whole-device /proc/diskstats. After a fault, find the wall-clock time of the LH2_Sta_HCA->2 event (from the rlog) and look at the rows around it: the process whose write_bytes delta spikes is the bully; the control process whose blkio delta jumps / state == 'D' is the victim. Deploy: copy to the device, run alongside openpilot during a drive: python3 io_stall_tracer.py --out /data/media/0/io_trace.csv Overhead: reading /proc for ~40 procs every 100ms is well under 1% of one core, and it pins itself to CPU 0 (away from the control cores 4/5) at low priority. Read-only. Writes a single CSV. No openpilot deps. """ import argparse, os, time, glob, sys CLK_TCK = os.sysconf("SC_CLK_TCK") # usually 100 -> blkio ticks are 10ms each def read_proc_io(pid): # wchar/rchar = bytes moved via read()/write() syscalls (catches BUFFERED writers # like loggerd, which never appear in write_bytes because the kernel flushes their # page-cache dirty pages asynchronously via kworker). write_bytes = bytes actually # sent to the block device. Track both. try: with open(f"/proc/{pid}/io") as f: d = {} for line in f: k, _, v = line.partition(":") d[k] = int(v) return (d.get("wchar", 0), d.get("rchar", 0), d.get("write_bytes", 0), d.get("read_bytes", 0)) except (OSError, ValueError): return None def read_proc_stat(pid): # state is field 3; delayacct_blkio_ticks is field 42 (1-indexed). comm may # contain spaces/parens, so split on the last ')'. try: with open(f"/proc/{pid}/stat") as f: data = f.read() rparen = data.rfind(")") comm = data[data.find("(") + 1:rparen] rest = data[rparen + 2:].split() state = rest[0] # field 3 blkio_ticks = int(rest[39]) if len(rest) > 39 else 0 # field 42 return comm, state, blkio_ticks except (OSError, ValueError, IndexError): return None def read_diskstats(): # returns {dev: (sectors_written, ms_doing_io)} for whole-disk devices out = {} try: with open("/proc/diskstats") as f: for line in f: p = line.split() if len(p) < 14: continue dev = p[2] # field 10 (idx 9) = sectors written; field 13 (idx 12) = ms doing I/O out[dev] = (int(p[9]), int(p[12])) except (OSError, AttributeError): pass return out # These counters tell us WHICH kernel mechanism caused a stall, which decides # the fix: compact_stall jumping -> memory compaction (texture-pool fix); # allocstall/pgsteal jumping -> direct reclaim; high nr_dirty/nr_writeback -> # loggerd writeback bomb (loggerd sync_file_range fix). meminfo Dirty/Writeback # are absolute kB; vmstat ones are cumulative event counts (we delta them). VMSTAT_KEYS = ("compact_stall", "compact_fail", "allocstall_normal", "allocstall_movable", "pgsteal_direct", "pgscan_direct", "pgmajfault", "nr_dirty", "nr_writeback") MEMINFO_KEYS = ("MemFree", "MemAvailable", "Dirty", "Writeback") def read_vmstat(): out = {} try: with open("/proc/vmstat") as f: for line in f: k, _, v = line.partition(" ") if k in VMSTAT_KEYS: out[k] = int(v) except OSError: pass return out def read_meminfo(): out = {} try: with open("/proc/meminfo") as f: for line in f: k, _, v = line.partition(":") if k in MEMINFO_KEYS: out[k] = int(v.split()[0]) # kB except (OSError, IndexError): pass return out def main(): ap = argparse.ArgumentParser() ap.add_argument("--out", default="/data/media/0/io_trace.csv") ap.add_argument("--hz", type=float, default=10.0, help="sample rate (default 10Hz/100ms)") ap.add_argument("--disk", default="sda", help="comma-separated disk devices to track (default sda)") ap.add_argument("--names", default="controlsd,car.c,selfd,ui,loggerd,encoderd,modeld,camerad,locationd,paramsd,navd,mapd", help="substring match of process comm to record (others summed as 'other')") args = ap.parse_args() # be a good citizen: low priority, off the control cores try: os.nice(10) os.sched_setaffinity(0, {0}) except OSError: pass watch = [n.strip() for n in args.names.split(",") if n.strip()] disks = [d.strip() for d in args.disk.split(",") if d.strip()] interval = 1.0 / args.hz prev_io = {} # pid -> (wchar, rchar, write_bytes, read_bytes) prev_blkio = {} # pid -> blkio_ticks prev_disk = read_diskstats() prev_vm = read_vmstat() f = open(args.out, "w", buffering=1) # per-proc rows fill the first block; one SYS row per tick fills the trailing # mechanism columns (deltas for the vmstat counts, absolute kB for meminfo). f.write("wall,mono,proc,pid,state,d_wchar_kB,d_wbytes_kB,d_blkio_ms,disk_d_write_kB,disk_d_busy_ms," "compact_stall,allocstall,pgmajfault,dirty_kB,writeback_kB,memfree_kB,memavail_kB\n") print(f"[io_stall_tracer] writing {args.out} at {args.hz}Hz, tracking {watch}", file=sys.stderr) while True: t_wall = time.time() t_mono = time.monotonic() # whole-disk delta (write kB + busy ms) for the named disks disk = read_diskstats() disk_dw = disk_db = 0 for dev in disks: if dev in disk and dev in prev_disk: disk_dw += (disk[dev][0] - prev_disk[dev][0]) * 512 / 1024.0 # sectors->kB disk_db += (disk[dev][1] - prev_disk[dev][1]) prev_disk = disk seen = set() rows = [] for path in glob.glob("/proc/[0-9]*"): pid = path.rsplit("/", 1)[1] st = read_proc_stat(pid) if st is None: continue comm, state, blkio = st label = next((w for w in watch if w in comm), None) if label is None: # still track D-state of anything to catch surprise writers/blockers if state != "D": continue label = comm io = read_proc_io(pid) if io is None: continue wchar, rchar, wbytes, rbytes = io pw = prev_io.get(pid, io) pblk = prev_blkio.get(pid, blkio) d_wchar = (wchar - pw[0]) / 1024.0 # syscall write volume (catches loggerd) d_wbytes = (wbytes - pw[2]) / 1024.0 # bytes hitting the block device d_blk = (blkio - pblk) * (1000.0 / CLK_TCK) # ticks -> ms blocked on block I/O prev_io[pid] = io prev_blkio[pid] = blkio seen.add(pid) # only emit rows that carry signal (writing, blocked, or in D) to keep file small if d_wchar > 4 or d_wbytes > 4 or d_blk > 5 or state == "D": rows.append((label, pid, state, d_wchar, d_wbytes, d_blk)) # drop dead pids from prev maps occasionally if len(prev_io) > 4000: prev_io = {p: v for p, v in prev_io.items() if p in seen} prev_blkio = {p: v for p, v in prev_blkio.items() if p in seen} for label, pid, state, d_wchar, d_wbytes, d_blk in rows: f.write(f"{t_wall:.3f},{t_mono:.3f},{label},{pid},{state},{d_wchar:.0f},{d_wbytes:.0f},{d_blk:.0f},{disk_dw:.0f},{disk_db:.0f},,,,,,,\n") # one SYS row per tick: the kernel-mechanism counters (compaction vs reclaim # vs writeback). Compare these against the stall's wall-clock to see which # one spiked. vm = read_vmstat(); mi = read_meminfo() d_compact = vm.get("compact_stall", 0) - prev_vm.get("compact_stall", 0) d_alloc = ((vm.get("allocstall_normal", 0) + vm.get("allocstall_movable", 0)) - (prev_vm.get("allocstall_normal", 0) + prev_vm.get("allocstall_movable", 0))) d_majflt = vm.get("pgmajfault", 0) - prev_vm.get("pgmajfault", 0) prev_vm = vm f.write(f"{t_wall:.3f},{t_mono:.3f},SYS,0,-,,,,,," f"{d_compact},{d_alloc},{d_majflt},{mi.get('Dirty',0)},{mi.get('Writeback',0)}," f"{mi.get('MemFree',0)},{mi.get('MemAvailable',0)}\n") time.sleep(max(0.0, interval - (time.monotonic() - t_mono))) if __name__ == "__main__": main()