ci: measure and cut the store-test step (#126) by Hafeok · Pull Request #136 · Hafeok/Varve

Hafeok · 2026-10-19T14:02:06Z

What this changes, and why

Work in progress for #126. Test Varve.Store takes 27–38 min on Windows and 10–16 on Ubuntu since #116, and every PR pays it. This PR measures first and then changes things, in this order:

Measure. A TRX from every dotnet test step in ci.yml, azure-objects.yml and publish.yml, uploaded if: always(), and eng/test-durations.cs (BCL only) writing the 20 slowest tests and the classes by busy time into the job summary. (pushed; this run is the baseline)
Guards. timeout-minutes per step and --hangdump, sized from step 1.
Windows. TEMP/TMP on the runner's temp drive, and a run without the existing Defender exclusion (ADR 0090), each measured on its own run.
The slow tests. For each test over 60 s, where the time goes, then either a fix or fewer land-gate iterations, with the full count in a nightly run.
Parallelism. From the per-class spans.

Targets: the store step under 12 min on Windows and under 6 on Ubuntu.

What was measured

Pending the first CI run.

What was found

Pending.

What is left

Everything after step 1.

Refs #126 (the last commit carries the closing trailer; no closing keyword here, per #108).

Generated by Claude Code

…ts in the summary The Test Varve.Store step takes 27-38 minutes on Windows since #116 and nothing in the log says where: Microsoft.Testing.Platform prints only failed and skipped tests, and no run kept a report. Every dotnet test step in ci.yml, azure-objects.yml and publish.yml now writes a TRX under artifacts/test-results/<project>, and every job that tests uploads that folder, pass or fail. eng/test-durations.cs, BCL only, reads a run's TRX and writes the 20 slowest tests and the classes by busy time, with the minutes into the run at which each class started and finished, to the job summary; the build job runs it after the store step, and storage (services) after its Objects run. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

…er ADR 0007 No step that runs Varve.Store.Tests can name a hung test: the platform prints nothing until a test ends, and VSTest's --blame-hang-timeout is not available on Microsoft.Testing.Platform. The HangDump extension writes a dump, and the tests in flight, when no test has reported for a set time. A test-time register entry under ADR 0007, which admits TrxReport for the same reason, by a dated amendment with its ruling HangDumpForTheStoreTests, filed unaccepted (ADR 0066). 2.4.1, TrxReport's platform line; MIT and managed, as is Microsoft.Diagnostics.NETCore.Client, which it brings. Referenced by Varve.Store.Tests alone. The workflow flags follow with the time limits, sized from the measured run. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

The platform's test name repeats the class, which has its own column. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

No step that runs Varve.Store.Tests had a time limit, so a hang held its runner to the six-hour job limit and named no test. Each now has timeout-minutes at about twice this pull request's first measured run, and --hangdump below it, which writes a dump and a log of the tests in flight when none has ended for the given time: build (windows-latest), Test Varve.Store: 32m 41s -> 65 min, dump 15m build (ubuntu-latest), Test Varve.Store: 15m 52s -> 35 min, dump 15m storage (services), Test against them: 4m 12s -> 10 min, dump 5m publish.yml, Test Varve.Store (Ubuntu): as the build's Ubuntu leg azure-objects.yml, the two contract classes: as storage (services) The longest stretch with no test ending was 9.0 minutes on Windows, 6.6 on Ubuntu and 1.5 against the services, so the dumps do not fire on a green run. The dump lands in the results directory each job already uploads. Checked locally with a test that never ends and a 20 s limit: the log read "[00:00:19] Varve.Store.Tests.HangProbe.a_test_that_hangs", a dump was written beside it, and the run exited 7. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

Hafeok · 2026-10-19T14:51:44Z

Baseline: `Test Varve.Store` before any change (run 39265320616, `1d543f2`)

Step	ubuntu-latest	windows-latest
build → Test Varve.Store	15m 52s	32m 41s
storage (services) → Test against them	4m 12s	n/a

Longest stretch with no test ending: 9.0 min (Windows), 6.6 (Ubuntu), 1.5 (services).

windows-latest

299 results from 1 TRX; first start to last end 32m 34s; busy time (sum of durations) 88m 25s.

#	Duration	Outcome	Class	Test
1	32m 30s	Passed	Objects.ObjectFaultTests	after_a_fault_at_any_request_the_dataset_reopens_at_the_last_closed_commit_with_nothing_lost_or_doubled(seed: 9201)
2	11m 03s	Passed	Faults.FaultInjectionTests	a_crash_during_recovery_recovers
3	4m 12s	Passed	Objects.ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
4	3m 16s	Passed	Objects.ObjectPropertyTests	the_store_in_objects_agrees_with_the_model_with_the_projection_in_derived_runs_and_segments_consolidated
5	2m 56s	Passed	Objects.ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)
6	2m 31s	Passed	Faults.FaultInjectionTests	a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6202, steps: 24, imagesPerPoint: 6)
7	2m 29s	Passed	Objects.ObjectPropertyTests	the_store_in_objects_agrees_with_the_reference_model
8	2m 24s	Passed	FilePropertyTests	the_store_on_files_agrees_with_the_reference_model
9	2m 23s	Passed	Objects.ObjectExtentTests	a_fault_at_any_extent_write_or_catalog_swap_never_leaves_a_catalog_naming_a_missing_extent
10	2m 14s	Passed	Faults.FaultInjectionTests	a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6151, steps: 32)
11	2m 06s	Passed	Faults.FaultInjectionTests	a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6152, steps: 32)
12	2m 01s	Passed	Faults.FaultInjectionTests	a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6102, steps: 24)
13	1m 37s	Passed	Faults.FaultInjectionTests	a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6101, steps: 24)
14	1m 27s	Passed	FilePropertyTests	the_store_on_files_agrees_with_the_model_with_the_projection_in_derived_runs
15	1m 15s	Passed	FilePropertyTests	a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
16	1m 11s	Passed	Faults.FaultInjectionTests	a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6201, steps: 24, imagesPerPoint: 6)
17	1m 04s	Passed	PerGraphConcurrencyTests	the_graph_version_index_rebuilt_from_the_log_equals_the_one_maintained(seed: 9301)
18	1m 02s	Passed	Objects.ObjectPropertyTests	the_store_in_objects_agrees_with_the_model_with_many_records_and_segments
19	51.7s	Passed	PerGraphConcurrencyTests	the_graph_version_index_rebuilt_from_the_log_equals_the_one_maintained(seed: 9302)
20	47.6s	Passed	FilePropertyTests	the_same_requests_give_byte_identical_log_directories

Classes by busy time; from and to are minutes into the run of the class's first start and last end.

Class	Tests	Busy	From	To
Objects.ObjectFaultTests	1	32m 30s	0.1	32.6
Faults.FaultInjectionTests	13	23m 31s	0.0	23.5
Objects.ObjectPropertyTests	10	14m 57s	1.7	16.7
FilePropertyTests	9	7m 17s	7.7	15.0
Objects.ObjectExtentTests	4	2m 33s	5.1	7.6
PerGraphConcurrencyTests	5	1m 56s	2.8	4.7
BulkLoadTests	8	1m 43s	0.0	1.7
LogPropertyTests	9	1m 10s	0.1	1.2
Objects.ObjectColdStartTests	2	26.2s	1.9	2.4
ReplicaTests	1	20.0s	2.4	2.7
ModelTests	5	19.8s	1.4	1.7
Objects.ObjectMigrationTests	1	17.7s	15.2	15.5
Objects.ObjectStorageTests	8	16.1s	4.8	5.1
Objects.ObjectEpochPropertyTests	1	11.5s	15.5	15.6
DerivedTests	6	11.0s	1.7	1.9
Format3Tests	1	10.1s	1.2	1.4
Objects.AzureCredentialTests	4	6.4s	7.6	7.7
ExtentTests	2	3.9s	0.0	0.1
AllocationTests	6	3.2s	15.1	15.1
FileStorageTests	10	3.2s	2.7	2.8

ubuntu-latest

299 results from 1 TRX; first start to last end 15m 47s; busy time (sum of durations) 24m 36s.

#	Duration	Outcome	Class	Test
1	6m 36s	Passed	Faults.FaultInjectionTests	a_crash_during_recovery_recovers
2	2m 29s	Passed	Faults.FaultInjectionTests	a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6151, steps: 32)
3	1m 29s	Passed	Objects.ObjectFaultTests	after_a_fault_at_any_request_the_dataset_reopens_at_the_last_closed_commit_with_nothing_lost_or_doubled(seed: 9201)
4	1m 27s	Passed	Faults.FaultInjectionTests	a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6152, steps: 32)
5	1m 07s	Passed	Faults.FaultInjectionTests	a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6102, steps: 24)
6	59.5s	Passed	LogPropertyTests	a_log_cut_at_any_byte_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
7	54.6s	Passed	Faults.FaultInjectionTests	a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6101, steps: 24)
8	52.1s	Passed	Faults.FaultInjectionTests	a_lost_directory_entry_is_a_segment_never_created
9	44.8s	Passed	Faults.FaultInjectionTests	a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6201, steps: 24, imagesPerPoint: 6)
10	40.3s	Passed	Faults.FaultInjectionTests	a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6202, steps: 24, imagesPerPoint: 6)
11	38.1s	Passed	Faults.FaultInjectionTests	a_directory_copied_mid_write_opens_on_the_copy
12	31.5s	Passed	Objects.ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
13	28.7s	Passed	Objects.ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)
14	28.3s	Passed	Objects.ObjectPropertyTests	the_store_in_objects_agrees_with_the_reference_model
15	21.9s	Passed	LogPropertyTests	a_log_cut_at_any_byte_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)
16	16.8s	Passed	BulkLoadTests	a_crash_at_every_operation_of_a_load_leaves_the_dataset_at_the_previous_head
17	16.2s	Passed	FilePropertyTests	a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
18	15.7s	Passed	Objects.ObjectPropertyTests	the_store_in_objects_agrees_with_the_model_with_the_projection_in_derived_runs_and_segments_consolidated
19	15.3s	Passed	FilePropertyTests	a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)
20	15.2s	Passed	FilePropertyTests	the_store_on_files_agrees_with_the_model_with_the_projection_in_derived_runs

Classes by busy time; from and to are minutes into the run of the class's first start and last end.

Class	Tests	Busy	From	To
Faults.FaultInjectionTests	13	15m 43s	0.1	15.8
Objects.ObjectPropertyTests	10	2m 02s	0.1	2.2
LogPropertyTests	9	1m 38s	0.8	2.4
Objects.ObjectFaultTests	1	1m 29s	2.4	3.9
FilePropertyTests	9	1m 16s	0.1	1.4
BulkLoadTests	8	46.3s	0.0	0.8
ModelTests	5	32.5s	1.5	2.1
PerGraphConcurrencyTests	5	10.0s	2.2	2.3
Objects.AzureCredentialTests	4	6.4s	1.4	1.5
Objects.ObjectExtentTests	4	6.3s	2.4	2.5
Objects.ObjectStorageTests	8	5.8s	2.1	2.2
GroupCommitTests	9	4.8s	0.0	0.1
ExtentTests	2	4.4s	2.2	2.3
AllocationTests	6	4.3s	0.0	0.1
KeyBlockTests	4	4.1s	2.3	2.3
Objects.ObjectMigrationTests	1	2.7s	0.0	0.0
Objects.ObjectColdStartTests	2	2.5s	2.4	2.4
ReplicaTests	1	2.3s	0.0	0.0
DictionaryTests	5	2.2s	2.3	2.4
DerivedTests	6	1.7s	0.1	0.1

storage (services): the Objects namespace against Azurite and RustFS

103 results from 1 TRX; first start to last end 3m 27s; busy time (sum of durations) 6m 54s.

#	Duration	Outcome	Class	Test
1	3m 27s	Passed	AzuriteFaultTests	after_a_fault_at_any_request_over_http_the_dataset_reopens_with_nothing_lost_or_doubled
2	1m 35s	Passed	ObjectFaultTests	after_a_fault_at_any_request_the_dataset_reopens_at_the_last_closed_commit_with_nothing_lost_or_doubled(seed: 9201)
3	15.1s	Passed	AzuriteAdapterTests	a_list_pages_past_five_thousand_names
4	13.8s	Passed	ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)
5	9.4s	Passed	ObjectExtentTests	a_fault_at_any_extent_write_or_catalog_swap_never_leaves_a_catalog_naming_a_missing_extent
6	8.9s	Passed	ObjectPropertyTests	a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)
7	8.9s	Passed	ObjectPropertyTests	the_store_in_objects_agrees_with_the_reference_model
8	8.4s	Passed	ObjectPropertyTests	the_store_in_objects_agrees_with_the_model_with_many_records_and_segments
9	6.3s	Passed	AzureCredentialTests	a_token_reaches_no_message_and_no_rendering_whatever_the_store_answers
10	6.1s	Passed	ObjectPropertyTests	the_store_in_objects_agrees_with_the_model_with_the_projection_in_derived_runs_and_segments_consolidated
11	5.0s	Passed	ObjectPropertyTests	the_same_requests_give_byte_identical_logs_on_files_and_in_objects
12	4.9s	Passed	ObjectStorageTests	a_sealed_segment_is_consolidated_byte_for_byte_and_only_fence_chunks_remain
13	2.9s	Passed	ObjectMigrationTests	a_dataset_moved_from_a_directory_to_a_container_and_back_answers_identically
14	2.6s	Passed	RustFsStorageContractTests	a_dataset_commits_checkpoints_reopens_and_reads_as_of_over_the_backend
15	2.5s	Passed	AzuriteStorageContractTests	a_dataset_commits_checkpoints_reopens_and_reads_as_of_over_the_backend
16	2.1s	Passed	ObjectColdStartTests	a_cold_start_reads_the_log_only_from_the_catalogs_cursor_and_serves_what_the_whole_log_serves
17	1.4s	Passed	AzuriteStorageContractTests	a_blob_is_invisible_until_published_and_an_unpublished_writer_leaves_nothing
18	1.2s	Passed	AzuriteStorageContractTests	a_sealed_segment_refuses_appends_and_only_the_newest_may_be_open
19	1.1s	Passed	ObjectEpochPropertyTests	a_superseded_writer_attempts_only_its_own_slots_or_the_fence_and_appends_nothing_after_it
20	1.0s	Passed	AzuriteStorageContractTests	an_open_blob_keeps_its_bytes_when_its_name_is_replaced

Classes by busy time; from and to are minutes into the run of the class's first start and last end.

Class	Tests	Busy	From	To
AzuriteFaultTests	1	3m 27s	0.0	3.5
ObjectFaultTests	1	1m 35s	0.4	2.0
ObjectPropertyTests	10	52.3s	0.0	0.9
AzuriteAdapterTests	4	15.8s	0.0	0.3
ObjectExtentTests	4	10.1s	0.4	0.6
AzuriteStorageContractTests	9	7.8s	0.2	0.3
AzureCredentialTests	4	6.4s	0.1	0.2
ObjectStorageTests	8	5.8s	0.3	0.4
RustFsStorageContractTests	9	4.5s	0.0	0.1
ObjectMigrationTests	1	2.9s	0.0	0.0
ObjectColdStartTests	2	2.4s	0.4	0.4
RustFsObjectStoreContractTests	7	1.2s	0.3	0.4
AzuriteObjectStoreContractTests	7	1.1s	0.6	0.6
ObjectEpochPropertyTests	1	1.1s	0.3	0.3
ObjectStorageContractTests	9	0.1s	0.6	0.6
S3CredentialTests	3	0.1s	0.0	0.0
MemoryObjectStoreContractTests	7	0.1s	0.0	0.0
AzureAccountObjectStoreContractTests	7	0.0s	0.0	0.0
AzureAccountStorageContractTests	9	0.0s	0.1	0.1

What they show

Windows' tail is ObjectFaultTests: 32m 30s on Windows, 1m 29s on Ubuntu (22×). ObjectPropertyTests is 15m busy on Windows against 2m. Both run the object-storage backend over an in-memory store, with a local cache directory per run on the real disk under %TEMP% (C:). The tests' timers are instant and the cache does not flush, so it is not ADR 0090's cost. The disk work on C: is the suspect, which step 3's TEMP change targets directly.
Ubuntu's tail is FaultInjectionTests: its 13 tests are one class, so they run one after another, 15m 43s from minute 0.1 to 15.8, while everything else is done by minute 3.9.
a_crash_during_recovery_recovers is the largest single file-backend test: 6m 36s (Ubuntu), 11m 03s (Windows).

Generated by Claude Code

…ry drive On windows-latest the temporary folder is the profile's, on C:, the system drive. Every test dataset directory and every object-storage cache directory is made there, and the object-storage suites make one per run: ObjectFaultTests took 32m 30s on Windows and 1m 29s on Ubuntu in this pull request's first run, and ObjectPropertyTests 15 minutes busy against 2. From the step before the tests, TEMP and TMP name the runner's own temporary folder instead, on D: with the workspace. Windows only; the build steps before it are unchanged. Measured on its own run. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

