1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
//! Unit tests for the `parse_stall_duration_seconds` helper used by
//! the `watchdog_override_timing_precision` gauntlet entry in
//! `tests/ktstr_sched_tests.rs`. The helper parses the sched_ext
//! SCX_EXIT_ERROR_STALL message — either
//! `"{task}[{pid}] failed to run for {secs}.{millis}s"` or
//! `"watchdog failed to check in for {secs}.{millis}s"` — emitted by
//! `kernel/sched/ext.c` scx_exit. The watchdog timing test forwards
//! the guest kernel ring buffer to the host via `ktstr::send_kmsg`
//! and recovers the kernel's own stall-duration measurement through
//! this helper.
//!
//! Kept in its own file (rather than nested in
//! `ktstr_sched_tests.rs`) because the ktstr early-dispatch path
//! intercepts nextest `--list` and `--exact` for any test binary
//! that registers `KtstrTestEntry` entries — plain `#[test]`
//! functions in such a binary are filtered out of the listing.
//! This file registers no gauntlet entries, so the standard
//! harness discovers its `#[test]` functions normally.
use grok::Grok;
/// Re-implementation of the helper under test. Kept in sync with
/// `parse_stall_duration_seconds` in `tests/ktstr_sched_tests.rs`
/// — both files compile separately under cargo (each integration
/// test is its own binary), so a shared function would require a
/// helper crate or a `#[path = ...]` include. Duplicating the
/// 7-line helper keeps the dep graph flat; the unit tests here
/// pin the contract via direct input, and the production call
/// site in `ktstr_sched_tests.rs` uses the same grok pattern.
fn parse_stall_duration_seconds(kmsg: &str) -> Option<f64> {
// Kernel emits `failed to run for %u.%03us` (per-task,
// check_rq_for_timeouts) or `watchdog failed to check in for
// %u.%03us` (per-CPU, scx_tick) per `kernel/sched/ext.c` scx_exit.
// Decompose the duration into two `INT` captures — NOT `NUMBER`,
// because NUMBER expands to BASE10NUM which already matches `2.004`
// as a whole decimal and would greedily consume the `.`, leaving
// nothing for the second capture and making the pattern fail to
// match. `INT` matches `[+-]?[0-9]+` — an integer with optional
// sign — which matches each side of the kernel's printf output
// individually.
let grok = Grok::with_default_patterns();
let pattern = grok
.compile(
r"(?:failed to run for|watchdog failed to check in for) %{INT:seconds}\.%{INT:millis}s",
false,
)
.expect("grok pattern compiles with fancy-regex backend");
let matches = pattern.match_against(kmsg)?;
let seconds: u64 = matches.get("seconds")?.parse().ok()?;
let millis: u64 = matches.get("millis")?.parse().ok()?;
Some(seconds as f64 + (millis as f64) / 1000.0)
}
#[test]
fn parses_kernel_stall_message() {
let kmsg = "\
[ 42.001] sched_ext: enabled scx-ktstr
[ 44.105] kworker/0:1[42] failed to run for 2.004s
[ 44.120] sched_ext: scx-ktstr: BPF scheduler \"scx-ktstr\" errored, disabling
";
assert_eq!(parse_stall_duration_seconds(kmsg), Some(2.004));
}
#[test]
fn returns_none_when_no_stall_message() {
let kmsg = "[ 42.001] sched_ext: enabled scx-ktstr\n";
assert_eq!(parse_stall_duration_seconds(kmsg), None);
}
#[test]
fn parses_the_first_stall_line_when_multiple() {
// grok's match_against returns the FIRST successful match over
// the input. Earliest stall line wins.
let kmsg = "\
a[1] failed to run for 1.500s
b[2] failed to run for 3.700s
";
assert_eq!(parse_stall_duration_seconds(kmsg), Some(1.500));
}
#[test]
fn parses_exact_second_boundary() {
// Kernel printf `%u.%03u` always emits three-digit millis, even
// on an exact-second boundary: 5 seconds exactly renders as
// `5.000s`, not `5s`. Pin that the parser combines the two INT
// captures back into the correct f64 seconds value.
let kmsg = "x[1] failed to run for 5.000s\n";
assert_eq!(parse_stall_duration_seconds(kmsg), Some(5.0));
}
#[test]
fn computes_seconds_plus_millis_correctly() {
// Spot-check the two-part reconstruction: `0.123s` is
// 0 + 123/1000 = 0.123. `7.999s` is 7.999.
assert_eq!(
parse_stall_duration_seconds("a[1] failed to run for 0.123s\n"),
Some(0.123),
);
assert_eq!(
parse_stall_duration_seconds("b[2] failed to run for 7.999s\n"),
Some(7.999),
);
}
#[test]
fn parses_watchdog_check_in_form() {
// Post-Path-A, a deterministic stall starves the watchdog
// wq-kworker, so scx_tick's per-CPU "watchdog failed to check in
// for" printk fires instead of check_rq_for_timeouts' per-task
// "failed to run for". The parser must match both forms.
let kmsg = "[ 44.210] sched_ext: watchdog failed to check in for 2.050s\n";
assert_eq!(parse_stall_duration_seconds(kmsg), Some(2.050));
}