DispatchIO.read spinning while pipe is open on Windows

[DimaKozhinov]

The sourcekit-lsp.exe consumes ~24% of CPU power all the time, even when idle. This bug does not appear under Linux, and does not appear in Swift versions earlier than v5.9. It is still present in v5.10. I tested this under VirtualBox, my virtual machine has 4 virtual processors. The host machine has 13th Gen Intel Core i7 processor, so ~24% load seems like a lot of mysterious calculations.

How to reproduce:

1. Install Swift version 5.9 .. 5.10. Install Microsoft VS Code and Swift extension for it (v1.8.1 from Swift Server Work Group).
2. Create a test Swift package:
   mkdir test
   cd test
   swift package init
3. Open the test folder in VS Code. (File | Open Folder...). At this point CPU usage increases, you don't even need to edit any source file. On my (usually silent) PC fan immediately starts rotating much faster, producing loud noise.
4. Check CPU usage by the sourcekit-lsp.exe: Press Ctrl-Shift-Esc, in the process list find the Visual Studio Code, click ">" next to it to see its sub-processes, and see high CPU usage by sourcekit-lsp .
5. Return to step 1 and this time install Swift version 5.8.1 or earlier. Repeat step 2 (create Swift package) because earlier version of Swift won't open a package created with a later version. Repeat all next steps and see ~0% CPU usage by sourcekit-lsp.exe .

This bug has nothing to do with VS Code. I found this bug when using my own app that runs sourcekit-lsp.exe, and not VS Code.

[ahoppen]

Tracked in Apple’s issue tracker as rdar://124157417

[litewrap]

Same problem here.
Using Swift on Windows 11.
I am running Windows 11 under Parallels Desktop on Macbook M1.
VS Code 1.8 or recent 1.8.1 and Task Manager shows sourcekit-lsp CPU usage 25% (single swift file open) to 71% (when many .swift files open).

[DimaKozhinov]

To rule out influence of virtual environments like VirtualBox or Parallels, I've tested this on bare metal (3 GHz Intel Core i5-7400, Windows 10):

Swift 5.8.1 sourcekit-lsp CPU usage: 0% (the expected behavior)
Swift 5.10 sourcekit-lsp CPU usage: 29%

Small note: This time sourcekit-lsp appeared in Task Manager not as a sub-process of Visual Studio Code, but as a separate background process due to some reason.

[nieuwenhoven]

Same problem. Running Swift 5.10 directly on Windows 11 x64

[ahoppen]

I have managed to reduce the problem to the following.

1. Replace Sources/sourcekit-lsp/SourceKitLSP.swift with the following main function that doesn’t do anything and just causes sourcekit-lsp to listen for data from stdin.

Sources/sourcekit-lsp/SourceKitLSP.swift

import Dispatch
import Foundation

#if canImport(CDispatch)
import struct CDispatch.dispatch_fd_t
#endif


@main
struct MyCommand {
    static func main() throws {
        let fh = try! FileHandle(forWritingTo: URL(fileURLWithPath: #"C:/Users/rintaro/out.txt"#))
        try! fh.seekToEnd()
        try! fh.write("start\n".data(using: .utf8)!)

        let queue: DispatchQueue = DispatchQueue(label: "jsonrpc-queue", qos: .userInitiated)
        #if os(Windows)
        let rawInFD = dispatch_fd_t(bitPattern: FileHandle.standardInput._handle)
        #else
        let rawInFD = inFD.fileDescriptor
        #endif

        let receiveIO = DispatchIO(type: .stream, fileDescriptor: rawInFD, queue: queue) { (error: Int32) in
          if error != 0 {
            print("IO error \(error)")
          }
        }
        receiveIO.setLimit(lowWater: 1)
        receiveIO.read(offset: 0, length: Int.max, queue: queue) { done, data, errorCode in
            print("received \(data?.count ?? -1) data")
            let fh = try! FileHandle(forWritingTo: URL(fileURLWithPath: #"C:/Users/rintaro/out.txt"#))
            try! fh.seekToEnd()
            try! fh.write(contentsOf: data!)

        }
        
        dispatchMain()
    }
}

2. Build a local toolchain
3. Launch Visual Studio Code with the locally modified version of sourcekit-lsp by running

set SDKROOT=S:\Program Files\Swift\Platforms\Windows.platform\Developer\SDKs\Windows.sdk
path S:\Program Files\Swift\Runtimes\0.0.0\usr\bin;S:\Program Files\Swift\Toolchains\0.0.0+Asserts\usr\bin;%PATH%
"C:\path\to\Microsoft VS Code\Code.exe" C:\path\to\a\swiftpm\project

5. Open Task Manager and notice that sourcekit-lsp is constantly using CPU

I was unable to reproduce this issue by launching this modified version of sourcekit-lsp from the command prompt and passing data to stdin by typing or by piping data to the modified version of sourcekit-lsp using

Get-Content C:\path\to\input.txt | .\sourcekit-lsp.exe

With the following input.txt

input.txt

Content-Length: 5887

{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":1948,"clientInfo":{"name":"Visual Studio Code","version":"1.87.2"},"locale":"en","rootPath":"s:\\SourceCache\\sourcekit-lsp","rootUri":"file:///s%3A/SourceCache/sourcekit-lsp","capabilities":{"workspace":{"applyEdit":true,"workspaceEdit":{"documentChanges":true,"resourceOperations":["create","rename","delete"],"failureHandling":"textOnlyTransactional","normalizesLineEndings":true,"changeAnnotationSupport":{"groupsOnLabel":true}},"configuration":true,"didChangeWatchedFiles":{"dynamicRegistration":true,"relativePatternSupport":true},"symbol":{"dynamicRegistration":true,"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]},"tagSupport":{"valueSet":[1]},"resolveSupport":{"properties":["location.range"]}},"codeLens":{"refreshSupport":true},"executeCommand":{"dynamicRegistration":true},"didChangeConfiguration":{"dynamicRegistration":true},"workspaceFolders":true,"foldingRange":{"refreshSupport":true},"semanticTokens":{"refreshSupport":true},"fileOperations":{"dynamicRegistration":true,"didCreate":true,"didRename":true,"didDelete":true,"willCreate":true,"willRename":true,"willDelete":true},"inlineValue":{"refreshSupport":true},"inlayHint":{"refreshSupport":true},"diagnostics":{"refreshSupport":true}},"textDocument":{"publishDiagnostics":{"relatedInformation":true,"versionSupport":false,"tagSupport":{"valueSet":[1,2]},"codeDescriptionSupport":true,"dataSupport":true},"synchronization":{"dynamicRegistration":true,"willSave":true,"willSaveWaitUntil":true,"didSave":true},"completion":{"dynamicRegistration":true,"contextSupport":true,"completionItem":{"snippetSupport":true,"commitCharactersSupport":true,"documentationFormat":["markdown","plaintext"],"deprecatedSupport":true,"preselectSupport":true,"tagSupport":{"valueSet":[1]},"insertReplaceSupport":true,"resolveSupport":{"properties":["documentation","detail","additionalTextEdits"]},"insertTextModeSupport":{"valueSet":[1,2]},"labelDetailsSupport":true},"insertTextMode":2,"completionItemKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25]},"completionList":{"itemDefaults":["commitCharacters","editRange","insertTextFormat","insertTextMode","data"]}},"hover":{"dynamicRegistration":true,"contentFormat":["markdown","plaintext"]},"signatureHelp":{"dynamicRegistration":true,"signatureInformation":{"documentationFormat":["markdown","plaintext"],"parameterInformation":{"labelOffsetSupport":true},"activeParameterSupport":true},"contextSupport":true},"definition":{"dynamicRegistration":true,"linkSupport":true},"references":{"dynamicRegistration":true},"documentHighlight":{"dynamicRegistration":true},"documentSymbol":{"dynamicRegistration":true,"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]},"hierarchicalDocumentSymbolSupport":true,"tagSupport":{"valueSet":[1]},"labelSupport":true},"codeAction":{"dynamicRegistration":true,"isPreferredSupport":true,"disabledSupport":true,"dataSupport":true,"resolveSupport":{"properties":["edit"]},"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}},"honorsChangeAnnotations":true},"codeLens":{"dynamicRegistration":true},"formatting":{"dynamicRegistration":true},"rangeFormatting":{"dynamicRegistration":true,"rangesSupport":true},"onTypeFormatting":{"dynamicRegistration":true},"rename":{"dynamicRegistration":true,"prepareSupport":true,"prepareSupportDefaultBehavior":1,"honorsChangeAnnotations":true},"documentLink":{"dynamicRegistration":true,"tooltipSupport":true},"typeDefinition":{"dynamicRegistration":true,"linkSupport":true},"implementation":{"dynamicRegistration":true,"linkSupport":true},"colorProvider":{"dynamicRegistration":true},"foldingRange":{"dynamicRegistration":true,"rangeLimit":5000,"lineFoldingOnly":true,"foldingRangeKind":{"valueSet":["comment","imports","region"]},"foldingRange":{"collapsedText":false}},"declaration":{"dynamicRegistration":true,"linkSupport":true},"selectionRange":{"dynamicRegistration":true},"callHierarchy":{"dynamicRegistration":true},"semanticTokens":{"dynamicRegistration":true,"tokenTypes":["namespace","type","class","enum","interface","struct","typeParameter","parameter","variable","property","enumMember","event","function","method","macro","keyword","modifier","comment","string","number","regexp","operator","decorator"],"tokenModifiers":["declaration","definition","readonly","static","deprecated","abstract","async","modification","documentation","defaultLibrary"],"formats":["relative"],"requests":{"range":true,"full":{"delta":true}},"multilineTokenSupport":false,"overlappingTokenSupport":false,"serverCancelSupport":true,"augmentsSyntaxTokens":true},"linkedEditingRange":{"dynamicRegistration":true},"typeHierarchy":{"dynamicRegistration":true},"inlineValue":{"dynamicRegistration":true},"inlayHint":{"dynamicRegistration":true,"resolveSupport":{"properties":["tooltip","textEdits","label.tooltip","label.location","label.command"]}},"diagnostic":{"dynamicRegistration":true,"relatedDocumentSupport":false}},"window":{"showMessage":{"messageActionItem":{"additionalPropertiesSupport":true}},"showDocument":{"support":true},"workDoneProgress":true},"general":{"staleRequestSupport":{"cancel":true,"retryOnContentModified":["textDocument/semanticTokens/full","textDocument/semanticTokens/range","textDocument/semanticTokens/full/delta"]},"regularExpressions":{"engine":"ECMAScript","version":"ES2020"},"markdown":{"parser":"marked","version":"1.1.0"},"positionEncodings":["utf-16"]},"notebookDocument":{"synchronization":{"dynamicRegistration":true,"executionSummarySupport":true}}},"trace":"verbose","workspaceFolders":[{"uri":"file:///s%3A/SourceCache/sourcekit-lsp","name":"sourcekit-lsp"}]}}

[ahoppen]

@tristanlabelle This sounds like a similar issue to swiftlang/sourcekit-lsp#752, which you fixed in #796. Do you have any idea what might be going wrong here?

[tristanlabelle]

That's very interesting, thanks for the reduced repro. It points to another pipe handling problem in libdispatch, likely on the reading side, but I don't know what it may be. What kind of received <N> data output do you get when testing this? And does that print send back a broken response to vscode and causes it to misbehave?

[ahoppen]

I just managed to reduce it even further without any dependency on VS Code.

It appears that DispatchIO.read is constantly using CPU time until the pipe to it has been closed.

To reproduce this one:

• Unzip the attached package
• swift build (to build both parent.exe and child.exe)
• Run .build\debug\parent.exe
• Notice that child.exe is constantly using CPU without any work happening.

testpackage.zip

[tristanlabelle]

Nice repro @ahoppen ! Let me know if this gets into gnarly libdispatch Win32 pipe semantics and you need help. We're tracking this bug as affecting our developers and we could give a hand to the investigation.

[ahoppen]

@tristanlabelle I have reached that stage. If you could investigate it, I would really appreciate it.

[tristanlabelle]

Hi @ahoppen , we'll look into it. Currently our priorities in this area are roughly:

1. SourceKit-LSP file locking issue
2. Frequent crashes on Windows with Assertion failed: IDAndOffset.first.isValid() && "invalid FileID for transition" swiftlang/sourcekit-lsp#1139
3. This

[ahoppen]

It looks like we are spending the time in _dispatch_event_loop_leave_immediate. @tristanlabelle Have you seen this before in your previous fixes of hangs in libdispatch?

Edit: Sorry, I just realized that I already reached this debugging state a few months ago. I remembered that you looked into Dispatch before but forgot that the DispatchIO issue was still open.

[tristanlabelle]

@ahoppen I don't remember seeing this before specifically. The trace will be useful though as this is next in the priority list. We got through the file locking issue and I don't think we're hitting the crash anymore (from my list in previous comment). fyi @z2oh

[ahoppen]

That would be amazing. I wonder what kind of fix this will be.

[z2oh]

I've figured out what's causing this, but I'm not sure of a proper fix yet.

By default, Windows pipes are blocking on both the read and write side (PIPE_WAIT).

libdispatch seems to expect non-blocking write semantics on pipes, and so this was effected on Windows in #781 by setting the PIPE_NOWAIT flag here:
https://github.com/apple/swift-corelibs-libdispatch/blob/85369bae730669dcee18b771f27f885250971900/src/io.c#L1440-L1456

Perhaps surprisingly, this also changes the read side of the pipe to do non-blocking reads. The original Windows pipe-event implementation (#501) took advantage of Windows' blocking-by-default read semantics and spawned a lightweight thread to call ReadFile on the pipe in a loop.

I'm not sure when ReadFile on a PIPE_WAIT pipe would result in ERROR_NO_DATA (the docs don't describe this case in detail), but the dispatch code handles this error by restarting the loop. Under PIPE_NOWAIT, ERROR_NO_DATA is returned immediately on a read of an empty pipe, turning this code into a CPU-hogging polling loop.

https://github.com/apple/swift-corelibs-libdispatch/blob/85369bae730669dcee18b771f27f885250971900/src/event/event_windows.c#L299-L303

The comment in the code here seems to indicate that this error implies we have a non-blocking pipe (which is true as we've seen), but I can't intuit why that should cause the loop to restart. Perhaps there was an assumption that the pipe is still initializing and would eventually be set to PIPE_WAIT? I'm not sure.

#781 was cherry-picked into Swift 5.9 (and after), which explains why this issue isn't present in earlier versions.

I've built a local dispatch.dll that switches the pipe back to PIPE_WAIT and I no longer observe the perpetually spinning thread in sourcekit-lsp or in the test repro provided by @ahoppen. Presumably, this reintroduces the bug(s) that #781 resolved, so the actual fix will need to be more sophisticated. I'll continue to look into this.

[z2oh]

I've done some more investigation here:

The key insight is that the PIPE_WAIT pipe was cleverly overloaded to perform both data transfer and synchronization (via blocking on a 0-byte read). As far as I can tell, a PIPE_NOWAIT pipe requires some external signaling mechanism to achieve the same kind of synchronization. Because external writers may only have access to the file descriptor of the write side of the pipe, there's no way to get reliable synchronization from outside of libdispatch. Even overlapped I/O (the preferred mechanism for non-blocking pipe semantics) requires explicit signaling when calling WriteFile.

This is to say, I don't see a way to fix this problem without switching back to PIPE_WAIT. As mentioned previously, this will require an alternate solution for the write-hang bug that was mitigated by switching to PIPE_NOWAIT in #781, which is what I will be looking for next.

[tristanlabelle]

It makes sense to me that a final solution would be with PIPE_WAIT pipes, especially since PIPE_NOWAIT is deprecated. For context on the original issue: a PIPE_WAIT write will block if there's not enough buffer space to complete the write (which the dispatch code isn't expecting), and we never were able to find a reliable way to know that there will not be enough buffer space before attempting the write. The function that is supposed to report that information spuriously reports a misleading value of zero bytes.
Some possible avenues of investigation:

• Can we get the reader side of the pipe from the writer and query how much data is available to read as a proxy to determine how much of the pipe is empty and available to write?
• Can we do an overlapped write operation and then cancel it if it doesn't complete immediately because the pipe is full?