DispatchIO.read spinning while pipe is open on Windows about swift-corelibs-libdispatch HOT 16 OPEN

@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

from swift-corelibs-libdispatch.

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:

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.

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.

from swift-corelibs-libdispatch.

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.

from swift-corelibs-libdispatch.

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

1. SourceKit-LSP file locking issue
2. swiftlang/sourcekit-lsp#1139
3. This

from swift-corelibs-libdispatch.

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.

from swift-corelibs-libdispatch.

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.

from swift-corelibs-libdispatch.

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

from swift-corelibs-libdispatch.

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).

from swift-corelibs-libdispatch.

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.

from swift-corelibs-libdispatch.

Same problem. Running Swift 5.10 directly on Windows 11 x64

from swift-corelibs-libdispatch.

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.

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

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"}]}}

from swift-corelibs-libdispatch.

@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?

from swift-corelibs-libdispatch.

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?

from swift-corelibs-libdispatch.

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

from swift-corelibs-libdispatch.

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

from swift-corelibs-libdispatch.

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

from swift-corelibs-libdispatch.