ci(probe): record emulator health-check durations per iteration - #787
Conversation
592700d to
9f67e9b
Compare
armando-navarro
left a comment
There was a problem hiding this comment.
Thanks for this, and for putting the reasoning in the workflow file rather than only in the PR description. The code itself is right and I have run it.
I am requesting changes for one thing only, the wrong sentence about the vitest reporter. Everything else here is yours to take or leave.
On the timing question itself
The durations for all 120 iterations are recoverable from the logs you already uploaded, they show no separation between the runs that failed and the runs that passed, and I think the reason is that the health check times a write while the two failing tests wait on the Listen stream.
The reporter claim is not right, and this is the one thing I am blocking on
The new comment and the commit message both say the default reporter prints no per-test line on a passing run. What I found instead:
- It prints one for any test over the 300ms slow threshold, pass or fail.
- In your artifact, firestore and database health checks appear on all 120 iterations, including the 111 that passed. That is how I recovered the durations.
The json reporter is still the right call, for a better reason: the log is censored at 300ms, so it drops auth entirely and truncates everything else at the fast end. As the comment stands, someone could test the claim, find durations in the log, and conclude the reporter was not needed.
This is the only thing I am blocking on, and purely because of where it ends up. The comment stays editable. The commit message does not, once this squashes into main, so a wrong statement about the tooling would sit in the history for whoever picks it up next.
Nothing else in the review needs to happen. Push the fix and I will re-review straight away.
Three small ones in the summary table
- The
ncolumn counts rows for that outcome, but the duration cells are computed only over the finite ones, sinceseriesfilters onNumber.isFiniteandNumber("na")isNaN. So an infra row can readn = 5off two actual measurements. The footnote below the table gives a total for missing firestore durations but does not attribute it to a row. q(a, 0.5)takes the upper of the two middle values, so at n = 2 the median and max cells print the same number. The two compound: five infra rows of which two had durations, 1200 and 1400, render asnof 5 with a firestore cell of1400 / 1400. The flake row is where n will be smallest, 1 to 3 per arm last time.- The table pools arms.
probe-iterations.tsvcarries the arm in column 2 and the summary drops it, so a dispatch with both arms puts baseline and override rows into one distribution while the counts tables above stay per-arm. The baseline-only default makes this rare rather than gone.
The grpc-js override was measured and does not fix the flake (baseline 5/60 vs override 4/60, p = 1.0), so the default arm list drops to baseline alone. The arm stays available as a dispatch input. What replaces it is timing. Firestore's health check is a bare addDoc round trip, and every waitFor in test/firestore.test.tsx uses the 1000ms default, so a slow round trip would explain failures landing at 1058ms and 1142ms. Each iteration now records that duration for firestore, auth and database into probe-iterations.tsv, and the summary compares distributions across outcomes. All three because a slow firestore round trip only explains FirebaseExtended#776 if firestore is slow specifically; if every emulator is slow together, the cause is runner-wide contention instead. The durations come from vitest's json reporter rather than the log, because the default reporter prints a per-test line only above its 300ms slow threshold: the log drops auth entirely and censors the fast end of the other two, so it cannot support a comparison across outcomes. Extraction is scoped by file path, since all three test files open with a test named "double check - emulator is running". The summary reports each arm separately, gives every duration cell its own count of measured iterations, and takes the mean of the two middle values at even n. Refs FirebaseExtended#776
9f67e9b to
af9f075
Compare
|
You're right on the reporter, and I ran it rather than taking it on reading: standalone vitest 4.1.10, three passing tests at 0ms, 150ms and 400ms, default reporter. Only the 400ms one printed a line. So the log is censored at the slow threshold rather than silent on passing runs, which is your reason and the better one. Fixed in the workflow comment and in the commit message. Took the three table items as well:
Verified against fabricated rows reproducing your case (5 infra, two measurements at 1200 and 1400): reads On the listen-vs-write point: if the health check times a write while the two failing tests wait on the Listen stream, this probe is timing the wrong round trip. Dispatch it once merged anyway, or instrument the Listen path first? |
armando-navarro
left a comment
There was a problem hiding this comment.
Thanks for turning this around so fast, and for running the reporter case rather than taking it on reading. Approving.
One optional wording fix
Take it or leave it, and it changes no behavior.
The workflow comment and the commit message both say the default reporter prints a per-test line "only above its 300ms slow threshold". There is a second case:
- Every test in a file that failed prints regardless of its duration.
- The last branch of
printTestCasereadselse if (this.renderSucceed || moduleState === "failed"). - Running vitest 4.1.9 over two files, the passing one printed only its 400ms test, while the failing one also printed its 1ms and 152ms tests.
Worth a sentence because it sharpens your own argument. The log is not censored uniformly, it is censored in a way that tracks outcome: a file that passed gives up only its slow tests, a file that failed gives up every test in it. The bias runs along the same axis the summary compares, which is a better reason to prefer the json reporter than the fast end being cut off.
|
On your listen versus write question: I would dispatch it, and treat instrumenting the Listen path as the next step rather than a prerequisite. Two reasons to dispatch as it stands:
I would not wait on the firestore column to settle #776 though, because I think it will come back flat. The durations for that column turn out to be recoverable from run 31223456796 for all 120 iterations, and the flake and pass distributions sit on top of each other. Numbers and method are in a comment on #776. On instrumenting Listen, here is what made me raise it in the first place:
Which test to key on is your call, and if you think the write round trip is the better proxy after all I would like to hear why. |
Why
The grpc-js override was measured and does not fix the flake: 120 full-suite runs gave baseline 5/60 vs override 4/60, Fisher exact p = 1.0. So the default arm list drops to
["baseline"], with the arm kept as a dispatch input rather than deleted.What replaces it is timing. Firestore's health check is a bare
addDocround trip, and everywaitForintest/firestore.test.tsxuses the 1000ms default, which would explain the failures landing at 1058ms and 1142ms.What changes
Each iteration records the health-check duration for firestore, auth and database into a new
probe-iterations.tsv, and the summary compares median and max across outcomes:All three, not firestore alone: a slow firestore round trip only explains #776 if firestore is slow specifically. The illustrative shape above, with everything rising together, would instead say runner-wide contention and send the fix elsewhere.
Two implementation notes
Durations come from vitest's json reporter, not the log. The default reporter prints no per-test line at all on a passing run, so the log would yield durations only for runs that went wrong. The json reporter runs alongside it, leaving the existing classifier greps untouched.
Extraction is scoped by file path. All three test files open with a test named
double check - emulator is running, so matching on the title would record whichever vitest emitted first.Verification
1623 na na, thenas correct for firestore-only mode.2246 111 786, so each column takes its own file.na, never a bogus0.workflow_dispatchis only offered for workflows on the default branch, so this cannot be run from the branch. Merging is what makes it dispatchable, and the first real run is the first proof, same as #780.Refs #776, and does not close it. #783 stays open too.