authorgravatar for mlugg@mlugg.co.ukMatthew Lugg <mlugg@mlugg.co.uk> 2025-08-21 13:44:43+01:00
committergravatar for mlugg@mlugg.co.ukMatthew Lugg <mlugg@mlugg.co.uk> 2025-10-18 09:28:39+01:00
log7e7d7875b9af97bd04ca03a98b2e4188d57e3c13
tree59d1f3ebe4d23a4c92fee31a5a2c763de7a9012e
parent337762114f575824a1ab793dca41a3d073aa17cd
signaturelock-open Commit is signed but in an unrecognized format.

std.Build: implement unit test timeouts

For now, there is a flag to `zig build` called `--test-timeout-ms` which accepts a value in milliseconds. If the execution time of any individual unit test exceeds that number of milliseconds, the test is terminated and marked as timed out. In the future, we may want to increase the granularity of this feature by allowing timeouts to be specified per-step or even per-test. However, a global option is actually very useful. In particular, it can be used in CI scripts to ensure that no individual unit test exceeds some reasonable limit (e.g. 60 seconds) without having to assign limits to every individual test step in the build script. Also, individual unit test durations are now shown in the time report web interface -- this was fairly trivial to add since we're timing tests (to check for timeouts) anyway. This commit makes progress on #19821, but does not close it, because that proposal includes a more sophisticated mechanism for setting timeouts. Co-Authored-By: David Rubin <david@vortan.dev>

11 files changed, 370 insertions(+), 36 deletions(-)

lib/build-web/index.html+13
......@@ -139,6 +139,19 @@
139139 <div><slot name="llvm-pass-timings"></slot></div>
140140 </details>
141141 </div>
142 <div id="runTestReport">
143 <table class="time-stats">
144 <thead>
145 <tr>
146 <th scope="col">Test Name</th>
147 <th scope="col">Duration</th>
148 </tr>
149 </thead>
150 <!-- HTML does not allow placing a 'slot' inside of a 'tbody' for backwards-compatibility
151 reasons, so we unfortunately must template on the `id` here. -->
152 <tbody id="runTestTableBody"></tbody>
153 </div>
154 </div>
142155 </details>
143156</template>
144157
lib/build-web/main.js+21-1
......@@ -46,8 +46,9 @@ WebAssembly.instantiateStreaming(wasm_promise, {
4646 updateCoverage: fuzzUpdateCoverage,
4747 },
4848 time_report: {
49 updateCompile: timeReportUpdateCompile,
5049 updateGeneric: timeReportUpdateGeneric,
50 updateCompile: timeReportUpdateCompile,
51 updateRunTest: timeReportUpdateRunTest,
5152 },
5253}).then(function(obj) {
5354 setConnectionStatus("Connecting to WebSocket...", true);
......@@ -248,6 +249,7 @@ function timeReportUpdateCompile(
248249
249250 shadow.getElementById("genericReport").classList.add("hidden");
250251 shadow.getElementById("compileReport").classList.remove("hidden");
252 shadow.getElementById("runTestReport").classList.add("hidden");
251253
252254 if (!use_llvm) shadow.querySelector(":host > details").classList.add("no-llvm");
253255 host.innerHTML = inner_html;
......@@ -265,8 +267,26 @@ function timeReportUpdateGeneric(
265267 shadow.querySelector(":host > details").classList.remove("pending", "no-llvm");
266268 shadow.getElementById("genericReport").classList.remove("hidden");
267269 shadow.getElementById("compileReport").classList.add("hidden");
270 shadow.getElementById("runTestReport").classList.add("hidden");
268271 host.innerHTML = inner_html;
269272}
273function timeReportUpdateRunTest(
274 step_idx,
275 table_html_ptr,
276 table_html_len,
277) {
278 const table_html = decodeString(table_html_ptr, table_html_len);
279 const host = domTimeReportList.children.item(step_idx);
280 const shadow = host.shadowRoot;
281
282 shadow.querySelector(":host > details").classList.remove("pending", "no-llvm");
283
284 shadow.getElementById("genericReport").classList.add("hidden");
285 shadow.getElementById("compileReport").classList.add("hidden");
286 shadow.getElementById("runTestReport").classList.remove("hidden");
287
288 shadow.getElementById("runTestTableBody").innerHTML = table_html;
289}
270290
271291const fuzz_entry_template = document.getElementById("fuzzEntryTemplate").content;
272292const domFuzz = document.getElementById("fuzz");
lib/build-web/main.zig+1
......@@ -94,6 +94,7 @@ export fn message_end() void {
9494
9595 .time_report_generic_result => return time_report.genericResultMessage(msg_bytes) catch @panic("OOM"),
9696 .time_report_compile_result => return time_report.compileResultMessage(msg_bytes) catch @panic("OOM"),
97 .time_report_run_test_result => return time_report.runTestResultMessage(msg_bytes) catch @panic("OOM"),
9798 }
9899}
99100
lib/build-web/time_report.zig+41
......@@ -27,6 +27,13 @@ const js = struct {
2727 /// Whether the LLVM backend was used. If not, LLVM-specific statistics are hidden.
2828 use_llvm: bool,
2929 ) void;
30 extern "time_report" fn updateRunTest(
31 /// The index of the step.
32 step_idx: u32,
33 // The HTML which will populate the <tbody> of the test table.
34 table_html_ptr: [*]const u8,
35 table_html_len: usize,
36 ) void;
3037};
3138
3239pub fn genericResultMessage(msg_bytes: []u8) error{OutOfMemory}!void {
......@@ -237,3 +244,37 @@ pub fn compileResultMessage(msg_bytes: []u8) error{ OutOfMemory, WriteFailed }!v
237244 hdr.flags.use_llvm,
238245 );
239246}
247
248pub fn runTestResultMessage(msg_bytes: []u8) error{OutOfMemory}!void {
249 if (msg_bytes.len < @sizeOf(abi.RunTestResult)) @panic("malformed RunTestResult message");
250 const hdr: *const abi.RunTestResult = @ptrCast(msg_bytes[0..@sizeOf(abi.RunTestResult)]);
251 if (hdr.step_idx >= step_list.*.len) @panic("malformed RunTestResult message");
252 const trailing = msg_bytes[@sizeOf(abi.RunTestResult)..];
253
254 const durations: []align(1) const u64 = @ptrCast(trailing[0 .. hdr.tests_len * 8]);
255 var offset: usize = hdr.tests_len * 8;
256
257 var table_html: std.ArrayListUnmanaged(u8) = .empty;
258 defer table_html.deinit(gpa);
259
260 for (durations) |test_ns| {
261 const test_name_len = std.mem.indexOfScalar(u8, trailing[offset..], 0) orelse @panic("malformed RunTestResult message");
262 const test_name = trailing[offset..][0..test_name_len];
263 offset += test_name_len + 1;
264 try table_html.print(gpa, "<tr><th scope=\"row\"><code>{f}</code></th>", .{fmtEscapeHtml(test_name)});
265 if (test_ns == std.math.maxInt(u64)) {
266 try table_html.appendSlice(gpa, "<td class=\"empty-cell\"></td>"); // didn't run
267 } else {
268 try table_html.print(gpa, "<td>{D}</td>", .{test_ns});
269 }
270 try table_html.appendSlice(gpa, "</tr>\n");
271 }
272
273 if (offset != trailing.len) @panic("malformed RunTestResult message");
274
275 js.updateRunTest(
276 hdr.step_idx,
277 table_html.items.ptr,
278 table_html.items.len,
279 );
280}
lib/compiler/build_runner.zig+35-7
......@@ -106,6 +106,7 @@ pub fn main() !void {
106106 var summary: ?Summary = null;
107107 var max_rss: u64 = 0;
108108 var skip_oom_steps = false;
109 var test_timeout_ms: ?u64 = null;
109110 var color: Color = .auto;
110111 var prominent_compile_errors = false;
111112 var help_menu = false;
......@@ -175,6 +176,14 @@ pub fn main() !void {
175176 };
176177 } else if (mem.eql(u8, arg, "--skip-oom-steps")) {
177178 skip_oom_steps = true;
179 } else if (mem.eql(u8, arg, "--test-timeout-ms")) {
180 const millis_str = nextArgOrFatal(args, &arg_idx);
181 test_timeout_ms = std.fmt.parseInt(u64, millis_str, 10) catch |err| {
182 std.debug.print("invalid millisecond count: '{s}': {s}\n", .{
183 millis_str, @errorName(err),
184 });
185 process.exit(1);
186 };
178187 } else if (mem.eql(u8, arg, "--search-prefix")) {
179188 const search_prefix = nextArgOrFatal(args, &arg_idx);
180189 builder.addSearchPrefix(search_prefix);
......@@ -448,6 +457,11 @@ pub fn main() !void {
448457 .max_rss_is_default = false,
449458 .max_rss_mutex = .{},
450459 .skip_oom_steps = skip_oom_steps,
460 .unit_test_timeout_ns = ns: {
461 const ms = test_timeout_ms orelse break :ns null;
462 break :ns std.math.mul(u64, ms, std.time.ns_per_ms) catch null;
463 },
464
451465 .watch = watch,
452466 .web_server = undefined, // set after `prepare`
453467 .memory_blocked_steps = .empty,
......@@ -605,6 +619,7 @@ const Run = struct {
605619 max_rss_is_default: bool,
606620 max_rss_mutex: std.Thread.Mutex,
607621 skip_oom_steps: bool,
622 unit_test_timeout_ns: ?u64,
608623 watch: bool,
609624 web_server: if (!builtin.single_threaded) ?WebServer else ?noreturn,
610625 /// Allocated into `gpa`.
......@@ -724,6 +739,7 @@ fn runStepNames(
724739 var test_fail_count: usize = 0;
725740 var test_pass_count: usize = 0;
726741 var test_leak_count: usize = 0;
742 var test_timeout_count: usize = 0;
727743 var test_count: usize = 0;
728744
729745 var success_count: usize = 0;
......@@ -736,6 +752,7 @@ fn runStepNames(
736752 test_fail_count += s.test_results.fail_count;
737753 test_skip_count += s.test_results.skip_count;
738754 test_leak_count += s.test_results.leak_count;
755 test_timeout_count += s.test_results.timeout_count;
739756 test_pass_count += s.test_results.passCount();
740757 test_count += s.test_results.test_count;
741758
......@@ -834,6 +851,7 @@ fn runStepNames(
834851 if (test_skip_count > 0) w.print("; {d} skipped", .{test_skip_count}) catch {};
835852 if (test_fail_count > 0) w.print("; {d} failed", .{test_fail_count}) catch {};
836853 if (test_leak_count > 0) w.print("; {d} leaked", .{test_leak_count}) catch {};
854 if (test_timeout_count > 0) w.print("; {d} timed out", .{test_timeout_count}) catch {};
837855
838856 w.writeAll("\n") catch {};
839857
......@@ -995,7 +1013,10 @@ fn printStepStatus(
9951013 try stderr.writeAll("\n");
9961014 try ttyconf.setColor(stderr, .reset);
9971015 },
998 .failure => try printStepFailure(s, stderr, ttyconf),
1016 .failure => {
1017 try printStepFailure(s, stderr, ttyconf);
1018 try ttyconf.setColor(stderr, .reset);
1019 },
9991020 }
10001021}
10011022
......@@ -1009,7 +1030,6 @@ fn printStepFailure(
10091030 try stderr.print(" {d} errors\n", .{
10101031 s.result_error_bundle.errorMessageCount(),
10111032 });
1012 try ttyconf.setColor(stderr, .reset);
10131033 } else if (!s.test_results.isSuccess()) {
10141034 try stderr.print(" {d}/{d} passed", .{
10151035 s.test_results.passCount(), s.test_results.test_count,
......@@ -1020,7 +1040,7 @@ fn printStepFailure(
10201040 try stderr.print("{d} failed", .{
10211041 s.test_results.fail_count,
10221042 });
1023 try ttyconf.setColor(stderr, .reset);
1043 try ttyconf.setColor(stderr, .white);
10241044 }
10251045 if (s.test_results.skip_count > 0) {
10261046 try stderr.writeAll(", ");
......@@ -1028,7 +1048,7 @@ fn printStepFailure(
10281048 try stderr.print("{d} skipped", .{
10291049 s.test_results.skip_count,
10301050 });
1031 try ttyconf.setColor(stderr, .reset);
1051 try ttyconf.setColor(stderr, .white);
10321052 }
10331053 if (s.test_results.leak_count > 0) {
10341054 try stderr.writeAll(", ");
......@@ -1036,18 +1056,24 @@ fn printStepFailure(
10361056 try stderr.print("{d} leaked", .{
10371057 s.test_results.leak_count,
10381058 });
1039 try ttyconf.setColor(stderr, .reset);
1059 try ttyconf.setColor(stderr, .white);
1060 }
1061 if (s.test_results.timeout_count > 0) {
1062 try stderr.writeAll(", ");
1063 try ttyconf.setColor(stderr, .red);
1064 try stderr.print("{d} timed out", .{
1065 s.test_results.timeout_count,
1066 });
1067 try ttyconf.setColor(stderr, .white);
10401068 }
10411069 try stderr.writeAll("\n");
10421070 } else if (s.result_error_msgs.items.len > 0) {
10431071 try ttyconf.setColor(stderr, .red);
10441072 try stderr.writeAll(" failure\n");
1045 try ttyconf.setColor(stderr, .reset);
10461073 } else {
10471074 assert(s.result_stderr.len > 0);
10481075 try ttyconf.setColor(stderr, .red);
10491076 try stderr.writeAll(" stderr\n");
1050 try ttyconf.setColor(stderr, .reset);
10511077 }
10521078}
10531079
......@@ -1250,6 +1276,7 @@ fn workerMakeOneStep(
12501276 .thread_pool = thread_pool,
12511277 .watch = run.watch,
12521278 .web_server = if (run.web_server) |*ws| ws else null,
1279 .unit_test_timeout_ns = run.unit_test_timeout_ns,
12531280 .gpa = run.gpa,
12541281 });
12551282
......@@ -1439,6 +1466,7 @@ fn printUsage(b: *std.Build, w: *Writer) !void {
14391466 \\ -j<N> Limit concurrent jobs (default is to use all CPU cores)
14401467 \\ --maxrss <bytes> Limit memory usage (default is to use available memory)
14411468 \\ --skip-oom-steps Instead of failing, skip steps that would exceed --maxrss
1469 \\ --test-timeout-ms <ms> Limit execution time of unit tests, terminating if exceeded
14421470 \\ --fetch[=mode] Fetch dependency tree (optionally choose laziness) and exit
14431471 \\ needed (Default) Lazy dependencies are fetched as needed
14441472 \\ all Lazy dependencies are always fetched
lib/compiler/test_runner.zig+4
......@@ -135,6 +135,10 @@ fn mainServer() !void {
135135 var fail = false;
136136 var skip = false;
137137 is_fuzz_test = false;
138
139 // let the build server know we're starting the test now
140 try server.serveStringMessage(.test_started, &.{});
141
138142 test_fn.func() catch |err| switch (err) {
139143 error.SkipZigTest => skip = true,
140144 else => {
lib/std/Build/Step.zig+6-3
......@@ -66,15 +66,16 @@ pub const TestResults = struct {
6666 fail_count: u32 = 0,
6767 skip_count: u32 = 0,
6868 leak_count: u32 = 0,
69 timeout_count: u32 = 0,
6970 log_err_count: u32 = 0,
7071 test_count: u32 = 0,
7172
7273 pub fn isSuccess(tr: TestResults) bool {
73 return tr.fail_count == 0 and tr.leak_count == 0 and tr.log_err_count == 0;
74 return tr.fail_count == 0 and tr.leak_count == 0 and tr.log_err_count == 0 and tr.timeout_count == 0;
7475 }
7576
7677 pub fn passCount(tr: TestResults) u32 {
77 return tr.test_count - tr.fail_count - tr.skip_count;
78 return tr.test_count - tr.fail_count - tr.skip_count - tr.timeout_count;
7879 }
7980};
8081
......@@ -88,6 +89,8 @@ pub const MakeOptions = struct {
8889 // it currently breaks because `std.net.Address` doesn't work there. Work around for now.
8990 .wasm32 => void,
9091 },
92 /// If set, this is a timeout to enforce on all individual unit tests, in nanoseconds.
93 unit_test_timeout_ns: ?u64,
9194 /// Not to be confused with `Build.allocator`, which is an alias of `Build.graph.arena`.
9295 gpa: Allocator,
9396};
......@@ -243,6 +246,7 @@ pub fn make(s: *Step, options: MakeOptions) error{ MakeFailed, MakeSkipped }!voi
243246 var timer: ?std.time.Timer = t: {
244247 if (!s.owner.graph.time_report) break :t null;
245248 if (s.id == .compile) break :t null;
249 if (s.id == .run and s.cast(Run).?.stdio == .zig_test) break :t null;
246250 break :t std.time.Timer.start() catch @panic("--time-report not supported on this host");
247251 };
248252 const make_result = s.makeFn(s, options);
......@@ -513,7 +517,6 @@ fn zigProcessUpdate(s: *Step, zp: *ZigProcess, watch: bool, web_server: ?*Build.
513517 const header = stdout.takeStruct(Header, .little) catch unreachable;
514518 while (stdout.buffered().len < header.bytes_len) if (!try zp.poller.poll()) break :poll;
515519 const body = stdout.take(header.bytes_len) catch unreachable;
516
517520 switch (header.tag) {
518521 .zig_version => {
519522 if (!std.mem.eql(u8, builtin.zig_version_string, body)) {
lib/std/Build/Step/Run.zig+169-25
......@@ -756,7 +756,6 @@ const IndexedOutput = struct {
756756 output: *Output,
757757};
758758fn make(step: *Step, options: Step.MakeOptions) !void {
759 const prog_node = options.progress_node;
760759 const b = step.owner;
761760 const arena = b.allocator;
762761 const run: *Run = @fieldParentPtr("step", step);
......@@ -964,7 +963,7 @@ fn make(step: *Step, options: Step.MakeOptions) !void {
964963 b.fmt("{s}{s}", .{ placeholder.output.prefix, arg_output_path });
965964 }
966965
967 try runCommand(run, argv_list.items, has_side_effects, output_dir_path, prog_node, null);
966 try runCommand(run, argv_list.items, has_side_effects, output_dir_path, options, null);
968967 if (!has_side_effects) try step.writeManifestAndWatch(&man);
969968 return;
970969 };
......@@ -997,7 +996,7 @@ fn make(step: *Step, options: Step.MakeOptions) !void {
997996 });
998997 }
999998
1000 try runCommand(run, argv_list.items, has_side_effects, tmp_dir_path, prog_node, null);
999 try runCommand(run, argv_list.items, has_side_effects, tmp_dir_path, options, null);
10011000
10021001 const dep_file_dir = std.fs.cwd();
10031002 const dep_file_basename = dep_output_file.generated_file.getPath2(b, step);
......@@ -1115,7 +1114,14 @@ pub fn rerunInFuzzMode(
11151114 const has_side_effects = false;
11161115 const rand_int = std.crypto.random.int(u64);
11171116 const tmp_dir_path = "tmp" ++ fs.path.sep_str ++ std.fmt.hex(rand_int);
1118 try runCommand(run, argv_list.items, has_side_effects, tmp_dir_path, prog_node, .{
1117 try runCommand(run, argv_list.items, has_side_effects, tmp_dir_path, .{
1118 .progress_node = prog_node,
1119 .thread_pool = undefined, // not used by `runCommand`
1120 .watch = undefined, // not used by `runCommand`
1121 .web_server = null, // only needed for time reports
1122 .unit_test_timeout_ns = null, // don't time out fuzz tests for now
1123 .gpa = undefined, // not used by `runCommand`
1124 }, .{
11191125 .unit_test_index = unit_test_index,
11201126 .fuzz = fuzz,
11211127 });
......@@ -1196,7 +1202,7 @@ fn runCommand(
11961202 argv: []const []const u8,
11971203 has_side_effects: bool,
11981204 output_dir_path: []const u8,
1199 prog_node: std.Progress.Node,
1205 options: Step.MakeOptions,
12001206 fuzz_context: ?FuzzContext,
12011207) !void {
12021208 const step = &run.step;
......@@ -1218,7 +1224,7 @@ fn runCommand(
12181224
12191225 var env_map = run.env_map orelse &b.graph.env_map;
12201226
1221 const result = spawnChildAndCollect(run, argv, env_map, has_side_effects, prog_node, fuzz_context) catch |err| term: {
1227 const result = spawnChildAndCollect(run, argv, env_map, has_side_effects, options, fuzz_context) catch |err| term: {
12221228 // InvalidExe: cpu arch mismatch
12231229 // FileNotFound: can happen with a wrong dynamic linker path
12241230 if (err == error.InvalidExe or err == error.FileNotFound) interpret: {
......@@ -1357,7 +1363,7 @@ fn runCommand(
13571363
13581364 try Step.handleVerbose2(step.owner, cwd, run.env_map, interp_argv.items);
13591365
1360 break :term spawnChildAndCollect(run, interp_argv.items, env_map, has_side_effects, prog_node, fuzz_context) catch |e| {
1366 break :term spawnChildAndCollect(run, interp_argv.items, env_map, has_side_effects, options, fuzz_context) catch |e| {
13611367 if (!run.failing_to_execute_foreign_is_an_error) return error.MakeSkipped;
13621368
13631369 return step.fail("unable to spawn interpreter {s}: {s}", .{
......@@ -1372,8 +1378,14 @@ fn runCommand(
13721378 step.result_duration_ns = result.elapsed_ns;
13731379 step.result_peak_rss = result.peak_rss;
13741380 step.test_results = result.stdio.test_results;
1375 if (result.stdio.test_metadata) |tm|
1381 if (result.stdio.test_metadata) |tm| {
13761382 run.cached_test_metadata = tm.toCachedTestMetadata();
1383 if (options.web_server) |ws| ws.updateTimeReportRunTest(
1384 run,
1385 &run.cached_test_metadata.?,
1386 tm.ns_per_test,
1387 );
1388 }
13771389
13781390 const final_argv = if (interp_argv.items.len == 0) argv else interp_argv.items;
13791391
......@@ -1558,7 +1570,7 @@ fn spawnChildAndCollect(
15581570 argv: []const []const u8,
15591571 env_map: *EnvMap,
15601572 has_side_effects: bool,
1561 prog_node: std.Progress.Node,
1573 options: Step.MakeOptions,
15621574 fuzz_context: ?FuzzContext,
15631575) !ChildProcResult {
15641576 const b = run.step.owner;
......@@ -1604,7 +1616,7 @@ fn spawnChildAndCollect(
16041616 const inherit = child.stdout_behavior == .Inherit or child.stderr_behavior == .Inherit;
16051617
16061618 if (run.stdio != .zig_test and !run.disable_zig_progress and !inherit) {
1607 child.progress_node = prog_node;
1619 child.progress_node = options.progress_node;
16081620 }
16091621
16101622 const term, const result, const elapsed_ns = t: {
......@@ -1622,7 +1634,7 @@ fn spawnChildAndCollect(
16221634 var timer = try std.time.Timer.start();
16231635
16241636 const result = if (run.stdio == .zig_test)
1625 try evalZigTest(run, &child, prog_node, fuzz_context)
1637 try evalZigTest(run, &child, options, fuzz_context)
16261638 else
16271639 try evalGeneric(run, &child);
16281640
......@@ -1647,13 +1659,15 @@ const StdIoResult = struct {
16471659fn evalZigTest(
16481660 run: *Run,
16491661 child: *std.process.Child,
1650 prog_node: std.Progress.Node,
1662 options: Step.MakeOptions,
16511663 fuzz_context: ?FuzzContext,
16521664) !StdIoResult {
16531665 const gpa = run.step.owner.allocator;
16541666 const arena = run.step.owner.allocator;
16551667
1656 var poller = std.Io.poll(gpa, enum { stdout, stderr }, .{
1668 const PollEnum = enum { stdout, stderr };
1669
1670 var poller = std.Io.poll(gpa, PollEnum, .{
16571671 .stdout = child.stdout.?,
16581672 .stderr = child.stderr.?,
16591673 });
......@@ -1692,21 +1706,126 @@ fn evalZigTest(
16921706 var fail_count: u32 = 0;
16931707 var skip_count: u32 = 0;
16941708 var leak_count: u32 = 0;
1709 var timeout_count: u32 = 0;
16951710 var test_count: u32 = 0;
16961711 var log_err_count: u32 = 0;
16971712
16981713 var metadata: ?TestMetadata = null;
16991714 var coverage_id: ?u64 = null;
17001715
1716 var test_is_running = false;
1717
1718 // String allocated into `gpa`. Owned by this function while it runs, then moved to the `Step`.
1719 var result_stderr: []u8 = &.{};
1720 defer run.step.result_stderr = result_stderr;
1721
1722 // `null` means this host does not support `std.time.Timer`. This timer is `reset()` whenever we
1723 // toggle `test_is_running`, i.e. whenever a test starts or finishes.
1724 var timer: ?std.time.Timer = std.time.Timer.start() catch t: {
1725 std.log.warn("std.time.Timer not supported on host; test timeouts will be ignored", .{});
1726 break :t null;
1727 };
1728
17011729 var sub_prog_node: ?std.Progress.Node = null;
17021730 defer if (sub_prog_node) |n| n.end();
17031731
1704 const stdout = poller.reader(.stdout);
1705 const stderr = poller.reader(.stderr);
1732 // This timeout is used when we're waiting on the test runner itself rather than a user-specified
1733 // test. For instance, if the test runner leaves this much time between us requesting a test to
1734 // start and it acknowledging the test starting, we terminate the child and raise an error. This
1735 // *should* never happen, but could in theory be caused by some very unlucky IB in a test.
1736 const response_timeout_ns = 30 * std.time.ns_per_s;
1737
17061738 const any_write_failed = first_write_failed or poll: while (true) {
1739 // These are scoped inside the loop because we sometimes respawn the child and recreate
1740 // `poller` which invaldiates these readers.
1741 const stdout = poller.reader(.stdout);
1742 const stderr = poller.reader(.stderr);
1743
17071744 const Header = std.zig.Server.Message.Header;
1708 while (stdout.buffered().len < @sizeOf(Header)) if (!try poller.poll()) break :poll false;
1745
1746 // This block is exited when `stdout` contains enough bytes for a `Header`.
1747 header_ready: {
1748 if (stdout.buffered().len >= @sizeOf(Header)) {
1749 // We already have one, no need to poll!
1750 break :header_ready;
1751 }
1752
1753 // Always `null` if `timer` is `null`.
1754 const opt_timeout_ns: ?u64 = ns: {
1755 if (timer == null) break :ns null;
1756 if (!test_is_running) break :ns response_timeout_ns;
1757 break :ns options.unit_test_timeout_ns;
1758 };
1759
1760 if (opt_timeout_ns) |timeout_ns| {
1761 const remaining_ns = timeout_ns -| timer.?.read();
1762 if (!try poller.pollTimeout(remaining_ns)) break :poll false;
1763 } else {
1764 if (!try poller.poll()) break :poll false;
1765 }
1766
1767 if (stdout.buffered().len >= @sizeOf(Header)) {
1768 // There wasn't a header before, but there is one after the `poll`.
1769 break :header_ready;
1770 }
1771
1772 const timeout_ns = opt_timeout_ns orelse continue;
1773 const cur_ns = timer.?.read();
1774 if (cur_ns < timeout_ns) continue;
1775
1776 // There was a timeout.
1777
1778 if (!test_is_running) {
1779 // The child stopped responding while *not* running a test. To avoid getting into
1780 // a loop if something's broken, don't retry; just report an error and stop.
1781 try run.step.addError("test runner failed to respond for {D}", .{cur_ns});
1782 break :poll false;
1783 }
1784
1785 // A test has probably just gotten stuck. We'll report an error, then just kill the
1786 // child and continue with the next test in the list.
1787
1788 const md = &metadata.?;
1789 const test_index = md.next_index - 1;
1790
1791 timeout_count += 1;
1792 try run.step.addError(
1793 "'{s}' timed out after {D}",
1794 .{ md.testName(test_index), cur_ns },
1795 );
1796 if (stderr.buffered().len > 0) {
1797 const new_bytes = stderr.buffered();
1798 const old_len = result_stderr.len;
1799 result_stderr = try gpa.realloc(result_stderr, old_len + new_bytes.len);
1800 @memcpy(result_stderr[old_len..], new_bytes);
1801 }
1802
1803 _ = try child.kill();
1804 // Respawn the test runner. There's a double-cleanup if this fails, but that's
1805 // fine because our caller's `kill` will just return `error.AlreadyTerminated`.
1806 try child.spawn();
1807 try child.waitForSpawn();
1808
1809 // After respawning the child, we must update the poller's streams.
1810 poller.deinit();
1811 poller = std.Io.poll(gpa, PollEnum, .{
1812 .stdout = child.stdout.?,
1813 .stderr = child.stderr.?,
1814 });
1815
1816 test_is_running = false;
1817 md.ns_per_test[test_index] = timer.?.lap();
1818
1819 requestNextTest(child.stdin.?, md, &sub_prog_node) catch |err| {
1820 try run.step.addError("unable to write stdin: {s}", .{@errorName(err)});
1821 break :poll true;
1822 };
1823
1824 continue :poll; // continue work with the new (respawned) child
1825 }
1826 // There is definitely a header available now -- read it.
17091827 const header = stdout.takeStruct(Header, .little) catch unreachable;
1828
17101829 while (stdout.buffered().len < header.bytes_len) if (!try poller.poll()) break :poll false;
17111830 const body = stdout.take(header.bytes_len) catch unreachable;
17121831 switch (header.tag) {
......@@ -1720,6 +1839,12 @@ fn evalZigTest(
17201839 },
17211840 .test_metadata => {
17221841 assert(fuzz_context == null);
1842
1843 // `metadata` would only be populated if we'd already seen a `test_metadata`, but we
1844 // only request it once (and importantly, we don't re-request it if we kill and
1845 // restart the test runner).
1846 assert(metadata == null);
1847
17231848 const TmHdr = std.zig.Server.Message.TestMetadata;
17241849 const tm_hdr = @as(*align(1) const TmHdr, @ptrCast(body));
17251850 test_count = tm_hdr.tests_len;
......@@ -1730,32 +1855,42 @@ fn evalZigTest(
17301855
17311856 const names = std.mem.bytesAsSlice(u32, names_bytes);
17321857 const expected_panic_msgs = std.mem.bytesAsSlice(u32, expected_panic_msgs_bytes);
1858
17331859 const names_aligned = try arena.alloc(u32, names.len);
17341860 for (names_aligned, names) |*dest, src| dest.* = src;
17351861
17361862 const expected_panic_msgs_aligned = try arena.alloc(u32, expected_panic_msgs.len);
17371863 for (expected_panic_msgs_aligned, expected_panic_msgs) |*dest, src| dest.* = src;
17381864
1739 prog_node.setEstimatedTotalItems(names.len);
1865 options.progress_node.setEstimatedTotalItems(names.len);
17401866 metadata = .{
17411867 .string_bytes = try arena.dupe(u8, string_bytes),
1868 .ns_per_test = try arena.alloc(u64, test_count),
17421869 .names = names_aligned,
17431870 .expected_panic_msgs = expected_panic_msgs_aligned,
17441871 .next_index = 0,
1745 .prog_node = prog_node,
1872 .prog_node = options.progress_node,
17461873 };
1874 @memset(metadata.?.ns_per_test, std.math.maxInt(u64));
1875
1876 test_is_running = false;
1877 if (timer) |*t| t.reset();
17471878
17481879 requestNextTest(child.stdin.?, &metadata.?, &sub_prog_node) catch |err| {
17491880 try run.step.addError("unable to write stdin: {s}", .{@errorName(err)});
17501881 break :poll true;
17511882 };
17521883 },
1884 .test_started => {
1885 test_is_running = true;
1886 if (timer) |*t| t.reset();
1887 },
17531888 .test_results => {
17541889 assert(fuzz_context == null);
1755 const md = metadata.?;
1890 const md = &metadata.?;
17561891
17571892 const TrHdr = std.zig.Server.Message.TestResults;
1758 const tr_hdr = @as(*align(1) const TrHdr, @ptrCast(body));
1893 const tr_hdr: *align(1) const TrHdr = @ptrCast(body);
17591894 fail_count +|= @intFromBool(tr_hdr.flags.fail);
17601895 skip_count +|= @intFromBool(tr_hdr.flags.skip);
17611896 leak_count +|= @intFromBool(tr_hdr.flags.leak);
......@@ -1764,7 +1899,7 @@ fn evalZigTest(
17641899 if (tr_hdr.flags.fuzz) try run.fuzz_tests.append(gpa, tr_hdr.index);
17651900
17661901 if (tr_hdr.flags.fail or tr_hdr.flags.leak or tr_hdr.flags.log_err_count > 0) {
1767 const name = std.mem.sliceTo(md.string_bytes[md.names[tr_hdr.index]..], 0);
1902 const name = std.mem.sliceTo(md.testName(tr_hdr.index), 0);
17681903 const stderr_contents = stderr.buffered();
17691904 stderr.toss(stderr_contents.len);
17701905 const msg = std.mem.trim(u8, stderr_contents, "\n");
......@@ -1783,7 +1918,10 @@ fn evalZigTest(
17831918 }
17841919 }
17851920
1786 requestNextTest(child.stdin.?, &metadata.?, &sub_prog_node) catch |err| {
1921 test_is_running = false;
1922 if (timer) |*t| md.ns_per_test[tr_hdr.index] = t.lap();
1923
1924 requestNextTest(child.stdin.?, md, &sub_prog_node) catch |err| {
17871925 try run.step.addError("unable to write stdin: {s}", .{@errorName(err)});
17881926 break :poll true;
17891927 };
......@@ -1831,9 +1969,12 @@ fn evalZigTest(
18311969 while (try poller.poll()) {}
18321970 }
18331971
1834 const stderr_contents = std.mem.trim(u8, stderr.buffered(), "\n");
1835 if (stderr_contents.len > 0) {
1836 run.step.result_stderr = try arena.dupe(u8, stderr_contents);
1972 const stderr = poller.reader(.stderr);
1973 if (stderr.buffered().len > 0) {
1974 const new_bytes = stderr.buffered();
1975 const old_len = result_stderr.len;
1976 result_stderr = try gpa.realloc(result_stderr, old_len + new_bytes.len);
1977 @memcpy(result_stderr[old_len..], new_bytes);
18371978 }
18381979
18391980 // Send EOF to stdin.
......@@ -1848,6 +1989,7 @@ fn evalZigTest(
18481989 .fail_count = fail_count,
18491990 .skip_count = skip_count,
18501991 .leak_count = leak_count,
1992 .timeout_count = timeout_count,
18511993 .log_err_count = log_err_count,
18521994 },
18531995 .test_metadata = metadata,
......@@ -1856,6 +1998,7 @@ fn evalZigTest(
18561998
18571999const TestMetadata = struct {
18582000 names: []const u32,
2001 ns_per_test: []u64,
18592002 expected_panic_msgs: []const u32,
18602003 string_bytes: []const u8,
18612004 next_index: u32,
......@@ -1896,6 +2039,7 @@ fn requestNextTest(in: fs.File, metadata: *TestMetadata, sub_prog_node: *?std.Pr
18962039 try sendRunTestMessage(in, .run_test, i);
18972040 return;
18982041 } else {
2042 metadata.next_index = std.math.maxInt(u32); // indicate that all tests are done
18992043 try sendMessage(in, .exit);
19002044 }
19012045}
lib/std/Build/WebServer.zig+58
......@@ -751,6 +751,64 @@ pub fn updateTimeReportGeneric(ws: *WebServer, step: *Build.Step, ns_total: u64)
751751 ws.notifyUpdate();
752752}
753753
754pub fn updateTimeReportRunTest(
755 ws: *WebServer,
756 run: *Build.Step.Run,
757 tests: *const Build.Step.Run.CachedTestMetadata,
758 ns_per_test: []const u64,
759) void {
760 const gpa = ws.gpa;
761
762 const step_idx: u32 = for (ws.all_steps, 0..) |s, i| {
763 if (s == &run.step) break @intCast(i);
764 } else unreachable;
765
766 assert(tests.names.len == ns_per_test.len);
767 const tests_len: u32 = @intCast(tests.names.len);
768
769 const new_len: u64 = len: {
770 var names_len: u64 = 0;
771 for (0..tests_len) |i| {
772 names_len += tests.testName(@intCast(i)).len + 1;
773 }
774 break :len @sizeOf(abi.time_report.RunTestResult) + names_len + 8 * tests_len;
775 };
776 const old_buf = old: {
777 ws.time_report_mutex.lock();
778 defer ws.time_report_mutex.unlock();
779 const old = ws.time_report_msgs[step_idx];
780 ws.time_report_msgs[step_idx] = &.{};
781 break :old old;
782 };
783 const buf = gpa.realloc(old_buf, new_len) catch @panic("out of memory");
784
785 const out_header: *align(1) abi.time_report.RunTestResult = @ptrCast(buf[0..@sizeOf(abi.time_report.RunTestResult)]);
786 out_header.* = .{
787 .step_idx = step_idx,
788 .tests_len = tests_len,
789 };
790 var offset: usize = @sizeOf(abi.time_report.RunTestResult);
791 const ns_per_test_out: []align(1) u64 = @ptrCast(buf[offset..][0 .. tests_len * 8]);
792 @memcpy(ns_per_test_out, ns_per_test);
793 offset += tests_len * 8;
794 for (0..tests_len) |i| {
795 const name = tests.testName(@intCast(i));
796 @memcpy(buf[offset..][0..name.len], name);
797 buf[offset..][name.len] = 0;
798 offset += name.len + 1;
799 }
800 assert(offset == buf.len);
801
802 {
803 ws.time_report_mutex.lock();
804 defer ws.time_report_mutex.unlock();
805 assert(ws.time_report_msgs[step_idx].len == 0);
806 ws.time_report_msgs[step_idx] = buf;
807 ws.time_report_update_times[step_idx] = ws.now();
808 }
809 ws.notifyUpdate();
810}
811
754812const RunnerRequest = union(enum) {
755813 rebuild,
756814};
lib/std/Build/abi.zig+16
......@@ -56,6 +56,7 @@ pub const ToClientTag = enum(u8) {
5656 // `--time-report`
5757 time_report_generic_result,
5858 time_report_compile_result,
59 time_report_run_test_result,
5960
6061 _,
6162};
......@@ -342,4 +343,19 @@ pub const time_report = struct {
342343 };
343344 };
344345 };
346
347 /// WebSocket server->client.
348 ///
349 /// Sent after a `Step.Run` for a Zig test executable finishes, providing the test's time report.
350 ///
351 /// Trailing:
352 /// * for each `tests_len`:
353 /// * `test_ns: u64` (nanoseconds spent running this test)
354 /// * for each `tests_len`:
355 /// * `name` (null-terminated UTF-8 string)
356 pub const RunTestResult = extern struct {
357 tag: ToClientTag = .time_report_run_test_result,
358 step_idx: u32 align(1),
359 tests_len: u32 align(1),
360 };
345361};
lib/std/zig/Server.zig+6
......@@ -34,6 +34,12 @@ pub const Message = struct {
3434 test_metadata,
3535 /// Body is a TestResults
3636 test_results,
37 /// Does not have a body.
38 /// Notifies the build runner that the next test (requested by `Client.Message.Tag.run_test`)
39 /// is starting execution. This message helps to ensure that the timestamp used by the build
40 /// runner to enforce unit test time limits is relatively accurate under extreme system load
41 /// (where there may be a non-trivial delay before the test process is scheduled).
42 test_started,
3743 /// Body is a series of strings, delimited by null bytes.
3844 /// Each string is a prefixed file path.
3945 /// The first byte indicates the file prefix path (see prefixes fields