From 27171ec4dc04481b2a15743416e4643e9ff76ff4 Mon Sep 17 00:00:00 2001 From: Luna Date: Wed, 20 May 2026 09:10:17 -0700 Subject: [PATCH] 0.5.0: storm detection, device IO digest, new classifiers, PSI io full graph MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit daemon: - storm detection: after 8 captures in 5min, logs STORM STARTED/ENDED to events.log with duration and capture count; uses longer cooldown (90s) during storms to reduce log spam while still capturing periodically - new capture_device_io_digest(): human-readable table of hot devices with volume label, %util, r_await, w_await, nr_requests — makes USB vs SATA and dm-crypt queue depth problems immediately visible - new ## Block device map section (lsblk) in every snapshot - new classifiers: dm-crypt request pool exhausted (crypt_alloc_buffer + blk_mq_get_tag pattern), block MQ tag starvation, container/Waydroid CPU spike (lxc cgroup PSI); USB stall now names the hot volumes - events.log lines now include the first classifier diagnosis in brackets - CAPTURE_DEVICE_IO config option (default 1) gui: - PSI io full % metric tile and live graph (more severe than io.some) - storm indicator in status bar showing duration and capture count - storm events parsed from events.log and shown inline in Snapshots list (orange, ⚡ prefix), interleaved by timestamp with snapshot entries - clicking a storm item shows its details in the detail pane - orange vertical markers on graphs for storm-start events - Summary tab opens with storm history section (count, avg/max duration, captures per storm, last 5 storms) Co-Authored-By: Claude Sonnet 4.6 --- src/freeze-monitor-gui | 319 ++++++++++++++++++++++++++++++++--------- src/freeze-watcher.sh | 222 +++++++++++++++++++++++----- 2 files changed, 434 insertions(+), 107 deletions(-) diff --git a/src/freeze-monitor-gui b/src/freeze-monitor-gui index e28c2ff..e3ae644 100755 --- a/src/freeze-monitor-gui +++ b/src/freeze-monitor-gui @@ -11,7 +11,7 @@ import re import subprocess import sys from collections import Counter, deque -from datetime import datetime +from datetime import datetime, timedelta from pathlib import Path from PySide6.QtCore import Qt, QTimer, QPointF, Signal @@ -34,13 +34,25 @@ GRAPH_UPDATE_MS = 1000 def read_psi(name): try: - line = (Path("/proc/pressure") / name).read_text().splitlines()[0] - m = re.search(r"avg10=([\d.]+)", line) + text = (Path("/proc/pressure") / name).read_text() + m = re.search(r"avg10=([\d.]+)", text.splitlines()[0]) return float(m.group(1)) if m else 0.0 except Exception: return 0.0 +def read_psi_full(name): + """Read the 'full' row avg10 instead of 'some'.""" + try: + for line in (Path("/proc/pressure") / name).read_text().splitlines(): + if line.startswith("full"): + m = re.search(r"avg10=([\d.]+)", line) + return float(m.group(1)) if m else 0.0 + except Exception: + pass + return 0.0 + + def read_dstate_count(): try: out = subprocess.run( @@ -74,6 +86,50 @@ def service_active(): return r.stdout.strip() == "active" +def parse_events_log(): + """Parse events.log and return a list of storm dicts with start/end info.""" + storms = [] + current = None + try: + for line in (LOG_DIR / "events.log").read_text(errors="replace").splitlines(): + m = re.match(r"^(\S+) STORM STARTED: (\d+) captures in (\d+)s \(trigger: (.+)\)$", line) + if m: + current = { + "type": "storm", + "start_str": m.group(1), + "count_at_start": int(m.group(2)), + "window": int(m.group(3)), + "trigger": m.group(4), + "end_str": None, + "duration": None, + "total_captures": None, + } + try: + current["start_ts"] = datetime.fromisoformat(m.group(1)).replace(tzinfo=None) + except Exception: + current["start_ts"] = None + continue + m = re.match(r"^(\S+) STORM ENDED: duration=(\d+)s, captures=(\d+)$", line) + if m and current: + current["end_str"] = m.group(1) + current["duration"] = int(m.group(2)) + current["total_captures"] = int(m.group(3)) + try: + current["end_ts"] = datetime.fromisoformat(m.group(1)).replace(tzinfo=None) + except Exception: + current["end_ts"] = None + storms.append(current) + current = None + # Storm without an end (still ongoing) + if current: + current["end_str"] = None + current["end_ts"] = None + storms.append(current) + except Exception: + pass + return storms + + # ----------------------------------------------------------------- widgets class MetricLabel(QLabel): @@ -114,21 +170,26 @@ class LineGraph(QWidget): self.warn = warn self.crit = crit self.values = deque(maxlen=HISTORY_SECONDS) - self.markers = set() # indices to mark as snapshot events + self.markers = set() # indices of regular snapshot captures + self.storm_markers = set() # indices of storm-start events self.setMinimumHeight(110) self.setSizePolicy(QSizePolicy.Expanding, QSizePolicy.Preferred) - def push(self, value, marker=False): + def push(self, value, marker=False, storm_marker=False): self.values.append(value) + idx = len(self.values) - 1 if marker: - self.markers.add(len(self.values) - 1) - # Decay markers as values shift out - new_markers = set() - for m in self.markers: - shifted = m - 1 if len(self.values) == HISTORY_SECONDS else m - if shifted >= 0: - new_markers.add(shifted) - self.markers = new_markers + self.markers.add(idx) + if storm_marker: + self.storm_markers.add(idx) + # Decay markers as values shift out of the deque + for attr in ("markers", "storm_markers"): + new = set() + for m in getattr(self, attr): + shifted = m - 1 if len(self.values) == HISTORY_SECONDS else m + if shifted >= 0: + new.add(shifted) + setattr(self, attr, new) self.update() def paintEvent(self, _): @@ -136,7 +197,6 @@ class LineGraph(QWidget): p.setRenderHint(QPainter.Antialiasing) w, h = self.width(), self.height() - # Background p.fillRect(0, 0, w, h, QColor("#1a1a1a")) if not self.values: @@ -148,13 +208,11 @@ class LineGraph(QWidget): min_v = 0 rng = max_v - min_v - # Title and current value p.setPen(QColor("#aaa")) p.setFont(QFont("monospace", 9)) current = self.values[-1] p.drawText(8, 16, f"{self.label} current={current:.1f} max={max(self.values):.1f}") - # Threshold lines plot_top = 24 plot_bot = h - 8 plot_h = plot_bot - plot_top @@ -165,11 +223,10 @@ class LineGraph(QWidget): p.setPen(QPen(QColor(col), 1, Qt.DashLine)) p.drawLine(0, int(y), w, int(y)) - # Line n = len(self.values) if n < 2: return - step = w / (n - 1) if n > 1 else 0 + step = w / (n - 1) poly = QPolygonF() for i, v in enumerate(self.values): x = i * step @@ -178,12 +235,18 @@ class LineGraph(QWidget): p.setPen(QPen(self.color, 1.5)) p.drawPolyline(poly) - # Markers (snapshot captures) + # Regular snapshot markers (red dotted) p.setPen(QPen(QColor("#ff5555"), 1, Qt.DotLine)) for m in self.markers: x = m * step p.drawLine(int(x), plot_top, int(x), plot_bot) + # Storm markers (orange solid, thicker) + p.setPen(QPen(QColor("#f5a623"), 2, Qt.SolidLine)) + for m in self.storm_markers: + x = m * step + p.drawLine(int(x), plot_top, int(x), plot_bot) + # ----------------------------------------------------------------- snapshot parsing @@ -252,6 +315,10 @@ class FreezeMonitor(QMainWindow): self.status_label = QLabel() self.status_label.setStyleSheet("padding:6px; font-weight:bold;") status_row.addWidget(self.status_label) + self.storm_label = QLabel() + self.storm_label.setStyleSheet("padding:6px; font-weight:bold; color:#f5a623;") + self.storm_label.hide() + status_row.addWidget(self.storm_label) status_row.addStretch() self.btn_capture_now = QPushButton("📸 Capture Now") self.btn_capture_now.setToolTip("Manually trigger a snapshot capture") @@ -268,7 +335,7 @@ class FreezeMonitor(QMainWindow): # Live metrics row metrics_box = QGroupBox("Live metrics (1s refresh)") grid = QGridLayout(metrics_box) - labels = ["PSI IO %", "PSI CPU %", "PSI Mem %", "D-state", "Blocked", "Load (1m)"] + labels = ["PSI IO %", "PSI IO full %", "PSI CPU %", "PSI Mem %", "D-state", "Blocked", "Load (1m)"] self.metrics = {} for i, name in enumerate(labels): grid.addWidget(QLabel(name, alignment=Qt.AlignCenter), 0, i) @@ -286,7 +353,8 @@ class FreezeMonitor(QMainWindow): self._build_summary_tab() self._known_events = set() - self._all_snapshots = [] # cached parses + self._all_snapshots = [] + self._storms = [] # Tray self.tray = QSystemTrayIcon(self.style().standardIcon(QStyle.SP_ComputerIcon), self) @@ -306,7 +374,6 @@ class FreezeMonitor(QMainWindow): self.tray.activated.connect(self._tray_clicked) self.tray.show() - # Tick timer self.timer = QTimer() self.timer.timeout.connect(self.tick) self.timer.start(GRAPH_UPDATE_MS) @@ -318,12 +385,14 @@ class FreezeMonitor(QMainWindow): def _build_graphs_tab(self): tab = QWidget() v = QVBoxLayout(tab) - v.addWidget(QLabel("Last hour — red dashed lines mark snapshot captures")) - self.graph_load = LineGraph("Load (1m)", "#5cdb95", warn=8, crit=16) - self.graph_psi_io = LineGraph("PSI io.some %", "#88ccff", warn=30, crit=60) - self.graph_psi_cpu = LineGraph("PSI cpu.some %", "#ffcc66", warn=30, crit=60) - self.graph_dstate = LineGraph("D-state procs", "#ff8888", warn=3, crit=6) - for g in (self.graph_load, self.graph_psi_io, self.graph_psi_cpu, self.graph_dstate): + v.addWidget(QLabel("Last hour — red dashed = snapshot capture, orange = storm start")) + self.graph_load = LineGraph("Load (1m)", "#5cdb95", warn=8, crit=16) + self.graph_psi_io = LineGraph("PSI io.some %", "#88ccff", warn=30, crit=60) + self.graph_psi_iof = LineGraph("PSI io.full %", "#5599ff", warn=15, crit=40) + self.graph_psi_cpu = LineGraph("PSI cpu.some %", "#ffcc66", warn=30, crit=60) + self.graph_dstate = LineGraph("D-state procs", "#ff8888", warn=3, crit=6) + for g in (self.graph_load, self.graph_psi_io, self.graph_psi_iof, + self.graph_psi_cpu, self.graph_dstate): v.addWidget(g) self.tabs.addTab(tab, "Live graphs") @@ -334,7 +403,7 @@ class FreezeMonitor(QMainWindow): filter_row = QHBoxLayout() filter_row.addWidget(QLabel("Filter:")) self.filter_edit = QLineEdit() - self.filter_edit.setPlaceholderText("substring match against reason/diagnosis (e.g. btrfs, dstate, usb)") + self.filter_edit.setPlaceholderText("substring match against reason/diagnosis (e.g. btrfs, dstate, usb, storm)") self.filter_edit.textChanged.connect(self._apply_filter) filter_row.addWidget(self.filter_edit) self.btn_refresh = QPushButton("Refresh") @@ -415,19 +484,21 @@ class FreezeMonitor(QMainWindow): # ---- tick def tick(self): - psi_io = read_psi("io") - psi_cpu = read_psi("cpu") - psi_mem = read_psi("memory") - dstate = read_dstate_count() - blocked = read_procs_blocked() - load = read_loadavg() + psi_io = read_psi("io") + psi_io_f = read_psi_full("io") + psi_cpu = read_psi("cpu") + psi_mem = read_psi("memory") + dstate = read_dstate_count() + blocked = read_procs_blocked() + load = read_loadavg() - self.metrics["PSI IO %"].set_value(int(psi_io), 30, 60, "") - self.metrics["PSI CPU %"].set_value(int(psi_cpu), 30, 60, "") - self.metrics["PSI Mem %"].set_value(int(psi_mem), 20, 50, "") - self.metrics["D-state"].set_value(dstate, 3, 6, "") - self.metrics["Blocked"].set_value(blocked, 3, 6, "") - self.metrics["Load (1m)"].set_value(int(load), 8, 16, "") + self.metrics["PSI IO %"].set_value(int(psi_io), 30, 60) + self.metrics["PSI IO full %"].set_value(int(psi_io_f), 15, 40) + self.metrics["PSI CPU %"].set_value(int(psi_cpu), 30, 60) + self.metrics["PSI Mem %"].set_value(int(psi_mem), 20, 50) + self.metrics["D-state"].set_value(dstate, 3, 6) + self.metrics["Blocked"].set_value(blocked, 3, 6) + self.metrics["Load (1m)"].set_value(int(load), 8, 16) active = service_active() if active: @@ -437,23 +508,43 @@ class FreezeMonitor(QMainWindow): self.status_label.setText("● Service: STOPPED") self.status_label.setStyleSheet("padding:6px; font-weight:bold; color:#ff5555;") + # Storm indicator + storms = parse_events_log() + active_storm = next((s for s in reversed(storms) if s.get("end_str") is None), None) + if active_storm: + start_ts = active_storm.get("start_ts") + dur_str = "" + if start_ts: + dur = int((datetime.now() - start_ts).total_seconds()) + dur_str = f" — {dur//60}m{dur%60:02d}s" + self.storm_label.setText(f"⚡ STORM IN PROGRESS{dur_str} ({active_storm['total_captures'] or active_storm['count_at_start']} captures)") + self.storm_label.show() + else: + self.storm_label.hide() + self.tray.setToolTip( f"Freeze Watcher — {'active' if active else 'stopped'}\n" - f"PSI io {int(psi_io)}% / cpu {int(psi_cpu)}% — D:{dstate} blk:{blocked} load:{load:.2f}" + f"PSI io {int(psi_io)}%/{int(psi_io_f)}%full cpu {int(psi_cpu)}% — D:{dstate} blk:{blocked} load:{load:.2f}" ) - # Detect new snapshot files for graph markers current = set(p.name for p in LOG_DIR.glob("snap-*.log")) if LOG_DIR.exists() else set() new = current - self._known_events + + # Check if any new storm events occurred since last tick + new_storm = len(storms) > len(self._storms) + self._storms = storms + is_marker = bool(new) - self.graph_load.push(load, marker=is_marker) - self.graph_psi_io.push(psi_io, marker=is_marker) - self.graph_psi_cpu.push(psi_cpu, marker=is_marker) - self.graph_dstate.push(dstate, marker=is_marker) + is_storm_marker = new_storm and bool(active_storm) + self.graph_load.push(load, marker=is_marker, storm_marker=is_storm_marker) + self.graph_psi_io.push(psi_io, marker=is_marker, storm_marker=is_storm_marker) + self.graph_psi_iof.push(psi_io_f, marker=is_marker, storm_marker=is_storm_marker) + self.graph_psi_cpu.push(psi_cpu, marker=is_marker, storm_marker=is_storm_marker) + self.graph_dstate.push(dstate, marker=is_marker, storm_marker=is_storm_marker) if current != self._known_events: self._known_events = current - self._all_snapshots = [] # invalidate cache + self._all_snapshots = [] self.load_events() for n in new: self.tray.showMessage( @@ -474,29 +565,89 @@ class FreezeMonitor(QMainWindow): self._all_snapshots = [parse_snapshot(p) for p in files] self._all_snapshots = [s for s in self._all_snapshots if s] self._known_events = set(p.name for p in files) + self._storms = parse_events_log() self._apply_filter() def _apply_filter(self): needle = self.filter_edit.text().lower().strip() self.event_list.clear() + + # Interleave storm events into the snapshot list by time + snap_items = [] for info in self._all_snapshots: + ts = datetime.fromtimestamp(info["mtime"]) text_blob = (info["reason"] + " " + " ".join(info["diagnoses"])).lower() - if needle and needle not in text_blob: + if needle and needle not in text_blob and "storm" not in needle: continue - ts = datetime.fromtimestamp(info["mtime"]).strftime("%Y-%m-%d %H:%M:%S") - diag_short = info["diagnoses"][0][:80] if info["diagnoses"] else "" - label = f"{ts}\n reason: {info['reason']}" - if diag_short: - label += f"\n → {diag_short}" - item = QListWidgetItem(label) - item.setData(Qt.UserRole, info["path"]) - self.event_list.addItem(item) + snap_items.append(("snap", ts, info)) + + storm_items = [] + for s in self._storms: + ts = s.get("start_ts") or datetime.now() + text_blob = f"storm {s['trigger']}".lower() + if needle and needle not in text_blob and needle not in "storm": + continue + storm_items.append(("storm", ts, s)) + + # Merge by timestamp descending + all_items = sorted(snap_items + storm_items, key=lambda x: x[1], reverse=True) + + for kind, ts, data in all_items: + if kind == "storm": + s = data + dur = f"{s['duration']}s" if s.get("duration") else "ongoing" + n = s.get("total_captures") or s.get("count_at_start", "?") + label = (f"⚡ STORM {ts.strftime('%Y-%m-%d %H:%M:%S')}\n" + f" {n} captures, {dur}, trigger: {s['trigger'][:60]}") + item = QListWidgetItem(label) + item.setData(Qt.UserRole, None) + item.setData(Qt.UserRole + 1, "storm") + item.setForeground(QColor("#f5a623")) + self.event_list.addItem(item) + else: + info = data + ts_str = ts.strftime("%Y-%m-%d %H:%M:%S") + diag_short = info["diagnoses"][0][:80] if info["diagnoses"] else "" + label = f"{ts_str}\n reason: {info['reason']}" + if diag_short: + label += f"\n → {diag_short}" + item = QListWidgetItem(label) + item.setData(Qt.UserRole, info["path"]) + item.setData(Qt.UserRole + 1, "snap") + self.event_list.addItem(item) def show_selected(self): items = self.event_list.selectedItems() if not items: return - path = Path(items[0].data(Qt.UserRole)) + kind = items[0].data(Qt.UserRole + 1) + if kind == "storm": + s_data = None + # Find this storm from its label + label = items[0].text() + ts_str = label.split("\n")[0].replace("⚡ STORM ", "").strip() + for s in self._storms: + if s.get("start_ts") and s["start_ts"].strftime("%Y-%m-%d %H:%M:%S") == ts_str: + s_data = s + break + if s_data: + dur = f"{s_data['duration']}s" if s_data.get("duration") else "ongoing" + n = s_data.get("total_captures") or s_data.get("count_at_start", "?") + text = ( + f"STORM EVENT\n" + f"{'─'*60}\n" + f"Started: {s_data['start_str']}\n" + f"Ended: {s_data.get('end_str') or '(ongoing)'}\n" + f"Duration: {dur}\n" + f"Captures: {n}\n" + f"Trigger: {s_data['trigger']}\n" + ) + self.detail.setPlainText(text) + return + path = items[0].data(Qt.UserRole) + if not path: + return + path = Path(path) try: text = path.read_text() html_sidecar = path.with_suffix(".html") @@ -519,10 +670,12 @@ class FreezeMonitor(QMainWindow): QMessageBox.information(self, "Select a snapshot", "Pick a snapshot from the list first.") return - path = Path(items[0].data(Qt.UserRole)) + path = items[0].data(Qt.UserRole) + if not path: + return + path = Path(path) html = path.with_suffix(".html") if not html.exists(): - # Try generating on demand try: subprocess.run(["freeze-snapshot-convert", "--html", str(path)], check=True, capture_output=True) @@ -556,17 +709,45 @@ class FreezeMonitor(QMainWindow): if not self._all_snapshots: self.load_events() snaps = self._all_snapshots + storms = self._storms + + out = [] + + # Storm summary + if storms: + completed = [s for s in storms if s.get("duration") is not None] + ongoing = [s for s in storms if s.get("duration") is None] + out.append("─── Storm history ───────────────────────────────────────") + out.append(f" Total storms recorded: {len(storms)}") + if completed: + durations = [s["duration"] for s in completed] + captures = [s["total_captures"] for s in completed if s.get("total_captures")] + out.append(f" Completed: {len(completed)} avg duration: {sum(durations)//len(durations)}s " + f"max: {max(durations)}s") + if captures: + out.append(f" Captures per storm: avg {sum(captures)//len(captures)} max {max(captures)}") + if ongoing: + out.append(f" Currently active: {len(ongoing)} storm(s)") + out.append("") + out.append(" Recent storms:") + for s in storms[-5:]: + dur = f"{s['duration']}s" if s.get("duration") else "ongoing" + n = s.get("total_captures") or s.get("count_at_start", "?") + out.append(f" {s['start_str'][:19]} {n} captures {dur} trigger: {s['trigger'][:50]}") + out.append("") + if not snaps: - self.summary_text.setPlainText("No snapshots captured yet.") + out.append("No snapshots captured yet.") + self.summary_text.setPlainText("\n".join(out)) return - wchans = Counter() - procs = Counter() + wchans = Counter() + procs = Counter() top_cpu = Counter() diagnoses = Counter() - hours = Counter() - first = None - last = None + hours = Counter() + first = None + last = None for s in snaps: for w in s["wchans"]: wchans[w] += 1 @@ -575,13 +756,12 @@ class FreezeMonitor(QMainWindow): if s["top_cpu_proc"]: top_cpu[s["top_cpu_proc"]] += 1 for d in s["diagnoses"]: - # First clause only, before " — " key = d.split("—")[0].strip()[:60] diagnoses[key] += 1 ts = datetime.fromtimestamp(s["mtime"]) hours[ts.hour] += 1 first = min(first, ts) if first else ts - last = max(last, ts) if last else ts + last = max(last, ts) if last else ts def topn(ctr, n=10): total = sum(ctr.values()) or 1 @@ -595,10 +775,9 @@ class FreezeMonitor(QMainWindow): hour_dist = [] for h in range(24): count = hours.get(h, 0) - bar = "▇" * count + bar = "▇" * min(count, 40) hour_dist.append(f" {h:02d}:00 {bar} {count}") - out = [] out.append(f"Snapshots analyzed: {len(snaps)}") if first and last: out.append(f"Time range: {first} → {last}") diff --git a/src/freeze-watcher.sh b/src/freeze-watcher.sh index 94b8fbf..1109900 100755 --- a/src/freeze-watcher.sh +++ b/src/freeze-watcher.sh @@ -15,6 +15,9 @@ DSTATE_THRESHOLD=5 BLOCKED_THRESHOLD=5 LOAD_THRESHOLD=20 COOLDOWN=30 +STORM_THRESHOLD=8 # captures within STORM_WINDOW before declaring a storm +STORM_WINDOW=300 # seconds; how far back to count captures for storm detection +STORM_COOLDOWN=90 # cooldown to use during an active storm (vs COOLDOWN) SAMPLE_INTERVAL=1 MAX_SNAPSHOTS=200 MAX_SNAPSHOT_AGE_DAYS=30 @@ -23,6 +26,7 @@ NOTIFY_URGENCY=normal CAPTURE_KERNEL_STACKS=1 CAPTURE_BPFTRACE=0 CAPTURE_CGROUP_PSI=1 +CAPTURE_DEVICE_IO=1 # include hot-device IO digest (device labels, await, nr_requests) OUTPUT_JSON=0 OUTPUT_HTML=0 @@ -33,6 +37,13 @@ mkdir -p "$LOG_DIR" last_capture=0 captures_since_prune=0 +# Storm tracking +in_storm=0 +storm_count=0 +storm_window_start=0 +storm_start_time=0 +last_trigger_time=0 + notify_users() { [ -z "$NOTIFY_USERS" ] && return 0 local body="$1" @@ -110,8 +121,65 @@ capture_bpftrace() { ' 2>/dev/null | tail -40 } +# Human-readable summary of hot block devices with volume labels, await times, +# and nr_requests. Makes it immediately clear which volume is under pressure. +capture_device_io_digest() { + echo "## Hot device IO digest (>10% util)" + + # Build label map from lsblk (covers dm and physical devices) + declare -A label_map + while IFS= read -r line; do + local dev lbl + dev=${line%% *} + lbl=${line#* } + lbl=${lbl## } + [ -n "$dev" ] && [ -n "$lbl" ] && label_map["$dev"]="$lbl" + done < <(lsblk -o NAME,LABEL -rn 2>/dev/null | awk 'NF>=2') + + # nr_requests for sd* (USB bridges typically nr_req=2, SATA gets 64+) + declare -A nr_map + for f in /sys/block/sd*/queue/nr_requests; do + [ -r "$f" ] || continue + local dev nr + dev=$(echo "$f" | cut -d/ -f4) + nr=$(cat "$f" 2>/dev/null) + [ -n "$nr" ] && nr_map["$dev"]="$nr" + done + + # Parse iostat using column headers so it's robust across versions + local raw + raw=$(iostat -dx 1 1 2>/dev/null | awk ' + /^Device/ { + for (i=1; i<=NF; i++) col[$i]=i + p=1; next + } + p && NF>5 { + u = col["%util"] ? $col["%util"]+0 : 0 + if (u < 10) next + r = col["r_await"] ? $col["r_await"] : 0 + w = col["w_await"] ? $col["w_await"] : 0 + a = col["aqu-sz"] ? $col["aqu-sz"] : 0 + printf "%s\t%.1f\t%s\t%s\t%s\n", $1, u, r, w, a + } + ' | sort -t$'\t' -k2 -rn) + + if [ -z "$raw" ]; then + echo " (no devices above 10% utilization)" + return + fi + + printf " %-10s %-22s %6s %8s %8s %6s\n" \ + Device "Volume/Label" "%util" "r_await" "w_await" "nr_req" + while IFS=$'\t' read -r dev util r_await w_await aqu; do + local lbl="${label_map[$dev]:-}" + local nr="${nr_map[$dev]:-}" + [ -z "$nr" ] && [[ "$dev" == nvme* ]] && nr="(nvme)" + printf " %-10s %-22s %5s%% %7sms %7sms %6s\n" \ + "$dev" "${lbl:0:22}" "$util" "$r_await" "$w_await" "${nr:-(n/a)}" + done <<< "$raw" +} + # Reads a snapshot file and emits one or more diagnosis lines. -# Pattern-matches D-state wchans and PSI metrics against known freeze types. classify_snapshot() { local file="$1" local diagnoses=() @@ -130,7 +198,33 @@ classify_snapshot() { local dcount dcount=$(echo "$dstate_section" | grep -c "^D ") - # btrfs lock contention + # --- dm-crypt request pool exhaustion --- + # Multiple kcryptd workers stuck in crypt_alloc_buffer, often with blk_mq_get_tag + # on the dmcrypt_write threads. Root cause: nr_requests=2 on USB-to-SATA bridges + # under concurrent IO load exhausts all block MQ slots. + if echo "$dstate_section" | grep -q "crypt_alloc_buffer"; then + local n_crypt + n_crypt=$(echo "$dstate_section" | grep -c "crypt_alloc_buffer") + if echo "$dstate_section" | grep -q "blk_mq_get_tag"; then + local hot_devs + hot_devs=$(awk '/^## Hot device IO digest/{flag=1;next} /^## /{flag=0} flag && /dm-/{print $1}' "$file" 2>/dev/null | head -3 | tr '\n' ' ') + local dev_hint="" + [ -n "$hot_devs" ] && dev_hint=" (hot: ${hot_devs% })" + diagnoses+=("dm-crypt request pool exhausted — ${n_crypt} kcryptd workers blocked${dev_hint}; backing device nr_requests too low for concurrent IO; increase nr_requests or limit parallel readers") + else + diagnoses+=("dm-crypt encryption pool stall — ${n_crypt} kcryptd workers waiting for memory; encryption CPU/memory bound") + fi + fi + + # --- block MQ tag starvation (non-crypt) --- + if echo "$dstate_section" | grep -q "blk_mq_get_tag" && \ + ! echo "$dstate_section" | grep -q "crypt_alloc_buffer"; then + local n_blkmq + n_blkmq=$(echo "$dstate_section" | grep -c "blk_mq_get_tag") + diagnoses+=("block MQ request tags exhausted — ${n_blkmq} processes waiting for IO slots; device nr_requests too low for this workload") + fi + + # --- btrfs lock contention --- if echo "$dstate_section" | grep -qE "btrfs_lock_root_node|btrfs_sync_log"; then if [ "${psi_io_some:-0}" -lt 10 ]; then diagnoses+=("btrfs metadata lock contention — wchans show btrfs_lock_root_node/sync_log with low PSI io. Typical of qgroups + many snapshots, or heavy fsync churn.") @@ -139,18 +233,26 @@ classify_snapshot() { fi fi - # btrfs metadata pressure (less severe) + # --- btrfs metadata pressure --- if echo "$dstate_section" | grep -q "btrfs_search_slot" && \ - ! echo "$dstate_section" | grep -q "btrfs_lock_root_node"; then + ! echo "$dstate_section" | grep -q "btrfs_lock_root_node" && \ + ! echo "$dstate_section" | grep -q "crypt_alloc_buffer"; then diagnoses+=("btrfs metadata pressure — cleaner walking trees, fsyncs queueing") fi - # USB stall + # --- USB stall --- if echo "$dstate_section" | grep -qE "usb_sg_wait|scsi_eh|sd_check_events|usb_hcd"; then - diagnoses+=("USB storage stall — one external drive responding slowly") + local n_usb + n_usb=$(echo "$dstate_section" | grep -cE "usb_sg_wait|scsi_eh|sd_check_events|usb_hcd") + local hot_vol + hot_vol=$(awk '/^## Hot device IO digest/{flag=1;next} /^## /{flag=0} flag && /%/{print $2}' "$file" 2>/dev/null \ + | grep -v "Volume\|---\|^$" | head -2 | tr '\n' ',' | sed 's/,$//') + local vol_hint="" + [ -n "$hot_vol" ] && vol_hint=" (hot volumes: $hot_vol)" + diagnoses+=("USB storage stall — ${n_usb} usb-storage threads unresponsive${vol_hint}; check SMART and USB hub bandwidth sharing") fi - # Memory swap thrash + # --- memory swap thrash --- if echo "$dstate_section" | grep -q "folio_wait_bit_common"; then if [ "${psi_mem_some:-0}" -gt 5 ]; then diagnoses+=("memory pressure / swap thrash — folio_wait + PSI mem ${psi_mem_some}%") @@ -159,15 +261,19 @@ classify_snapshot() { fi fi - # CPU oversubscription - if [ "${psi_cpu_some:-0}" -gt 30 ] && [ "$dcount" -lt 3 ]; then + # --- container/Waydroid startup CPU spike --- + local lxc_cpu_psi + lxc_cpu_psi=$(awk '/^## Top cgroups by PSI cpu/{flag=1;next} /^## /{flag=0} flag && /lxc/{print $1+0; exit}' "$file" 2>/dev/null) + if [ "${lxc_cpu_psi:-0}" -gt 20 ] && [ "${psi_cpu_some:-0}" -gt 20 ]; then + diagnoses+=("container/Waydroid CPU spike — lxc cgroup at ${lxc_cpu_psi}% CPU PSI; Android container startup or heavy in-container workload") + fi + + # --- CPU oversubscription --- + if [ "${psi_cpu_some:-0}" -gt 30 ] && [ "$dcount" -lt 3 ] && [ "${lxc_cpu_psi:-0}" -le 20 ]; then diagnoses+=("CPU oversubscription — PSI cpu ${psi_cpu_some}%, few D-state procs. Heavy compile, transcoding, or runaway process competing for cores.") fi - # NIC IRQ saturation — use delta against the running baseline so old - # cumulative skew doesn't trigger forever. - # With RPS enabled, per-flow concentration on one CPU is normal up to ~85%. - # Only flag when no RPS spreading is happening at all, or it's truly extreme. + # --- NIC IRQ saturation --- if [ -r "$LOG_DIR/.softirq-baseline" ] && [ -n "$(echo "$softirq" | grep '^ *NET_RX:')" ]; then local cur prev cur=$(echo "$softirq" | grep '^ *NET_RX:' | sed 's/^ *NET_RX://') @@ -187,13 +293,11 @@ classify_snapshot() { done if [ "$total" -gt 100000 ]; then local pct=$((max * 100 / total)) - # Check if RPS is configured (any non-zero, non-single-bit value) local rps_active=0 for rps in /sys/class/net/*/queues/rx-0/rps_cpus; do [ -r "$rps" ] || continue local v v=$(cat "$rps" 2>/dev/null | tr -d ',') - # Strip leading zeros, count hex bits set [ "$v" != "0" ] && [ "$v" != "00" ] && [ "$v" != "000" ] \ && [ "$v" != "0000" ] && rps_active=1 done @@ -206,7 +310,7 @@ classify_snapshot() { fi fi - # Genuine I/O bottleneck + # --- genuine I/O bottleneck --- if [ "${psi_io_full:-0}" -gt 30 ]; then diagnoses+=("genuine I/O bottleneck — PSI io full ${psi_io_full}%, device truly can't keep up") fi @@ -225,8 +329,7 @@ capture_snapshot() { local body="$LOG_DIR/.snap-body-$$.tmp" local final="$LOG_DIR/snap-$(date +%Y%m%d-%H%M%S).log" - # CAPTURE D-STATE FIRST - blocked spikes are often <1s long, so we need - # to grab process state before reading slower /proc/* files + # Capture D-state first — spikes can be <1s, grab before slower /proc reads local dstate_immediate dstate_immediate=$(ps -eo state,pid,user,wchan:25,comm,args --no-headers 2>/dev/null | awk '$1=="D"' | head -30) local dstate_t1 @@ -253,8 +356,6 @@ capture_snapshot() { echo fi echo "## D-state processes (with kernel wchan)" - # Use the snapshot taken before /proc reads to catch transient blockers. - # Combine 3 rapid samples (~100ms apart) and dedupe by pid (column 2). printf '%s\n%s\n%s\n' "$dstate_immediate" "$dstate_t1" "$dstate_t2" \ | awk 'NF >= 4 && $1=="D" && !seen[$2]++' | head -30 echo @@ -271,9 +372,16 @@ capture_snapshot() { echo "## /proc/meminfo summary" grep -E "MemTotal|MemFree|MemAvailable|Dirty|Writeback|Slab|Cached|Buffers" /proc/meminfo echo + if [ "${CAPTURE_DEVICE_IO:-1}" = "1" ]; then + capture_device_io_digest + echo + fi echo "## iostat (1s snapshot)" iostat -xt 1 2 2>&1 | tail -50 echo + echo "## Block device map" + lsblk -o NAME,MAJ:MIN,TYPE,TRAN,SIZE,LABEL 2>/dev/null + echo echo "## interrupts (top by total)" awk 'NR==1{next} {sum=0; for(i=2;i<=NF-2;i++) sum+=$i; if(sum>1000) print sum, $0}' /proc/interrupts | sort -rn | head -15 echo @@ -291,21 +399,27 @@ capture_snapshot() { journalctl --since "60 seconds ago" -p warning --no-pager 2>&1 | tail -40 } > "$body" 2>&1 - # Build final file: header + diagnosis (computed from body) + body + # Run classifier once — result goes into both the snapshot header and events.log + local diagnosis + diagnosis=$(classify_snapshot "$body") + { echo "=== FREEZE EVENT TRIGGERED: $reason ===" echo "Time: $(date -Iseconds)" echo echo "## Diagnosis (auto-classified)" - classify_snapshot "$body" + echo "$diagnosis" echo cat "$body" } > "$final" rm -f "$body" - echo "$(date -Iseconds) Captured snapshot to $final (reason: $reason)" >> "$LOG_DIR/events.log" - # Optional sidecar formats + local diag_line + diag_line=$(echo "$diagnosis" | head -1 | sed 's/^ • //') + echo "$(date -Iseconds) Captured snapshot to $final (reason: $reason) [${diag_line}]" \ + >> "$LOG_DIR/events.log" + local convert_args="" [ "${OUTPUT_JSON:-0}" = "1" ] && convert_args="$convert_args --json" [ "${OUTPUT_HTML:-0}" = "1" ] && convert_args="$convert_args --html" @@ -319,14 +433,13 @@ capture_snapshot() { echo "$(date -Iseconds) freeze-watcher started (pid $$)" >> "$LOG_DIR/events.log" prune_snapshots -# Initial softirq baseline so classifier can compute deltas cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null softirq_baseline_at=$(date +%s) while true; do now=$(date +%s) - # Manual trigger from GUI (file-based, no auth required for users in log group) + # Manual trigger from GUI if [ -f "$TRIGGER_FILE" ]; then manual_reason="manual" if [ -s "$TRIGGER_FILE" ]; then @@ -335,6 +448,7 @@ while true; do rm -f "$TRIGGER_FILE" capture_snapshot "$manual_reason" & last_capture=$now + last_trigger_time=$now sleep "$SAMPLE_INTERVAL" continue fi @@ -346,23 +460,57 @@ while true; do load1=$(awk '{print int($1+0.5)}' /proc/loadavg) triggered="" - [ "${psi_io:-0}" -ge "$PSI_IO_THRESHOLD" ] && triggered="psi_io=$psi_io%" + [ "${psi_io:-0}" -ge "$PSI_IO_THRESHOLD" ] && triggered="psi_io=$psi_io%" [ "${psi_cpu:-0}" -ge "$PSI_CPU_THRESHOLD" ] && triggered="${triggered:+$triggered, }psi_cpu=$psi_cpu%" - [ "${dstate:-0}" -ge "$DSTATE_THRESHOLD" ] && triggered="${triggered:+$triggered, }dstate=$dstate" + [ "${dstate:-0}" -ge "$DSTATE_THRESHOLD" ] && triggered="${triggered:+$triggered, }dstate=$dstate" [ "${blocked:-0}" -ge "$BLOCKED_THRESHOLD" ] && triggered="${triggered:+$triggered, }blocked=$blocked" - [ "${load1:-0}" -ge "$LOAD_THRESHOLD" ] && triggered="${triggered:+$triggered, }load1=$load1" + [ "${load1:-0}" -ge "$LOAD_THRESHOLD" ] && triggered="${triggered:+$triggered, }load1=$load1" - if [ -n "$triggered" ] && [ $((now - last_capture)) -ge "$COOLDOWN" ]; then - capture_snapshot "$triggered" & - last_capture=$now - captures_since_prune=$((captures_since_prune+1)) - if [ "$captures_since_prune" -ge 20 ]; then - prune_snapshots & - captures_since_prune=0 + if [ -n "$triggered" ]; then + last_trigger_time=$now + + # Slide the storm counting window + if [ "$storm_window_start" -eq 0 ] || \ + [ $((now - storm_window_start)) -gt "$STORM_WINDOW" ]; then + storm_count=0 + storm_window_start=$now + fi + storm_count=$((storm_count + 1)) + + # Transition into storm state + if [ "$in_storm" -eq 0 ] && [ "$storm_count" -ge "$STORM_THRESHOLD" ]; then + in_storm=1 + storm_start_time=$now + echo "$(date -Iseconds) STORM STARTED: ${storm_count} captures in $((now - storm_window_start))s (trigger: $triggered)" \ + >> "$LOG_DIR/events.log" + fi + + # Use longer cooldown during a storm to reduce log spam + effective_cooldown="$COOLDOWN" + [ "$in_storm" -eq 1 ] && effective_cooldown="$STORM_COOLDOWN" + + if [ $((now - last_capture)) -ge "$effective_cooldown" ]; then + capture_snapshot "$triggered" & + last_capture=$now + captures_since_prune=$((captures_since_prune+1)) + if [ "$captures_since_prune" -ge 20 ]; then + prune_snapshots & + captures_since_prune=0 + fi + fi + else + # End storm when quiet for 3× the storm cooldown after the last trigger + if [ "$in_storm" -eq 1 ] && [ $((now - last_trigger_time)) -gt $((STORM_COOLDOWN * 3)) ]; then + duration=$((last_trigger_time - storm_start_time)) + echo "$(date -Iseconds) STORM ENDED: duration=${duration}s, captures=${storm_count}" \ + >> "$LOG_DIR/events.log" + in_storm=0 + storm_count=0 + storm_window_start=0 fi fi - # Refresh softirq baseline every 5 minutes so classifier deltas reflect recent activity + # Refresh softirq baseline every 5 minutes if [ $((now - softirq_baseline_at)) -ge 300 ]; then cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null softirq_baseline_at=$now