…126's store-test measurement main moved 49 commits since this branch began at 9d48ccc, and the pull request could not merge, so CI did not run on its head. One conflict: ADR 0007 gained an amendment on main (the SHACL suites, 2026-10-17) and one here (HangDump, 2026-10-19); both are kept, in date order. The store's test suite gained tests on main (ServiceFollowerTests and ObjectStorageTests' additions), so the next run's step time is compared with the baseline test by test as well as whole. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

The object-storage backend keeps its local cache in a FileStorage, and every open of one wrote derived/LOCK.owner and derived/.gitignore beside and flushed each before its rename. ObjectFaultTests opens one at every restart of its workload: of the 88,073 device flushes in one run, 8,478 were the owner and 8,478 the ignore file (strace, four cores locally). On a disk where a flush is milliseconds, as the Windows runner's is, that is minutes of the test, and production pays two flushes an open. Neither file is state. The owner is read only for a refusal's message (ADR 0075), already tolerating a read that fails; the ignore file is read by tools and never by the store. ADR 0073's list of what the file backend flushes names neither. Both are still written beside and renamed, so no reader sees one half written, and no longer flushed. So that a power loss cannot leave derived/ in version control, the ignore file is now rewritten at open whenever it is not exactly "*\n", where before it was written only when absent: a_torn_ignore_file_is_whole_again_after_an_open holds that, and fails on the old open for an empty, a cut and a zeroed file. Storage format section 2 says so. The flushes left in that run, 70,908, are all the commit index's, and stay: see the next commit. ObjectFaultTests alone on four cores locally, on disk: 2m 11s before, 1m 50s after. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

…where verified, is a miss The object-storage backend keeps the commit index below the catalog as a blob in its local cache (ADR 0139), and production reuses that cache across restarts (CachePath/<dataset>). Opened again on a copy of the cache whose blob is cut short, or has a byte of its last entry, its directory or its derived header zeroed, a follower serves every position as of, by time and from the feed exactly as before: a miss, rebuilt from the log. Cut at every byte of those and every sixteenth before them, and zeroed at every byte of them: 23 s alone locally. What it does not hold, and does not claim: the entries before the last are not verified when the blob is read, only the last against the catalog's. Zeroing any of their bytes, all 23 x 80 tried, gave 985 failures of 1,920: a different history by time (the timestamp, the canonical counter) or LogVerificationException (the header hash, the segment and offset). A crash cannot produce such a blob because it is published by a temporary file flushed before its rename (ADR 0073), so that flush stays: 70,908 of ObjectFaultTests' flushes. Verifying the entries on read is a format or design decision, not this pull request's. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

The process-crash suites replayed the whole workload from scratch for every byte at which they cut a write: a write of 60 bytes to the log was 60 runs, identical up to the operation they crashed at. The batched suite replayed three more for its power-loss images, which the other power-loss suite already draws from one run. Profiled alone on four cores, replaying was 1m 42s of the process-crash theory's 2m 34s and 1m 47s of the batched theory's 3m 31s. The simulated file system now keeps the write a crash stopped, and Image(Process, random, inFlightBytes) applies its first bytes to the image, which is what a run crashed at that cut leaves. Each operation is crashed once and every cut and image is built from that run; the images verified, and the injection points counted, are the same as before. an_image_cut_from_one_crash_is_the_image_of_a_crash_at_that_cut holds that claim: for every tenth write of the unbatched and the batched workloads, at every cut the suites make, the built image and a replayed run's are the same files, bytes and seals, with the same acknowledged position. Cutting one byte short makes it fail at the second operation. Locally, alone: process crash 2m 34s to 1m 15s, batched 3m 31s to 2m 12s, the new check 7s. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

…l request a_crash_during_recovery_recovers crashed the workload at every fifth of its 1,428 operations and then crashed each recovery at every operation it performs: 57,679 points, 6m 36s on Ubuntu and 11m 03s on Windows in this pull request's first run, 8m 36s alone on four cores locally. No sleep, retry or rebuilt fixture: profiled, replaying the workload was 2.4 s of it, and verifying each recovered image the rest (as-of reads at every position 5m 47s, open 1m 14s, commit and maintenance 45 s, reopen 36 s), which is what the test proves. It now crashes the workload at every 25th operation by default, 11,753 points and 1m 51s alone locally, and at every VARVE_FAULT_RECOVERY_STRIDE th when that is set. The nightly run sets 5, which is today's search exactly; the pull request's points are a subset of it. Depth.Of reads such a variable. docs/testing.md section 7 lists every variable with its pull request and nightly values. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

FaultInjectionTests held its 13 tests in one class, and xunit runs a class's tests one after another: in this pull request's first run the class was busy from the step's first minute to its last on Ubuntu (15m 43s of 15m 47s) and for 23m 31s on Windows, while every other class was done by minute 3.9 on Ubuntu. The tests are independent: each builds its own SimulatedFileSystem in memory, and what they share is the workload and its checks, which are static and stateless. They now sit in eight nested classes, by kind of fault (ProcessCrash, BatchedCrash, PowerLoss, DerivedAndCheckpoints, CopiedMidWrite, Regressions, CrashDuringRecovery, DeepExploration), beside the workload in the static class FaultInjectionTests, whose name ADR 0090, its decision set and docs/testing.md cite. No test changes. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

A test whose search a pull request now runs a share of keeps its full depth behind a variable (docs/testing.md section 7). This workflow sets every one of them, at the value the gate used before #126, and runs Varve.Store.Tests on Ubuntu and Windows every night on main, with its TRX uploaded and its slowest tests in the summary, a two-hour limit and a 30-minute hang dump. Not a required check: it tests what has landed. #129 may make it a release's gate. It starts no container, so it adds no image to .github/ci-images.yaml; the services legs stay in ci.yml. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

Hafeok · 2026-10-20T19:18:18Z

`TEMP` on the runner's temporary drive: run 39412157646, `8faf8dc`, against the baseline (run 39265320616, `1d543f2`)

8faf8dc is 691322b (TEMP and TMP on D: for the Windows test steps) merged with 49 commits of main. CI never ran on 691322b itself because the PR could not merge.

`Test Varve.Store`	Baseline	Second sample (`5db693c`)	This run	Change
windows-latest	32m 41s	26m 26s	21m 0s	−11.7 min
ubuntu-latest	15m 52s	16m 48s	10m 36s	−5.3 min
storage (services)	4m 12s	4m 33s	5m 4s	+0.9 min

Where the drop came from

Windows: TEMP, about 9.1 of the 11.7 minutes. The tests that work on the real temporary folder fell 80–90% (below: ObjectFaultTests 32m 30s → 4m 25s, ObjectPropertyTests, FilePropertyTests, ObjectExtentTests). Their caches and dataset directories were on C:, the system disk, and are now on D:. ObjectFaultTests was the tail and ended at minute 32.6; it now ends at 4.5. The step's next tail, FaultInjectionTests, ended at 23.5 in the baseline, so TEMP alone takes the step to about 23.5.
Windows: about 2.6 minutes are runner speed. FaultInjectionTests runs over the in-memory simulated file system, which TEMP does not reach: 23.5 → 20.9 (−11%), with every test in it 5–15% faster.
Ubuntu: all 5.3 minutes are runner speed, none is code. TEMP is a Windows-only step. Every in-memory, CPU-bound test is about 30% faster: FaultInjectionTests 15.8 → 10.6, LogPropertyTests −47 to −65%. The disk tests barely moved: ObjectFaultTests −4%, ObjectPropertyTests (64 B records) +1%. The merged commits add a follower guard and attachments to the sequencer, which these tests do not time, and 13 store tests that take 0.8 s here (1.8 s on Windows). The two earlier Ubuntu samples were 15m 52s and 16m 48s, so this runner was a fast one. The target has to hold on an ordinary one.
storage (services) +0.9 min: AzuriteFaultTests +26 s (container round trips, not touched), plus main's 12 new tests (2.3 s). This step runs on Ubuntu, so TEMP does not apply.

windows-latest

First start to last end: 32m 34s → 20m 54s. Busy time of the 299 tests in both runs: 88m 25s → 32m 14s; of the 13 tests main added: 1.8s.

#	Test	Baseline	This run	Change
1	Faults.FaultInjectionTests · a_crash_during_recovery_recovers	11m 03s	10m 10s	-8%
2	Objects.ObjectFaultTests · after_a_fault_at_any_request_the_dataset_reopens_at_the_last_closed_commit_with_nothing_lost_or_doubled(seed: 9201)	32m 30s	4m 25s	-86%
3	Faults.FaultInjectionTests · a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6151, steps: 32)	2m 14s	2m 07s	-5%
4	Faults.FaultInjectionTests · a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6152, steps: 32)	2m 06s	2m 06s	-0%
5	Faults.FaultInjectionTests · a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6102, steps: 24)	2m 01s	1m 54s	-6%
6	Faults.FaultInjectionTests · a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6202, steps: 24, imagesPerPoint: 6)	2m 31s	1m 31s	-40%
7	Faults.FaultInjectionTests · a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6101, steps: 24)	1m 37s	1m 26s	-12%
8	Faults.FaultInjectionTests · a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6201, steps: 24, imagesPerPoint: 6)	1m 11s	57.6s	-19%
9	Objects.ObjectPropertyTests · a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	4m 12s	46.1s	-82%
10	Objects.ObjectPropertyTests · the_store_in_objects_agrees_with_the_model_with_the_projection_in_derived_runs_and_segments_consolidated	3m 16s	32.0s	-84%
11	Objects.ObjectExtentTests · a_fault_at_any_extent_write_or_catalog_swap_never_leaves_a_catalog_naming_a_missing_extent	2m 23s	26.4s	-82%
12	Objects.ObjectPropertyTests · the_store_in_objects_agrees_with_the_reference_model	2m 29s	24.5s	-84%
13	Objects.ObjectPropertyTests · a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 6710...	2m 56s	22.3s	-87%
14	FilePropertyTests · a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	1m 15s	20.9s	-72%
15	LogPropertyTests · a_log_cut_at_any_byte_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	26.8s	16.1s	-40%
16	BulkLoadTests · a_bulk_load_equals_the_same_operations_committed_the_ordinary_way	32.7s	15.4s	-53%
17	FilePropertyTests · the_store_on_files_agrees_with_the_reference_model	2m 24s	15.1s	-90%
18	FilePropertyTests · the_store_on_files_agrees_with_the_model_with_the_projection_in_derived_runs	1m 27s	14.2s	-84%
19	BulkLoadTests · the_open_scan_holds_a_bounded_part_of_any_commit	16.2s	13.0s	-20%
20	Faults.FaultInjectionTests · a_lost_directory_entry_is_a_segment_never_created	13.7s	11.8s	-14%

The classes that end last, in this run (minutes into the step):

Class	Busy, baseline → this run	Ends, baseline → this run
Faults.FaultInjectionTests	23m 31s → 20m 54s	23.5 → 20.9
Objects.ObjectFaultTests	32m 30s → 4m 25s	32.6 → 4.5
FilePropertyTests	7m 17s → 1m 16s	15.0 → 3.6
Objects.AzuriteObjectStoreContractTests	0.0s → 0.0s	15.6 → 3.3
Objects.ObjectEpochPropertyTests	11.5s → 2.7s	15.6 → 3.3
Objects.ObjectMigrationTests	17.7s → 2.7s	15.5 → 3.3

ubuntu-latest

First start to last end: 15m 47s → 10m 33s. Busy time of the 299 tests in both runs: 24m 36s → 16m 44s; of the 13 tests main added: 0.8s.

#	Test	Baseline	This run	Change
1	Faults.FaultInjectionTests · a_crash_during_recovery_recovers	6m 36s	4m 35s	-30%
2	Faults.FaultInjectionTests · a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6151, steps: 32)	2m 29s	1m 34s	-36%
3	Objects.ObjectFaultTests · after_a_fault_at_any_request_the_dataset_reopens_at_the_last_closed_commit_with_nothing_lost_or_doubled(seed: 9201)	1m 29s	1m 26s	-4%
4	Faults.FaultInjectionTests · a_crash_inside_a_batch_recovers_to_the_last_closed_commit(seed: 6152, steps: 32)	1m 27s	1m 01s	-30%
5	Faults.FaultInjectionTests · a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6102, steps: 24)	1m 07s	47.0s	-30%
6	Faults.FaultInjectionTests · a_process_crash_anywhere_recovers_to_the_last_closed_commit(seed: 6101, steps: 24)	54.6s	37.3s	-32%
7	Objects.ObjectPropertyTests · a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	31.5s	31.9s	+1%
8	Faults.FaultInjectionTests · a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6201, steps: 24, imagesPerPoint: 6)	44.8s	30.2s	-33%
9	Faults.FaultInjectionTests · a_power_loss_with_writes_reordered_up_to_the_flush_recovers(seed: 6202, steps: 24, imagesPerPoint: 6)	40.3s	27.3s	-32%
10	Faults.FaultInjectionTests · a_lost_directory_entry_is_a_segment_never_created	52.1s	24.7s	-53%
11	Faults.FaultInjectionTests · a_directory_copied_mid_write_opens_on_the_copy	38.1s	22.9s	-40%
12	LogPropertyTests · a_log_cut_at_any_byte_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	59.5s	21.0s	-65%
13	Objects.ObjectPropertyTests · a_log_in_objects_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 6710...	28.7s	19.8s	-31%
14	Objects.ObjectPropertyTests · the_store_in_objects_agrees_with_the_reference_model	28.3s	19.7s	-30%
15	FilePropertyTests · a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 64, segmentBytes: 1024)	16.2s	15.2s	-6%
16	LogPropertyTests · a_log_cut_at_any_byte_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)	21.9s	11.5s	-47%
17	FilePropertyTests · a_log_on_files_cut_at_its_boundaries_recovers_to_the_last_closed_commit(maxRecordBytes: 1048576, segmentBytes: 67108864)	15.3s	11.5s	-25%
18	BulkLoadTests · a_crash_at_every_operation_of_a_load_leaves_the_dataset_at_the_previous_head	16.8s	10.5s	-37%
19	FilePropertyTests · the_store_on_files_agrees_with_the_reference_model	14.2s	10.3s	-27%
20	FilePropertyTests · the_store_on_files_agrees_with_the_model_with_the_projection_in_derived_runs	15.2s	10.0s	-34%

The classes that end last, in this run (minutes into the step):

Class	Busy, baseline → this run	Ends, baseline → this run
Faults.FaultInjectionTests	15m 43s → 10m 30s	15.8 → 10.6
Objects.ObjectFaultTests	1m 29s → 1m 26s	3.9 → 2.9
Objects.ObjectExtentTests	6.3s → 7.7s	2.5 → 1.7
Objects.AzuriteObjectStoreContractTests	0.0s → 0.0s	2.4 → 1.6
MemoryStorageContractTests	0.0s → 0.0s	2.4 → 1.6
Format3Tests	1.3s → 0.8s	2.4 → 1.6

2c2e49c, the lease's owner and the ignore file written without a device flush, is pushed on its own. In ObjectFaultTests it removes 17,165 of 88,073 flushes (strace, locally). The other 70,908 are commit index publishes, which stay: a cached blob below the catalog is accepted on its last entry alone, so the flush is what keeps a torn one from being used. Its measurement follows here, and then the rest of the queue, one run each. The tail is now FaultInjectionTests on both OSes: the replay fix, the recovery stride and the class split are the commits aimed at it.

Generated by Claude Code

Hafeok · 2026-10-20T19:20:34Z

approve 2c2e49c

Hafeok · 2026-10-20T19:53:05Z

The flush fix: run 39482019599, `2c2e49c`, against the `TEMP` run (`8faf8dc`)

2c2e49c writes derived/LOCK.owner and derived/.gitignore without a device flush. The ignore file is rewritten at open when it isn't whole. The object backend's local cache opens a FileStorage at every restart.

Flushes in one run of ObjectFaultTests (strace, locally, by file):

	Before	After
commit index blobs, `local/derived/index/commits/…`	71,117	70,908
`LOCK.owner`	8,478	0
`.gitignore`	8,478	0
total	88,073	70,908 (−19.5%)

The commit index flushes stay. Below the catalog, a cached blob is accepted on its last entry alone. Locally, zeroing a byte in any earlier entry gave a different history or a LogVerificationException in 985 of 1,920 cases. The flush-then-rename publish is what keeps a torn blob from ever being used (6a990df, now running, tests the cases that are a miss).

Step times:

`Test Varve.Store`	Baseline `1d543f2`	`TEMP` `8faf8dc`	Flush fix `2c2e49c`
windows-latest	32m 41s	21m 0s	25m 29s
ubuntu-latest	15m 52s	10m 36s	15m 7s
storage (services)	4m 12s	5m 4s	3m 55s

The step times moved with the runner, not with the fix. In this run every in-memory test, which no change here touches, is slower than in the TEMP run: FaultInjectionTests +21% busy on Windows and +42% on Ubuntu. The TEMP run's Ubuntu runner was the fast one; this one is back to the baseline's 15–16 minutes. The tail is FaultInjectionTests on both OSes, so the step's length isn't something the flush fix could change.

ObjectFaultTests itself, normalised by the in-memory FaultInjectionTests on the same runner:

`ObjectFaultTests`	Baseline	`TEMP`	Flush fix
windows-latest	32m 30s (1.38×)	4m 25s (0.21×)	7m 28s (0.30×)
ubuntu-latest	1m 29s (0.10×)	1m 26s (0.14×)	1m 30s (0.10×)

The fix's ~19% doesn't show above the variation between runners. On Windows the disk tests got slower relative to the CPU-bound ones too: ObjectPropertyTests, which opens far fewer caches, went from 0.11× to 0.15×. The disk and the CPU of a runner vary separately. TEMP is the change that moved Windows: −86% on this test. The flush fix's effect is measurable only on one machine with one disk: locally, ObjectFaultTests alone went from 2m 11s to 1m 50s (−16%). It also removes two device flushes from every open in production.

Next: 6a990df (the cache test, about 23 s locally), then the replay fix, the recovery stride and the class split, which are the commits aimed at FaultInjectionTests, now the tail on both OSes.

Generated by Claude Code

Hafeok · 2026-10-21T10:07:16Z

approve 6a990df

Hafeok · 2026-10-21T10:16:50Z

approve 982a1de

Hafeok · 2026-10-21T11:00:25Z

approve 00de133

Hafeok · 2026-10-21T11:20:39Z

Approve ac143f8

main moved 15 commits, among them milestone Extent maintenance (#110), which adds store tests: ExtentMergeTests and ObjectReaderScheduleTests in process, and the extent maintenance legs against Azurite and RustFS in storage (services). The pull request could not merge, so CI did not run on ac143f8. One conflict: docs/testing.md gained section 7 on main (Extent maintenance) and here (how long the tests take); main's keeps 7, this one becomes 8, and the nightly workflow's references follow it. The next run is the baseline for Extent maintenance's tests in the store step, as #126 asks when that milestone lands first. Refs #126 Signed-off-by: Emil Okkels Klein <hannibal.okkels@gmail.com> Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01YWZaiBxSK7r6aizeG5YWo3

Hafeok deployed to gates October 19, 2026 14:02 — with GitHub Actions Active

Hafeok and others added 3 commits October 19, 2026 14:04

Hafeok deployed to gates October 19, 2026 14:50 — with GitHub Actions Active

Hafeok deployed to gates October 20, 2026 10:16 — with GitHub Actions Active

Hafeok and others added 7 commits October 20, 2026 11:02

Hafeok deployed to gates October 20, 2026 11:02 — with GitHub Actions Active

Hafeok deployed to gates October 20, 2026 19:16 — with GitHub Actions Active

Hafeok deployed to gates October 20, 2026 19:52 — with GitHub Actions Active

Hafeok deployed to gates October 21, 2026 10:07 — with GitHub Actions Active

Hafeok deployed to gates October 21, 2026 10:40 — with GitHub Actions Active

Hafeok deployed to gates October 21, 2026 11:03 — with GitHub Actions Active

Hafeok deployed to gates October 21, 2026 11:21 — with GitHub Actions Active

Hafeok deployed to gates October 21, 2026 11:24 — with GitHub Actions Active

Navigation Menu

Repository navigation

ci: measure and cut the store-test step (#126) - #136

ci: measure and cut the store-test step (#126)#136
Hafeok wants to merge 13 commits into
mainfrom
claude/varve-store-perf-measure-hcl8ga

Hafeok commented Oct 19, 2026

Uh oh!

Hafeok commented Oct 19, 2026

Uh oh!

Hafeok commented Oct 20, 2026

Uh oh!

Hafeok commented Oct 20, 2026

Uh oh!

Hafeok commented Oct 20, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

This branch was successfully deployed

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Conversation

Hafeok commented Oct 19, 2026

What this changes, and why

What was measured

What was found

What is left

Uh oh!

Hafeok commented Oct 19, 2026

Baseline: Test Varve.Store before any change (run 39265320616, 1d543f2)

windows-latest

ubuntu-latest

What they show

Uh oh!

Hafeok commented Oct 20, 2026

TEMP on the runner's temporary drive: run 39412157646, 8faf8dc, against the baseline (run 39265320616, 1d543f2)

Where the drop came from

windows-latest

ubuntu-latest

Next

Uh oh!

Hafeok commented Oct 20, 2026

Uh oh!

Hafeok commented Oct 20, 2026

The flush fix: run 39482019599, 2c2e49c, against the TEMP run (8faf8dc)

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

Hafeok commented Oct 21, 2026

Uh oh!

This branch was successfully deployed

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Baseline: `Test Varve.Store` before any change (run 39265320616, `1d543f2`)

`TEMP` on the runner's temporary drive: run 39412157646, `8faf8dc`, against the baseline (run 39265320616, `1d543f2`)

The flush fix: run 39482019599, `2c2e49c`, against the `TEMP` run (`8faf8dc`)