Repository navigation
The BackgroundIndexingTests are very flaky on Windows CI #2766
Description
Activity
Some data from ~200 Windows CI builds.
The signature to grep for
XCTUnwrap failed: expected non-nil value of type "CallHierarchyItem"andXCTAssertNotEqual failed: ("Optional([])") is equal to ("Optional([])")are downstream effects. The actual cause only shows up as:Terminating process using SIGINT because task was cancelled: [swiftc.exe -parse-as-library -module-name MyLibrary …] 🟨🟥⬜️ Finished with error in 120.00164099999999 seconds: Timed out Updating index store failed: Timed out.Counting
Updating index store failed: Timed outmatches the number of failed tests one-for-one in every affected build I looked at.It looks like a hang, not a slow machine
Index-store update durations in the affected runs are strictly bimodal — they either finish in under 10 seconds or hit the 120 second timeout exactly, with nothing in between. swift-PR-windows/61267 has 1 fast and 28 timed out, swift-PR-windows/61287 has 4 and 35, sourcekit-lsp-PR-windows/4261 has 1 and 4. If the machine were merely N× slow we would expect successful updates at 20s, 40s, 80s; there are none. (Caveat: SwiftPM only prints captured output for failing tests in parallel mode, so this distribution is conditioned on failing tests rather than being a sample of the whole run.) In that last build all four index jobs expired within a 5 second window of each other after each sitting for the full 120 seconds — the machine went away rather than gradually falling behind.
Comparing identical swift-testing suites between the Linux smoke test and Windows builds of the same commit, Windows is typically only 1.2–2.2× slower. But one 442-test suite took 8.0 seconds in 61253 and 62 seconds in 61309 and 61324 — same machine, same commit. That run-to-run variance, not a uniform slowdown, is what blows a fixed timeout budget.
Parallelism is probably not the cause
swift test --parallelwith no--num-workersusesProcessInfo.processInfo.activeProcessorCount, and neither the Linux nor the Windows CI path caps it. Both agents have 36 usable cores (perlit's reported worker count in the same builds), so Linux runs this suite at identical width without the stalls. That argues against oversubscription, and against the always-serial workaround in swiftlang/swift#85339.It isn't specific to background indexing
swift-PR-windows-status/1208 failed 8 tests in
BuildServerIntegrationTests— 6 inExternalBuildServerTests, 2 inLegacyBuildServerTests— all withtextDocument/diagnosticortextDocument/definition request timed out after 180.0 seconds, each taking ~180.2s, and zero index-store timeouts in that build. swift-PR-windows/61285 shows the identical 8 plus 23SwiftSourceKitPluginTestsfailures that allthrew error "Timed out". So this may be better characterised as Windows test processes intermittently wedging than as aBackgroundIndexingTestsproblem — it reaches diagnostics, definition and code completion across three different test targets.One thing that makes every occurrence harder to read than it needs to be
updateIndexStoreTimeoutdefaults to 120 seconds while tests wait up todefaultTimeout(180 seconds) for results. Because the subprocess timeout is the shorter of the two, a wedgedswiftcgets killed first, the index is left empty, and the test fails on an unrelated assertion instead of a timeout that names the slow indexing. Deriving it fromdefaultTimeoutdoesn't fix the hang but makes these failures self-describing.In progress
I'm instrumenting libdispatch's internal workqueue pool monitor in swiftlang/swift-corelibs-libdispatch#959 to see whether the pool fails to grow while all workers are blocked. So far the Windows probe reports
openthread_failed 0in every sample, so theOpenThread-misclassification path isn't firing, and transientSTALLED, no runnable workersoccurs benignly on Linux too — only a sustained stall across the 120 seconds would be meaningful.Jenkins console output for every run cited in the comment above. Named
<job>-<build>.txt.gz; gunzip to read.File Job / build What it shows swift-PR-windows-61267.txt.gzswift-PR-windows/61267 28 index-store timeouts, 14 tests failed. 1 index update under 10s, 28 at the 120s timeout, none between. swift-PR-windows-61287.txt.gzswift-PR-windows/61287 35 index-store timeouts, 20 tests failed. 4 fast, 35 timed out. Shares 14 identical failures with 61267. sourcekit-lsp-PR-windows-4261.txt.gzsourcekit-lsp-PR-windows/4261 4 index-store timeouts, 4 tests failed. All four expired within a 5 second window of each other. swift-PR-windows-61253.txt.gzswift-PR-windows/61253 The 442-test swift-testing suite completes in 8.0s here. swift-PR-windows-61309.txt.gzswift-PR-windows/61309 Same suite takes 62s. Same machine and commit as 61253. swift-PR-windows-61324.txt.gzswift-PR-windows/61324 Same suite takes 62s. swift-PR-windows-status-1208.txt.gzswift-PR-windows-status/1208 8 BuildServerIntegrationTestsfailures, alltextDocument/diagnosticortextDocument/definition request timed out after 180.0 seconds, zero index-store timeouts.swift-PR-windows-61285.txt.gzswift-PR-windows/61285 The same 8 build-server failures plus 23 SwiftSourceKitPluginTeststhat allthrew error "Timed out".swift-PR-Linux-smoke-test-30813.txt.gzswift-PR-Linux-smoke-test/30813 Linux baseline. Same suite, same parallel width, 1431 tests, no failures and no index-store timeouts. Useful greps
Updating index store failed: Timed out # the real cause behind the assertion failures Finished with error in 120 # the index-store subprocess being killed timed out after 180.0 seconds # requests hitting the test-level timeout Test Suite 'Selected tests' # SwiftPM prints captured output only for failing testsswift-PR-windowsandswift-PR-windows-statusare onci-external.swift.org;swift-PR-Linux-smoke-testis onci.swift.org.sourcekit-lsp-PR-windows-4261.txt.gz
swift-PR-Linux-smoke-test-30813.txt.gz
swift-PR-windows-61253.txt.gz
swift-PR-windows-61267.txt.gz
swift-PR-windows-61285.txt.gz
swift-PR-windows-61287.txt.gz
swift-PR-windows-61309.txt.gz
swift-PR-windows-61324.txt.gz
swift-PR-windows-status-1208.txt.gzThanks for looking into this, I only examined a few of the many failing logs and saw the BackgroundIndexingTests problems.
In that last build all four index jobs expired within a 5 second window of each other after each sitting for the full 120 seconds — the machine went away rather than gradually falling behind.
This makes me think that once one hangs, it causes other hangs too, which would imply the key is figuring out why the first one hangs.
Possible theory. To be clear up front: this is code reading by Claude plus a consistency argument, not something I have observed directly. I have no
.lockfile sighting and no lock-timeout remark in any log. But it is the only mechanism I have found that matches every property of these failures.The theory
Windows can never detect that a module cache lock's owning process has died, so a leaked lock costs a full timeout there, where on Linux and macOS it costs nothing.
LockFileManager::processStillExecutinginllvm/lib/Support/LockFileManager.cppis guarded by#if LLVM_ON_UNIX && !defined(__ANDROID__)and unconditionally returnstrueeverywhere else:bool LockFileManager::processStillExecuting(StringRef HostID, int PID) { #if LLVM_ON_UNIX && !defined(__ANDROID__) SmallString<256> StoredHostID; if (getHostID(StoredHostID)) return true; // Conservatively assume it's executing on error. // Check whether the process is dead. If so, we're done. if (StoredHostID == HostID && getsid(PID) == -1 && errno == ESRCH) return false; #endif return true; }
That breaks recovery in two places.
readLockFilecannot reap a stale lock at acquisition time — on Unix it deletes it immediately ("Delete the lock file. It's invalid anyway.") — andwaitForUnlockForcan never returnOwnerDied, so the waiter burns the whole timeout beforeunsafeUnlock()clears the lock and it rebuilds. Clang implicit module builds waitImplicitModulesLockTimeoutSeconds = 90(clang/include/clang/Basic/../Frontend/FrontendOptions.h:578, used atclang/lib/Frontend/CompilerInstance.cpp:1780). Since multiple pcm can be created, it two pcm builds are enough to reach the sourcekit-lsp's 120 sec timeouts.Where leaked locks would come from — routine teardown, not failures
TaskScheduler.shutDown()cancels every in-flight task:await allTasks.concurrentForEach { task in task.cancel() do { try await withTimeout(.seconds(10)) { await task.waitToFinish() } } catch { logger.error("Timed out waiting for task \(task.description.forLogging) to finish during shutdown") } }
Every test is its own process with its own server, and tests routinely return while background indexing is still running, so this is triggered on the success path for most background-indexing tests. Cancellation goes through
Sources/TSCExtensions/Process+Run.swift:43-60, which sends SIGINT, waits 2 seconds, then escalates — and on Windows TSC maps the escalation to_process?.terminate(), i.e.TerminateProcess, which runs no handlers, sosys::RemoveFileOnSignalnever removes the lock. Aswiftcin the middle of a module build may not exit within 2 seconds.testCancelIndexingalso kills deliberately (updateIndexStoreTimeout = 1). On Unix the same escalation happens, but the leak is reaped on first contact.All concurrently running test processes share a single
-module-cache-path, so a lock leaked by one test is waited on by later ones. Worth noting explicitly: the sharing itself is not the platform difference.build.ps1never setsSOURCEKIT_LSP_TEST_MODULE_CACHE, so Windows falls back toUtils.swift:123's%TEMP%\sourcekit-lsp-test-scratch\shared-module-cache, whereasUtilities/build-script-helper.py:251points Linux and macOS at a freshTemporaryDirectory— but that directory is also shared across all ~1400 tests in the run. So pointing Windows at a fresh per-run directory would only clear staleness inherited from previous runs and would not address locks leaked mid-run. The difference is purely the cost of recovery.Why it fits
- Windows-only, with identical code, tests, parallel width and cache sharing on every platform.
- Bimodal durations — either the lock is free and indexing finishes in under 10s, or it is held and we kill the process at 120s. Nothing in between, which is what the data shows.
- Self-healing, so it never permanently breaks an agent: the first waiter to time out calls
unsafeUnlock()and everyone after it proceeds. - Load-correlated and clustered, since several processes can be waiting on the same lock at once.
- Independent of anything in sourcekit-lsp's own threading, which is consistent with one test process per test and no shared state between them.
Possibly a second, independent factor
Sources/TSCExtensions/Process+Run.swift:51carries// TODO: We should also terminate all child processes (#2080). Cancelling a preparation killsswift buildbut not its descendants, so every cancelled preparation orphans liveswift-frontendprocesses that keep compiling unsupervised. Over a 1400-test run that cancels at nearly every teardown, orphans could accumulate on a 36-core agent and produce machine-wide slowness that the suite inflicts on itself. That would independently explain the 8.0s vs 62s spread of the same 442-test suite on the same machine and commit, and it is worth testing separately from the lock theory.Reacted by finagolfinIf #2770 PR testing logs shows
timed out waiting to acquire lock file for module 'X', it confirms the theory is real.
Swift version
6.4 and trunk
Platform
Windows Server 2019
Editor
None
Description
We've been seeing a bunch of flakes that break Windows CI runs for pulls to all toolchain repos, causing us to have to rerun the CI till it doesn't flake:
May be related to #2346?
Steps to Reproduce
Run the Windows CI
Logging
No response