0.5.0: storm detection, device IO digest, new classifiers, PSI io full graph
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 <noreply@anthropic.com>
This commit is contained in:
parent
6e39a1db66
commit
27171ec4dc
2 changed files with 434 additions and 107 deletions
|
|
@ -11,7 +11,7 @@ import re
|
||||||
import subprocess
|
import subprocess
|
||||||
import sys
|
import sys
|
||||||
from collections import Counter, deque
|
from collections import Counter, deque
|
||||||
from datetime import datetime
|
from datetime import datetime, timedelta
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
|
|
||||||
from PySide6.QtCore import Qt, QTimer, QPointF, Signal
|
from PySide6.QtCore import Qt, QTimer, QPointF, Signal
|
||||||
|
|
@ -34,10 +34,22 @@ GRAPH_UPDATE_MS = 1000
|
||||||
|
|
||||||
def read_psi(name):
|
def read_psi(name):
|
||||||
try:
|
try:
|
||||||
line = (Path("/proc/pressure") / name).read_text().splitlines()[0]
|
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)
|
m = re.search(r"avg10=([\d.]+)", line)
|
||||||
return float(m.group(1)) if m else 0.0
|
return float(m.group(1)) if m else 0.0
|
||||||
except Exception:
|
except Exception:
|
||||||
|
pass
|
||||||
return 0.0
|
return 0.0
|
||||||
|
|
||||||
|
|
||||||
|
|
@ -74,6 +86,50 @@ def service_active():
|
||||||
return r.stdout.strip() == "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
|
# ----------------------------------------------------------------- widgets
|
||||||
|
|
||||||
class MetricLabel(QLabel):
|
class MetricLabel(QLabel):
|
||||||
|
|
@ -114,21 +170,26 @@ class LineGraph(QWidget):
|
||||||
self.warn = warn
|
self.warn = warn
|
||||||
self.crit = crit
|
self.crit = crit
|
||||||
self.values = deque(maxlen=HISTORY_SECONDS)
|
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.setMinimumHeight(110)
|
||||||
self.setSizePolicy(QSizePolicy.Expanding, QSizePolicy.Preferred)
|
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)
|
self.values.append(value)
|
||||||
|
idx = len(self.values) - 1
|
||||||
if marker:
|
if marker:
|
||||||
self.markers.add(len(self.values) - 1)
|
self.markers.add(idx)
|
||||||
# Decay markers as values shift out
|
if storm_marker:
|
||||||
new_markers = set()
|
self.storm_markers.add(idx)
|
||||||
for m in self.markers:
|
# 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
|
shifted = m - 1 if len(self.values) == HISTORY_SECONDS else m
|
||||||
if shifted >= 0:
|
if shifted >= 0:
|
||||||
new_markers.add(shifted)
|
new.add(shifted)
|
||||||
self.markers = new_markers
|
setattr(self, attr, new)
|
||||||
self.update()
|
self.update()
|
||||||
|
|
||||||
def paintEvent(self, _):
|
def paintEvent(self, _):
|
||||||
|
|
@ -136,7 +197,6 @@ class LineGraph(QWidget):
|
||||||
p.setRenderHint(QPainter.Antialiasing)
|
p.setRenderHint(QPainter.Antialiasing)
|
||||||
w, h = self.width(), self.height()
|
w, h = self.width(), self.height()
|
||||||
|
|
||||||
# Background
|
|
||||||
p.fillRect(0, 0, w, h, QColor("#1a1a1a"))
|
p.fillRect(0, 0, w, h, QColor("#1a1a1a"))
|
||||||
|
|
||||||
if not self.values:
|
if not self.values:
|
||||||
|
|
@ -148,13 +208,11 @@ class LineGraph(QWidget):
|
||||||
min_v = 0
|
min_v = 0
|
||||||
rng = max_v - min_v
|
rng = max_v - min_v
|
||||||
|
|
||||||
# Title and current value
|
|
||||||
p.setPen(QColor("#aaa"))
|
p.setPen(QColor("#aaa"))
|
||||||
p.setFont(QFont("monospace", 9))
|
p.setFont(QFont("monospace", 9))
|
||||||
current = self.values[-1]
|
current = self.values[-1]
|
||||||
p.drawText(8, 16, f"{self.label} current={current:.1f} max={max(self.values):.1f}")
|
p.drawText(8, 16, f"{self.label} current={current:.1f} max={max(self.values):.1f}")
|
||||||
|
|
||||||
# Threshold lines
|
|
||||||
plot_top = 24
|
plot_top = 24
|
||||||
plot_bot = h - 8
|
plot_bot = h - 8
|
||||||
plot_h = plot_bot - plot_top
|
plot_h = plot_bot - plot_top
|
||||||
|
|
@ -165,11 +223,10 @@ class LineGraph(QWidget):
|
||||||
p.setPen(QPen(QColor(col), 1, Qt.DashLine))
|
p.setPen(QPen(QColor(col), 1, Qt.DashLine))
|
||||||
p.drawLine(0, int(y), w, int(y))
|
p.drawLine(0, int(y), w, int(y))
|
||||||
|
|
||||||
# Line
|
|
||||||
n = len(self.values)
|
n = len(self.values)
|
||||||
if n < 2:
|
if n < 2:
|
||||||
return
|
return
|
||||||
step = w / (n - 1) if n > 1 else 0
|
step = w / (n - 1)
|
||||||
poly = QPolygonF()
|
poly = QPolygonF()
|
||||||
for i, v in enumerate(self.values):
|
for i, v in enumerate(self.values):
|
||||||
x = i * step
|
x = i * step
|
||||||
|
|
@ -178,12 +235,18 @@ class LineGraph(QWidget):
|
||||||
p.setPen(QPen(self.color, 1.5))
|
p.setPen(QPen(self.color, 1.5))
|
||||||
p.drawPolyline(poly)
|
p.drawPolyline(poly)
|
||||||
|
|
||||||
# Markers (snapshot captures)
|
# Regular snapshot markers (red dotted)
|
||||||
p.setPen(QPen(QColor("#ff5555"), 1, Qt.DotLine))
|
p.setPen(QPen(QColor("#ff5555"), 1, Qt.DotLine))
|
||||||
for m in self.markers:
|
for m in self.markers:
|
||||||
x = m * step
|
x = m * step
|
||||||
p.drawLine(int(x), plot_top, int(x), plot_bot)
|
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
|
# ----------------------------------------------------------------- snapshot parsing
|
||||||
|
|
||||||
|
|
@ -252,6 +315,10 @@ class FreezeMonitor(QMainWindow):
|
||||||
self.status_label = QLabel()
|
self.status_label = QLabel()
|
||||||
self.status_label.setStyleSheet("padding:6px; font-weight:bold;")
|
self.status_label.setStyleSheet("padding:6px; font-weight:bold;")
|
||||||
status_row.addWidget(self.status_label)
|
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()
|
status_row.addStretch()
|
||||||
self.btn_capture_now = QPushButton("📸 Capture Now")
|
self.btn_capture_now = QPushButton("📸 Capture Now")
|
||||||
self.btn_capture_now.setToolTip("Manually trigger a snapshot capture")
|
self.btn_capture_now.setToolTip("Manually trigger a snapshot capture")
|
||||||
|
|
@ -268,7 +335,7 @@ class FreezeMonitor(QMainWindow):
|
||||||
# Live metrics row
|
# Live metrics row
|
||||||
metrics_box = QGroupBox("Live metrics (1s refresh)")
|
metrics_box = QGroupBox("Live metrics (1s refresh)")
|
||||||
grid = QGridLayout(metrics_box)
|
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 = {}
|
self.metrics = {}
|
||||||
for i, name in enumerate(labels):
|
for i, name in enumerate(labels):
|
||||||
grid.addWidget(QLabel(name, alignment=Qt.AlignCenter), 0, i)
|
grid.addWidget(QLabel(name, alignment=Qt.AlignCenter), 0, i)
|
||||||
|
|
@ -286,7 +353,8 @@ class FreezeMonitor(QMainWindow):
|
||||||
self._build_summary_tab()
|
self._build_summary_tab()
|
||||||
|
|
||||||
self._known_events = set()
|
self._known_events = set()
|
||||||
self._all_snapshots = [] # cached parses
|
self._all_snapshots = []
|
||||||
|
self._storms = []
|
||||||
|
|
||||||
# Tray
|
# Tray
|
||||||
self.tray = QSystemTrayIcon(self.style().standardIcon(QStyle.SP_ComputerIcon), self)
|
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.activated.connect(self._tray_clicked)
|
||||||
self.tray.show()
|
self.tray.show()
|
||||||
|
|
||||||
# Tick timer
|
|
||||||
self.timer = QTimer()
|
self.timer = QTimer()
|
||||||
self.timer.timeout.connect(self.tick)
|
self.timer.timeout.connect(self.tick)
|
||||||
self.timer.start(GRAPH_UPDATE_MS)
|
self.timer.start(GRAPH_UPDATE_MS)
|
||||||
|
|
@ -318,12 +385,14 @@ class FreezeMonitor(QMainWindow):
|
||||||
def _build_graphs_tab(self):
|
def _build_graphs_tab(self):
|
||||||
tab = QWidget()
|
tab = QWidget()
|
||||||
v = QVBoxLayout(tab)
|
v = QVBoxLayout(tab)
|
||||||
v.addWidget(QLabel("<b>Last hour</b> — red dashed lines mark snapshot captures"))
|
v.addWidget(QLabel("<b>Last hour</b> — red dashed = snapshot capture, orange = storm start"))
|
||||||
self.graph_load = LineGraph("Load (1m)", "#5cdb95", warn=8, crit=16)
|
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_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_psi_cpu = LineGraph("PSI cpu.some %", "#ffcc66", warn=30, crit=60)
|
||||||
self.graph_dstate = LineGraph("D-state procs", "#ff8888", warn=3, crit=6)
|
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):
|
for g in (self.graph_load, self.graph_psi_io, self.graph_psi_iof,
|
||||||
|
self.graph_psi_cpu, self.graph_dstate):
|
||||||
v.addWidget(g)
|
v.addWidget(g)
|
||||||
self.tabs.addTab(tab, "Live graphs")
|
self.tabs.addTab(tab, "Live graphs")
|
||||||
|
|
||||||
|
|
@ -334,7 +403,7 @@ class FreezeMonitor(QMainWindow):
|
||||||
filter_row = QHBoxLayout()
|
filter_row = QHBoxLayout()
|
||||||
filter_row.addWidget(QLabel("Filter:"))
|
filter_row.addWidget(QLabel("Filter:"))
|
||||||
self.filter_edit = QLineEdit()
|
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)
|
self.filter_edit.textChanged.connect(self._apply_filter)
|
||||||
filter_row.addWidget(self.filter_edit)
|
filter_row.addWidget(self.filter_edit)
|
||||||
self.btn_refresh = QPushButton("Refresh")
|
self.btn_refresh = QPushButton("Refresh")
|
||||||
|
|
@ -416,18 +485,20 @@ class FreezeMonitor(QMainWindow):
|
||||||
|
|
||||||
def tick(self):
|
def tick(self):
|
||||||
psi_io = read_psi("io")
|
psi_io = read_psi("io")
|
||||||
|
psi_io_f = read_psi_full("io")
|
||||||
psi_cpu = read_psi("cpu")
|
psi_cpu = read_psi("cpu")
|
||||||
psi_mem = read_psi("memory")
|
psi_mem = read_psi("memory")
|
||||||
dstate = read_dstate_count()
|
dstate = read_dstate_count()
|
||||||
blocked = read_procs_blocked()
|
blocked = read_procs_blocked()
|
||||||
load = read_loadavg()
|
load = read_loadavg()
|
||||||
|
|
||||||
self.metrics["PSI IO %"].set_value(int(psi_io), 30, 60, "")
|
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 IO full %"].set_value(int(psi_io_f), 15, 40)
|
||||||
self.metrics["PSI Mem %"].set_value(int(psi_mem), 20, 50, "")
|
self.metrics["PSI CPU %"].set_value(int(psi_cpu), 30, 60)
|
||||||
self.metrics["D-state"].set_value(dstate, 3, 6, "")
|
self.metrics["PSI Mem %"].set_value(int(psi_mem), 20, 50)
|
||||||
self.metrics["Blocked"].set_value(blocked, 3, 6, "")
|
self.metrics["D-state"].set_value(dstate, 3, 6)
|
||||||
self.metrics["Load (1m)"].set_value(int(load), 8, 16, "")
|
self.metrics["Blocked"].set_value(blocked, 3, 6)
|
||||||
|
self.metrics["Load (1m)"].set_value(int(load), 8, 16)
|
||||||
|
|
||||||
active = service_active()
|
active = service_active()
|
||||||
if active:
|
if active:
|
||||||
|
|
@ -437,23 +508,43 @@ class FreezeMonitor(QMainWindow):
|
||||||
self.status_label.setText("● Service: STOPPED")
|
self.status_label.setText("● Service: STOPPED")
|
||||||
self.status_label.setStyleSheet("padding:6px; font-weight:bold; color:#ff5555;")
|
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(
|
self.tray.setToolTip(
|
||||||
f"Freeze Watcher — {'active' if active else 'stopped'}\n"
|
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()
|
current = set(p.name for p in LOG_DIR.glob("snap-*.log")) if LOG_DIR.exists() else set()
|
||||||
new = current - self._known_events
|
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)
|
is_marker = bool(new)
|
||||||
self.graph_load.push(load, marker=is_marker)
|
is_storm_marker = new_storm and bool(active_storm)
|
||||||
self.graph_psi_io.push(psi_io, marker=is_marker)
|
self.graph_load.push(load, marker=is_marker, storm_marker=is_storm_marker)
|
||||||
self.graph_psi_cpu.push(psi_cpu, marker=is_marker)
|
self.graph_psi_io.push(psi_io, marker=is_marker, storm_marker=is_storm_marker)
|
||||||
self.graph_dstate.push(dstate, marker=is_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:
|
if current != self._known_events:
|
||||||
self._known_events = current
|
self._known_events = current
|
||||||
self._all_snapshots = [] # invalidate cache
|
self._all_snapshots = []
|
||||||
self.load_events()
|
self.load_events()
|
||||||
for n in new:
|
for n in new:
|
||||||
self.tray.showMessage(
|
self.tray.showMessage(
|
||||||
|
|
@ -474,29 +565,89 @@ class FreezeMonitor(QMainWindow):
|
||||||
self._all_snapshots = [parse_snapshot(p) for p in files]
|
self._all_snapshots = [parse_snapshot(p) for p in files]
|
||||||
self._all_snapshots = [s for s in self._all_snapshots if s]
|
self._all_snapshots = [s for s in self._all_snapshots if s]
|
||||||
self._known_events = set(p.name for p in files)
|
self._known_events = set(p.name for p in files)
|
||||||
|
self._storms = parse_events_log()
|
||||||
self._apply_filter()
|
self._apply_filter()
|
||||||
|
|
||||||
def _apply_filter(self):
|
def _apply_filter(self):
|
||||||
needle = self.filter_edit.text().lower().strip()
|
needle = self.filter_edit.text().lower().strip()
|
||||||
self.event_list.clear()
|
self.event_list.clear()
|
||||||
|
|
||||||
|
# Interleave storm events into the snapshot list by time
|
||||||
|
snap_items = []
|
||||||
for info in self._all_snapshots:
|
for info in self._all_snapshots:
|
||||||
|
ts = datetime.fromtimestamp(info["mtime"])
|
||||||
text_blob = (info["reason"] + " " + " ".join(info["diagnoses"])).lower()
|
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
|
continue
|
||||||
ts = datetime.fromtimestamp(info["mtime"]).strftime("%Y-%m-%d %H:%M:%S")
|
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 ""
|
diag_short = info["diagnoses"][0][:80] if info["diagnoses"] else ""
|
||||||
label = f"{ts}\n reason: {info['reason']}"
|
label = f"{ts_str}\n reason: {info['reason']}"
|
||||||
if diag_short:
|
if diag_short:
|
||||||
label += f"\n → {diag_short}"
|
label += f"\n → {diag_short}"
|
||||||
item = QListWidgetItem(label)
|
item = QListWidgetItem(label)
|
||||||
item.setData(Qt.UserRole, info["path"])
|
item.setData(Qt.UserRole, info["path"])
|
||||||
|
item.setData(Qt.UserRole + 1, "snap")
|
||||||
self.event_list.addItem(item)
|
self.event_list.addItem(item)
|
||||||
|
|
||||||
def show_selected(self):
|
def show_selected(self):
|
||||||
items = self.event_list.selectedItems()
|
items = self.event_list.selectedItems()
|
||||||
if not items:
|
if not items:
|
||||||
return
|
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:
|
try:
|
||||||
text = path.read_text()
|
text = path.read_text()
|
||||||
html_sidecar = path.with_suffix(".html")
|
html_sidecar = path.with_suffix(".html")
|
||||||
|
|
@ -519,10 +670,12 @@ class FreezeMonitor(QMainWindow):
|
||||||
QMessageBox.information(self, "Select a snapshot",
|
QMessageBox.information(self, "Select a snapshot",
|
||||||
"Pick a snapshot from the list first.")
|
"Pick a snapshot from the list first.")
|
||||||
return
|
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")
|
html = path.with_suffix(".html")
|
||||||
if not html.exists():
|
if not html.exists():
|
||||||
# Try generating on demand
|
|
||||||
try:
|
try:
|
||||||
subprocess.run(["freeze-snapshot-convert", "--html", str(path)],
|
subprocess.run(["freeze-snapshot-convert", "--html", str(path)],
|
||||||
check=True, capture_output=True)
|
check=True, capture_output=True)
|
||||||
|
|
@ -556,8 +709,36 @@ class FreezeMonitor(QMainWindow):
|
||||||
if not self._all_snapshots:
|
if not self._all_snapshots:
|
||||||
self.load_events()
|
self.load_events()
|
||||||
snaps = self._all_snapshots
|
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:
|
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
|
return
|
||||||
|
|
||||||
wchans = Counter()
|
wchans = Counter()
|
||||||
|
|
@ -575,7 +756,6 @@ class FreezeMonitor(QMainWindow):
|
||||||
if s["top_cpu_proc"]:
|
if s["top_cpu_proc"]:
|
||||||
top_cpu[s["top_cpu_proc"]] += 1
|
top_cpu[s["top_cpu_proc"]] += 1
|
||||||
for d in s["diagnoses"]:
|
for d in s["diagnoses"]:
|
||||||
# First clause only, before " — "
|
|
||||||
key = d.split("—")[0].strip()[:60]
|
key = d.split("—")[0].strip()[:60]
|
||||||
diagnoses[key] += 1
|
diagnoses[key] += 1
|
||||||
ts = datetime.fromtimestamp(s["mtime"])
|
ts = datetime.fromtimestamp(s["mtime"])
|
||||||
|
|
@ -595,10 +775,9 @@ class FreezeMonitor(QMainWindow):
|
||||||
hour_dist = []
|
hour_dist = []
|
||||||
for h in range(24):
|
for h in range(24):
|
||||||
count = hours.get(h, 0)
|
count = hours.get(h, 0)
|
||||||
bar = "▇" * count
|
bar = "▇" * min(count, 40)
|
||||||
hour_dist.append(f" {h:02d}:00 {bar} {count}")
|
hour_dist.append(f" {h:02d}:00 {bar} {count}")
|
||||||
|
|
||||||
out = []
|
|
||||||
out.append(f"Snapshots analyzed: {len(snaps)}")
|
out.append(f"Snapshots analyzed: {len(snaps)}")
|
||||||
if first and last:
|
if first and last:
|
||||||
out.append(f"Time range: {first} → {last}")
|
out.append(f"Time range: {first} → {last}")
|
||||||
|
|
|
||||||
|
|
@ -15,6 +15,9 @@ DSTATE_THRESHOLD=5
|
||||||
BLOCKED_THRESHOLD=5
|
BLOCKED_THRESHOLD=5
|
||||||
LOAD_THRESHOLD=20
|
LOAD_THRESHOLD=20
|
||||||
COOLDOWN=30
|
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
|
SAMPLE_INTERVAL=1
|
||||||
MAX_SNAPSHOTS=200
|
MAX_SNAPSHOTS=200
|
||||||
MAX_SNAPSHOT_AGE_DAYS=30
|
MAX_SNAPSHOT_AGE_DAYS=30
|
||||||
|
|
@ -23,6 +26,7 @@ NOTIFY_URGENCY=normal
|
||||||
CAPTURE_KERNEL_STACKS=1
|
CAPTURE_KERNEL_STACKS=1
|
||||||
CAPTURE_BPFTRACE=0
|
CAPTURE_BPFTRACE=0
|
||||||
CAPTURE_CGROUP_PSI=1
|
CAPTURE_CGROUP_PSI=1
|
||||||
|
CAPTURE_DEVICE_IO=1 # include hot-device IO digest (device labels, await, nr_requests)
|
||||||
OUTPUT_JSON=0
|
OUTPUT_JSON=0
|
||||||
OUTPUT_HTML=0
|
OUTPUT_HTML=0
|
||||||
|
|
||||||
|
|
@ -33,6 +37,13 @@ mkdir -p "$LOG_DIR"
|
||||||
last_capture=0
|
last_capture=0
|
||||||
captures_since_prune=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() {
|
notify_users() {
|
||||||
[ -z "$NOTIFY_USERS" ] && return 0
|
[ -z "$NOTIFY_USERS" ] && return 0
|
||||||
local body="$1"
|
local body="$1"
|
||||||
|
|
@ -110,8 +121,65 @@ capture_bpftrace() {
|
||||||
' 2>/dev/null | tail -40
|
' 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.
|
# 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() {
|
classify_snapshot() {
|
||||||
local file="$1"
|
local file="$1"
|
||||||
local diagnoses=()
|
local diagnoses=()
|
||||||
|
|
@ -130,7 +198,33 @@ classify_snapshot() {
|
||||||
local dcount
|
local dcount
|
||||||
dcount=$(echo "$dstate_section" | grep -c "^D ")
|
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 echo "$dstate_section" | grep -qE "btrfs_lock_root_node|btrfs_sync_log"; then
|
||||||
if [ "${psi_io_some:-0}" -lt 10 ]; 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.")
|
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
|
||||||
fi
|
fi
|
||||||
|
|
||||||
# btrfs metadata pressure (less severe)
|
# --- btrfs metadata pressure ---
|
||||||
if echo "$dstate_section" | grep -q "btrfs_search_slot" && \
|
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")
|
diagnoses+=("btrfs metadata pressure — cleaner walking trees, fsyncs queueing")
|
||||||
fi
|
fi
|
||||||
|
|
||||||
# USB stall
|
# --- USB stall ---
|
||||||
if echo "$dstate_section" | grep -qE "usb_sg_wait|scsi_eh|sd_check_events|usb_hcd"; then
|
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
|
fi
|
||||||
|
|
||||||
# Memory swap thrash
|
# --- memory swap thrash ---
|
||||||
if echo "$dstate_section" | grep -q "folio_wait_bit_common"; then
|
if echo "$dstate_section" | grep -q "folio_wait_bit_common"; then
|
||||||
if [ "${psi_mem_some:-0}" -gt 5 ]; then
|
if [ "${psi_mem_some:-0}" -gt 5 ]; then
|
||||||
diagnoses+=("memory pressure / swap thrash — folio_wait + PSI mem ${psi_mem_some}%")
|
diagnoses+=("memory pressure / swap thrash — folio_wait + PSI mem ${psi_mem_some}%")
|
||||||
|
|
@ -159,15 +261,19 @@ classify_snapshot() {
|
||||||
fi
|
fi
|
||||||
fi
|
fi
|
||||||
|
|
||||||
# CPU oversubscription
|
# --- container/Waydroid startup CPU spike ---
|
||||||
if [ "${psi_cpu_some:-0}" -gt 30 ] && [ "$dcount" -lt 3 ]; then
|
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.")
|
diagnoses+=("CPU oversubscription — PSI cpu ${psi_cpu_some}%, few D-state procs. Heavy compile, transcoding, or runaway process competing for cores.")
|
||||||
fi
|
fi
|
||||||
|
|
||||||
# NIC IRQ saturation — use delta against the running baseline so old
|
# --- NIC IRQ saturation ---
|
||||||
# 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.
|
|
||||||
if [ -r "$LOG_DIR/.softirq-baseline" ] && [ -n "$(echo "$softirq" | grep '^ *NET_RX:')" ]; then
|
if [ -r "$LOG_DIR/.softirq-baseline" ] && [ -n "$(echo "$softirq" | grep '^ *NET_RX:')" ]; then
|
||||||
local cur prev
|
local cur prev
|
||||||
cur=$(echo "$softirq" | grep '^ *NET_RX:' | sed 's/^ *NET_RX://')
|
cur=$(echo "$softirq" | grep '^ *NET_RX:' | sed 's/^ *NET_RX://')
|
||||||
|
|
@ -187,13 +293,11 @@ classify_snapshot() {
|
||||||
done
|
done
|
||||||
if [ "$total" -gt 100000 ]; then
|
if [ "$total" -gt 100000 ]; then
|
||||||
local pct=$((max * 100 / total))
|
local pct=$((max * 100 / total))
|
||||||
# Check if RPS is configured (any non-zero, non-single-bit value)
|
|
||||||
local rps_active=0
|
local rps_active=0
|
||||||
for rps in /sys/class/net/*/queues/rx-0/rps_cpus; do
|
for rps in /sys/class/net/*/queues/rx-0/rps_cpus; do
|
||||||
[ -r "$rps" ] || continue
|
[ -r "$rps" ] || continue
|
||||||
local v
|
local v
|
||||||
v=$(cat "$rps" 2>/dev/null | tr -d ',')
|
v=$(cat "$rps" 2>/dev/null | tr -d ',')
|
||||||
# Strip leading zeros, count hex bits set
|
|
||||||
[ "$v" != "0" ] && [ "$v" != "00" ] && [ "$v" != "000" ] \
|
[ "$v" != "0" ] && [ "$v" != "00" ] && [ "$v" != "000" ] \
|
||||||
&& [ "$v" != "0000" ] && rps_active=1
|
&& [ "$v" != "0000" ] && rps_active=1
|
||||||
done
|
done
|
||||||
|
|
@ -206,7 +310,7 @@ classify_snapshot() {
|
||||||
fi
|
fi
|
||||||
fi
|
fi
|
||||||
|
|
||||||
# Genuine I/O bottleneck
|
# --- genuine I/O bottleneck ---
|
||||||
if [ "${psi_io_full:-0}" -gt 30 ]; then
|
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")
|
diagnoses+=("genuine I/O bottleneck — PSI io full ${psi_io_full}%, device truly can't keep up")
|
||||||
fi
|
fi
|
||||||
|
|
@ -225,8 +329,7 @@ capture_snapshot() {
|
||||||
local body="$LOG_DIR/.snap-body-$$.tmp"
|
local body="$LOG_DIR/.snap-body-$$.tmp"
|
||||||
local final="$LOG_DIR/snap-$(date +%Y%m%d-%H%M%S).log"
|
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
|
# Capture D-state first — spikes can be <1s, grab before slower /proc reads
|
||||||
# to grab process state before reading slower /proc/* files
|
|
||||||
local dstate_immediate
|
local dstate_immediate
|
||||||
dstate_immediate=$(ps -eo state,pid,user,wchan:25,comm,args --no-headers 2>/dev/null | awk '$1=="D"' | head -30)
|
dstate_immediate=$(ps -eo state,pid,user,wchan:25,comm,args --no-headers 2>/dev/null | awk '$1=="D"' | head -30)
|
||||||
local dstate_t1
|
local dstate_t1
|
||||||
|
|
@ -253,8 +356,6 @@ capture_snapshot() {
|
||||||
echo
|
echo
|
||||||
fi
|
fi
|
||||||
echo "## D-state processes (with kernel wchan)"
|
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" \
|
printf '%s\n%s\n%s\n' "$dstate_immediate" "$dstate_t1" "$dstate_t2" \
|
||||||
| awk 'NF >= 4 && $1=="D" && !seen[$2]++' | head -30
|
| awk 'NF >= 4 && $1=="D" && !seen[$2]++' | head -30
|
||||||
echo
|
echo
|
||||||
|
|
@ -271,9 +372,16 @@ capture_snapshot() {
|
||||||
echo "## /proc/meminfo summary"
|
echo "## /proc/meminfo summary"
|
||||||
grep -E "MemTotal|MemFree|MemAvailable|Dirty|Writeback|Slab|Cached|Buffers" /proc/meminfo
|
grep -E "MemTotal|MemFree|MemAvailable|Dirty|Writeback|Slab|Cached|Buffers" /proc/meminfo
|
||||||
echo
|
echo
|
||||||
|
if [ "${CAPTURE_DEVICE_IO:-1}" = "1" ]; then
|
||||||
|
capture_device_io_digest
|
||||||
|
echo
|
||||||
|
fi
|
||||||
echo "## iostat (1s snapshot)"
|
echo "## iostat (1s snapshot)"
|
||||||
iostat -xt 1 2 2>&1 | tail -50
|
iostat -xt 1 2 2>&1 | tail -50
|
||||||
echo
|
echo
|
||||||
|
echo "## Block device map"
|
||||||
|
lsblk -o NAME,MAJ:MIN,TYPE,TRAN,SIZE,LABEL 2>/dev/null
|
||||||
|
echo
|
||||||
echo "## interrupts (top by total)"
|
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
|
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
|
echo
|
||||||
|
|
@ -291,21 +399,27 @@ capture_snapshot() {
|
||||||
journalctl --since "60 seconds ago" -p warning --no-pager 2>&1 | tail -40
|
journalctl --since "60 seconds ago" -p warning --no-pager 2>&1 | tail -40
|
||||||
} > "$body" 2>&1
|
} > "$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 "=== FREEZE EVENT TRIGGERED: $reason ==="
|
||||||
echo "Time: $(date -Iseconds)"
|
echo "Time: $(date -Iseconds)"
|
||||||
echo
|
echo
|
||||||
echo "## Diagnosis (auto-classified)"
|
echo "## Diagnosis (auto-classified)"
|
||||||
classify_snapshot "$body"
|
echo "$diagnosis"
|
||||||
echo
|
echo
|
||||||
cat "$body"
|
cat "$body"
|
||||||
} > "$final"
|
} > "$final"
|
||||||
|
|
||||||
rm -f "$body"
|
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=""
|
local convert_args=""
|
||||||
[ "${OUTPUT_JSON:-0}" = "1" ] && convert_args="$convert_args --json"
|
[ "${OUTPUT_JSON:-0}" = "1" ] && convert_args="$convert_args --json"
|
||||||
[ "${OUTPUT_HTML:-0}" = "1" ] && convert_args="$convert_args --html"
|
[ "${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"
|
echo "$(date -Iseconds) freeze-watcher started (pid $$)" >> "$LOG_DIR/events.log"
|
||||||
prune_snapshots
|
prune_snapshots
|
||||||
|
|
||||||
# Initial softirq baseline so classifier can compute deltas
|
|
||||||
cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null
|
cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null
|
||||||
softirq_baseline_at=$(date +%s)
|
softirq_baseline_at=$(date +%s)
|
||||||
|
|
||||||
while true; do
|
while true; do
|
||||||
now=$(date +%s)
|
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
|
if [ -f "$TRIGGER_FILE" ]; then
|
||||||
manual_reason="manual"
|
manual_reason="manual"
|
||||||
if [ -s "$TRIGGER_FILE" ]; then
|
if [ -s "$TRIGGER_FILE" ]; then
|
||||||
|
|
@ -335,6 +448,7 @@ while true; do
|
||||||
rm -f "$TRIGGER_FILE"
|
rm -f "$TRIGGER_FILE"
|
||||||
capture_snapshot "$manual_reason" &
|
capture_snapshot "$manual_reason" &
|
||||||
last_capture=$now
|
last_capture=$now
|
||||||
|
last_trigger_time=$now
|
||||||
sleep "$SAMPLE_INTERVAL"
|
sleep "$SAMPLE_INTERVAL"
|
||||||
continue
|
continue
|
||||||
fi
|
fi
|
||||||
|
|
@ -352,7 +466,30 @@ while true; do
|
||||||
[ "${blocked:-0}" -ge "$BLOCKED_THRESHOLD" ] && triggered="${triggered:+$triggered, }blocked=$blocked"
|
[ "${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
|
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" &
|
capture_snapshot "$triggered" &
|
||||||
last_capture=$now
|
last_capture=$now
|
||||||
captures_since_prune=$((captures_since_prune+1))
|
captures_since_prune=$((captures_since_prune+1))
|
||||||
|
|
@ -361,8 +498,19 @@ while true; do
|
||||||
captures_since_prune=0
|
captures_since_prune=0
|
||||||
fi
|
fi
|
||||||
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
|
if [ $((now - softirq_baseline_at)) -ge 300 ]; then
|
||||||
cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null
|
cp /proc/softirqs "$LOG_DIR/.softirq-baseline" 2>/dev/null
|
||||||
softirq_baseline_at=$now
|
softirq_baseline_at=$now
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue