Skip to content

test(ffi): wait for the joined workers' task entries before counting them - #350

Merged
shinaoka merged 1 commit into
mainfrom
test/348-fork-settle
Nov 9, 2026
Merged

shinaoka merged 1 commit into
mainfrom
test/348-fork-settle

Conversation

@shinaoka

@shinaoka shinaoka commented Nov 9, 2026 •

Copy link
Copy Markdown
Member

Fixes the flake behind #348. Refs #348 (do not close it on merge).

Symptom

PR #346 (docs only) failed ci / Run cargo test -p faer-ffi -j4
(run 42629271729, head eb7c2c46):

thread 'a_forked_child_creates_and_uses_a_handle_of_its_own' panicked at faer-ffi/tests/fork.rs:118:5:
assertion `left == right` failed: destroy left the handle's workers running
  left: 3
 right: 2

The same head's body passed and main (57db5c04, 4ccd69b3) was green: not a docs change.

Cause

faer-ffi/tests/fork.rs:102 counts /proc/self/task — the process's tasks — and the test read it
once, immediately after libfaer_v0_23_team_destroy:

unsafe { libfaer_v0_23_team_destroy(team) };
assert_eq!(threads(), before, "destroy left the handle's workers running");

destroy does join the workers (Team::pool_for gives the pool a thread_name, so threadteam 0.5.1
treats it as dedicated and Pool::drop joins each std handle instead of parking it in the process-wide
cache — threadteam-0.5.1/src/pool.rs:295, :399), but a joined task's /proc entry outlives the
join
: std's join returns when the worker's closure has finished, not when the task is gone, so the
single read sometimes samples the exit path. That is candidate (a) of the issue, not (b): nothing
leaks.

Measured on the pinned 1.96.0 (Linux x86_64):

# 1. a control with no faer-ffi in the process: std spawn(3) then join, read /proc/self/task
$ ./probe 200000 3
base=1 iters=200000 n=3 over=1609        # 0.8% of iterations read a task above the baseline

# 2. the test binary itself, pre-fix
$ for i in $(seq 1 2000); do target/debug/deps/fork-5a1ce98634b50021 > log 2>&1 || echo "FAIL $i"; done
FAIL 794
FAIL 1296
FAIL 1488                               # 3/2000 = 0.15%, all three the same 3 != 2 (logs kept)
$ for i in $(seq 1 100); do cargo test -p faer-ffi --test fork; done
100/100 pass                            # why 100 "reproductions" would have said nothing

# 3. in-process, 3000 create/use/destroy cycles, dumping the extra task and re-reading
iter 1123: before=2 after=3 extra=[(164566, "faer-ffi-0", 'R')]
iter 1648: before=2 after=3 extra=[(166606, "faer-ffi-2", '?')]
iter 305:  before=2 after=3 extra=[(161295, "", '?')]     # comm already unreadable: mid-exit
...
DIAG iters=3000 over=24 still_after_2ms=0
DIAG iters=3000 over=20 never_settled=0 base_first=2 base_last=2 \
     settle_p50=3.256µs settle_p99=4.328µs settle_max=2.099663ms

The extra task is the handle's own worker and it is gone within 2 ms; over 3000 cycles the baseline
never grew (2 tasks throughout) and the count always came back. So destroy joins, and the extra
thread was never a leak — the wait is the observation, not the fix.

Change

faer-ffi/tests/fork.rs only (+30 −4):

  • adds threads_settle(want, bound): spin-read /proc/self/task until it is back to want, bounded
    at a second, so the read no longer samples a worker's exit path;
  • the destroy assertion becomes assert!(threads_settle(before, 1s).is_some(), ...), still named
    "destroy left the handle's workers running" and still checking the same thing.

The #333 regression this test guards is not weakened: with the pool forced back to a shared one
(thread_name removed, the pre-#333 shape) the workers stay parked in threadteam's cache and never
leave, so the wait times out and the assertion still fails:

thread 'a_forked_child_creates_and_uses_a_handle_of_its_own' panicked at faer-ffi/tests/fork.rs:141:5:
destroy left the handle's workers running: 6 threads, 2 before the handle

The rest of the test (the live handle at the fork and create, use, destroy, fork, create, each child
under alarm(20)) is untouched.

Verification

# red, before the fix, on the pinned 1.96.0: the test binary in a loop (logs: /tmp/faer348-repro/binloop/)
$ for i in $(seq 1 2000); do target/debug/deps/fork-5a1ce98634b50021 >$i.log 2>&1 || echo "FAIL $i"; done
FAIL 794
FAIL 1296
FAIL 1488
$ cat 794.log
thread 'a_forked_child_creates_and_uses_a_handle_of_its_own' (118922) panicked at faer-ffi/tests/fork.rs:118:5:
assertion `left == right` failed: destroy left the handle's workers running
  left: 3
 right: 2
test result: FAILED. 0 passed; 1 failed; ... finished in 0.01s

# the guard is still a guard: the same fixed test against a shared pool, i.e. Team::pool_for's
# `.thread_name(...)` removed (the pre-#333 shape, the pool parked in threadteam's cache)
$ cargo test -p faer-ffi --test fork
thread 'a_forked_child_creates_and_uses_a_handle_of_its_own' panicked at faer-ffi/tests/fork.rs:141:5:
destroy left the handle's workers running: 6 threads, 2 before the handle
test result: FAILED. 0 passed; 1 failed; ...

# green, parallel as the harness runs it, 200 consecutive runs (logs: /tmp/faer348-repro/green/)
$ for i in $(seq 1 200); do cargo test -p faer-ffi --test fork >$i.log 2>&1; echo "$i $?" >>status.txt; done
$ awk '$2!=0' status.txt | wc -l
0
$ awk '{print $2}' status.txt | sort | uniq -c
    200 0

# green, 5000 more runs of the test binary
$ for i in $(seq 1 5000); do target/debug/deps/fork-5a1ce98634b50021 >/dev/null 2>&1 || echo "FAIL $i"; done
fails=0 / 5000

# the repository gate for this crate, default parallel settings
$ cargo test -p faer-ffi
test result: ok. 9 passed; 0 failed; 0 ignored  (unittests src/lib.rs)
test result: ok. 1 passed; 0 failed; 0 ignored  (tests/fork.rs)
test result: ok. 0 passed; 0 failed              (doc-tests)
exit=0                                          (full log: /tmp/faer348-repro/test-full.log)

# clippy: the requested -D warnings command cannot pass on main either, unchanged by this branch
$ cargo clippy -p faer-ffi --all-targets -- -D warnings ; echo $?
error: could not compile `t4a-faer` (lib) due to 2401 previous errors ; 101
$ cd /tmp/faer-348-base && git log --oneline -1 && cargo clippy -p faer-ffi --all-targets -- -D warnings
828fd9e perf(lu): ... (#342)
error: could not compile `t4a-faer` (lib) due to 2401 previous errors ; 101
# (code-quality.yml records t4a-faer's warnings as a non-blocking floor and gates only
#  t4a-faer-traits; the 40 `error:` lines are clippy::logic_bug / out_of_bounds_indexing /
#  approx_constant in faer/src, all pre-existing.) Allowing those three so the build reaches this
#  crate: faer-ffi generates 188 warnings and tests/fork.rs adds none of its own
#  (`test "fork" generated 1 warning (1 duplicate)`, the duplicate being lib.rs's missing `# Safety`).

# fmt: --check is red on main too (the pinned 1.96.0 rustfmt is a stable channel, so the
# nightly-only options in rustfmt.toml -- format_code_in_doc_comments, normalize_doc_attributes,
# imports_granularity ... -- are dropped; code-quality.yml marks it continue-on-error). The
# PR #344 form, per file, is clean and unchanged:
$ rustfmt +1.96.0 --edition 2024 --config-path rustfmt.toml --check faer-ffi/tests/fork.rs
origin/main: 0 hunks    this branch: 0 hunks       (also: `rustfmt --check --edition 2024` -> clean)

# the C header is not affected: the change is in a test file, no public item moved
$ git diff --stat origin/main
 faer-ffi/tests/fork.rs | 34 ++++++++++++++++++++++++++++++----

Recorded tasks: cargo test -p faer-ffi -j4 is the CI step that failed; it is green locally
(cargo test -p faer-ffi above, plus the 200- and 5000-run loops on the same binary the harness
loads).

Files

  • faer-ffi/tests/fork.rs — threads_settle and the destroy assertion. No test was renamed, so no
    inventory file moves (this repository has no scripts/ci/*.tsv).

Reproduction artifacts (inlined)

The measurement host is evo_vpn (Linux x86_64, rustc 1.96.0 pinned); its /tmp is not reachable from
the review side, so the probe source and the retained logs are reproduced here verbatim.

The spawn/join control (no faer-ffi in the process) — /tmp/faer348-probe/probe.rs

// Does a joined std::thread still show up in /proc/self/task?
fn threads() -> usize {
    std::fs::read_dir("/proc/self/task").unwrap().count()
}

fn main() {
    let base = threads();
    let mut over = 0usize;
    let iters: usize = std::env::args().nth(1).map_or(100_000, |a| a.parse().unwrap());
    let n: usize = std::env::args().nth(2).map_or(3, |a| a.parse().unwrap());
    for _ in 0..iters {
        let hs: Vec<_> = (0..n).map(|_| std::thread::spawn(|| {})).collect();
        for h in hs {
            h.join().unwrap();
        }
        if threads() > base {
            over += 1;
        }
    }
    println!("base={base} iters={iters} n={n} over={over}");
}
$ cargo run --release -- 200000 3      # 200000 iterations of spawn(3)/join, then one /proc/self/task read
base=1 iters=200000 n=3 over=1609      # 1609/200000 = 0.80% read a task above the baseline

So the transient task is std::thread::join itself, independent of faer-ffi: join returns when the
worker's closure returns, not when the kernel has reaped the task.

The guard still guards: Team::pool_for's .thread_name(...) removed, on head e90c5185

Mutation: faer-ffi/src/lib.rs, Team::pool_for — drop the .thread_name(...) builder call (the pre-#333
shape, pool parked in threadteam's cache). Command and full log
(/tmp/faer348-repro/guard-shared-pool.log):

$ cargo test -p faer-ffi --test fork
   Compiling faer-ffi v0.1.0 (/tmp/faer-348/faer-ffi)
    Finished `test` profile [optimized + debuginfo] target(s) in 1m 11s
     Running tests/fork.rs (target/debug/deps/fork-5a1ce98634b50021)

running 1 test
test a_forked_child_creates_and_uses_a_handle_of_its_own ... FAILED

---- a_forked_child_creates_and_uses_a_handle_of_its_own stdout ----

thread 'a_forked_child_creates_and_uses_a_handle_of_its_own' (184853) panicked at faer-ffi/tests/fork.rs:141:5:
destroy left the handle's workers running: 6 threads, 2 before the handle

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 1.01s

This fails at the modified assertion (fork.rs:141, "6 threads") after the one-second bound, i.e. the
wait does not paper over a parked pool — it times out, as the original single read would have.

The in-process diagnostic — /tmp/faer348-repro/diag2.log

diag runs 3000 create/use/destroy cycles in one process, records whether the count is back after
destroy, and re-reads /proc/self/task while listing the extra task:

iter 306: before=2 after=3 extra=[]          # the extra entry is already gone when listed
...
DIAG iters=3000 over=20 never_settled=0 base_first=2 base_last=2 \
     settle_p50=Some(3.256µs) settle_p99=Some(4.328µs) settle_max=Some(2.099663ms)

never_settled=0: every one of the 20 overshoots came back; the baseline (base_first/base_last) never
grew over 3000 cycles, so nothing leaks. Both artifacts were produced at this head with the pinned
toolchain (rustc 1.96.0); the mutation run used a separate checkout at /tmp/faer-348 on evo_vpn.

…them

`faer-ffi/tests/fork.rs` asserted that `/proc/self/task` is back to its
pre-`create` size immediately after `libfaer_v0_23_team_destroy`, and that read
races the workers' exit: `destroy` joins them (threadteam's dedicated-pool drop
joins each std handle), but a joined task's `/proc` entry outlives the join,
because `std`'s `join` returns when the worker's closure has finished, not when
the task is gone. The single read therefore sometimes samples the teardown and
reports "destroy left the handle's workers running: 3 != 2", which is what
#348 saw on CI (run 42629271729).

Reproduced on the pinned 1.96.0 at 3 of 2000 runs of the test binary, with the
extra entry still in `/proc` and gone again within 2 ms; over 3000
create/use/destroy cycles the baseline never grew (2 tasks throughout) and the
count always came back, so nothing leaks and `destroy` does join. A plain
`std::thread::spawn` + `join` with no faer-ffi in the process shows the same
over-count, so the observation, not the pool, is what was wrong.

Wait for the count to come back, bounded at a second, instead of reading it
once. A pool left parked in threadteam's cache — the #333
regression this test guards — never leaves, so the wait times out and the
assertion still fails: with the handle's pool forced back to a shared one the
test reports "6 threads, 2 before the handle".
@shinaoka

shinaoka commented Nov 9, 2026

Copy link
Copy Markdown
Member Author

GPT-6.1-sol adversarial review

CRITICAL: none
NEEDS_CHANGES: 0
UNVERIFIED: 2

Critical (must not merge)

none

Needs changes

none

Unverified claims

  • faer-ffi/tests/fork.rs:108–114 — The comment attributes the transient task count to post-join kernel teardown and cites measured frequencies and settling times. The diff contains neither the control probe nor the diagnostic recorder, and I cannot read /tmp/faer348-repro on this machine. To verify, provide the probe source and retained logs, then repeat the spawn/join control and create/use/destroy measurements on the stated Linux toolchain; the polling change alone does not establish the claimed cause.

  • faer-ffi/tests/fork.rs:143–148 — The PR asserts that removing Team::pool_for’s thread_name still makes this modified assertion fail, but the mutation and its execution evidence are not included in the diff; I cannot read the cited local logs. To verify, remove that configuration on the exact reviewed head, run cargo test -p faer-ffi --test fork, and retain the output showing failure at this assertion rather than an unrelated failure. The reported successful unmodified runs do not establish mutation sensitivity.

Checked and fine

  • Read the complete test at e90c518555bb9fa81c97cd99fe818aeab3bd9076; both fork scenarios and their child alarms remain present.
  • GitHub reports completed successful checks attached to that exact head; individual job steps and skip conditions were not inspected.
  • No tests or mutation experiments were run locally; runtime and leak-detection claims remain unverified as listed above.

Reviewed head: e90c518555bb9fa81c97cd99fe818aeab3bd9076 at 2026-11-09T15:07:48Z. This review is valid only for that commit: if the head has moved, it is a review of a tree that is not being merged.
Automated (gpt_review.sh). This is an enumeration of counterexamples, not a verdict; the merge decision stays with a human.

@shinaoka
shinaoka merged commit 82c6a24 into main Nov 9, 2026
9 checks passed
@shinaoka
shinaoka deleted the test/348-fork-settle branch November 9, 2026 15:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant