bug: debugger freezes when loading 1M goroutines

[ramya-rao-a]

From microsoft/vscode-go#2562 by @aarzilli:

Debug https://github.com/aarzilli/delve_client_testing/blob/master/20bigstuff/main.go.

I expected a slight slowdown but the debugger should keep working. What happend is that the debugger freezes slowing down the whole system. Possible causes include VSCode-go trying to read the 100MB string, 10 million stack frames or 1 million goroutines. Possibly all three.

[stamblerre]

@aarzilli: Can dlv on the command-line handle this, or is this issue specific to VS Code Go?

[aarzilli]

Yes, both the command line client and gdlv work with this. I haven't checked GoLand in a year and I don't remember if they fixed it. What this is doing is checking that reasonable limits are passed to ListGoroutines, Eval and Stacktrace. You will probably encounter problems with the fact that DAP doesn't have a way, in the protocol, to deal with too many goroutines.

[polinasok]

I tried this wiht dlv cli. The debug session makes it to the breakpoint with no issues.

$ dlv debug issue129.go 
Type 'help' for list of commands.
(dlv) c
about to stop
> main.done() ./issue129.go:20 (PC: 0x10c4d5f)
    15:         sh := (*reflect.StringHeader)(unsafe.Pointer(&s))
    16:         sh.Data = slh.Data
    17:         sh.Len = slh.Len
    18:         fmt.Printf("about to stop\n")
    19:         runtime.Breakpoint()
=>  20:         fmt.Printf("this\n")
    21:         fmt.Printf("should\n")
    22:         fmt.Printf("be\n")
    23:         fmt.Printf("fast\n")
    24: }
    25:
(dlv) 

At that point if we issue the same commands that VS Code would automatically, I see the following behavior:

(dlv) goroutines

This slowly prints 10K goroutines at a time with long pauses in-between. I killed the process after getting to 150000 in about 5 minutes.

(dlv) print buf
[]uint8 len: 100000000, cap: 100000000, [0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,...+99999936 more]

This returns immediately. Only 64 bytes are loaded.
Stack also prints quickly as it truncates.

(dlv) stack
 0  0x00000000010c4d5f in main.done
    at ./issue129.go:20
 1  0x00000000010c4e5c in main.makeStack
    at ./issue129.go:28
 2  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 3  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 4  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 5  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 6  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 7  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 8  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
 9  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
10  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
11  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
12  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
13  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
14  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
15  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
16  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
17  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
18  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
19  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
20  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
21  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
22  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
23  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
24  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
25  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
26  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
27  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
28  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
29  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
30  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
31  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
32  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
33  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
34  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
35  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
36  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
37  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
38  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
39  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
40  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
41  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
42  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
43  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
44  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
45  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
46  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
47  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
48  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
49  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
50  0x00000000010c4e77 in main.makeStack
    at ./issue129.go:31
(truncated)
(dlv) 

[polinasok]

When running the same program in vscode:

about to stop
020-11-02T09:21:46-08:00 debug layer=rpc (async 3) -> rpc2.CommandOut{"State":{"Running":false,"Recording":false,"currentThread":{"id":8099903,"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"ReturnValues":null},"currentGoroutine":{"id":1,"currentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":17178566,"file":"/usr/local/go/src/runtime/asm_amd64.s","line":220,"function":{"name":"runtime.rt0_go","value":17178256,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":16998528,"file":"/usr/local/go/src/runtime/proc.go","line":113,"function":{"name":"runtime.main","value":16998528,"type":0,"goType":0,"optimized":true}},"threadID":8099903,"unreadable":""},"Threads":[{"id":8099856,"pc":16861268,"file":"/usr/local/go/src/runtime/mbitmap.go","line":456,"function":{"name":"runtime.heapBits.next","value":16861216,"type":0,"goType":0,"optimized":true},"goroutineID":1000034,"ReturnValues":null},{"id":8099900,"pc":140735118227286,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099901,"pc":140735118227586,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099902,"pc":16908520,"file":"/usr/local/go/src/runtime/mgcmark.go","line":1260,"function":{"name":"runtime.scanobject","value":16908224,"type":0,"goType":0,"optimized":true},"goroutineID":1000018,"ReturnValues":null},{"id":8099903,"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"ReturnValues":null},{"id":8099904,"pc":16862226,"file":"\u003cautogenerated\u003e","line":1,"function":{"name":"runtime.heapBits.bits","value":16862208,"type":0,"goType":0,"optimized":true},"goroutineID":1000049,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""
continue state {"Running":false,"Recording":false,"currentThread":{"id":8099903,"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"ReturnValues":null},"currentGoroutine":{"id":1,"currentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":17178566,"file":"/usr/local/go/src/runtime/asm_amd64.s","line":220,"function":{"name":"runtime.rt0_go","value":17178256,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":16998528,"file":"/usr/local/go/src/runtime/proc.go","line":113,"function":{"name":"runtime.main","value":16998528,"type":0,"goType":0,"optimized":true}},"threadID":8099903,"unreadable":""},"Threads":[{"id":8099856,"pc":16861268,"file":"/usr/local/go/src/runtime/mbitmap.go","line":456,"function":{"name":"runtime.heapBits.next","value":16861216,"type":0,"goType":0,"optimized":true},"goroutineID":1000034,"ReturnValues":null},{"id":8099900,"pc":140735118227286,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099901,"pc":140735118227586,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099902,"pc":16908520,"[...]
handleReenterDebug(breakpoint).
2020-11-02T09:21:46-08:00 debug layer=rpc <- RPCServer.ListGoroutines(rpc2.ListGoroutinesIn{"Start":0,"Count":1})
2020-11-02T09:21:46-08:00 debug layer=rpc -> *rpc2.ListGoroutinesOut{"Goroutines":[{"id":1,"currentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":17178566,"file":"/usr/local/go/src/runtime/asm_amd64.s","line":220,"function":{"name":"runtime.rt0_go","value":17178256,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":16998528,"file":"/usr/local/go/src/runtime/proc.go","line":113,"function":{"name":"runtime.main","value":16998528,"type":0,"goType":0,"optimized":true}},"threadID":8099903,"unreadable":""}],"Nextg":1} error: ""
To client: {"seq":0,"type":"event","event":"stopped","body":{"reason":"breakpoint","threadId":1,"allThreadsStopped":true}}
StoppedEvent("breakpoint")
From client: threads(undefined)
2020-11-02T09:21:46-08:00 debug layer=rpc (async 6) <- RPCServer.State(rpc2.StateIn{"NonBlocking":true})
2020-11-02T09:21:46-08:00 debug layer=rpc (async 6) -> rpc2.StateOut{"State":{"Running":false,"Recording":false,"currentThread":{"id":8099903,"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"ReturnValues":null},"currentGoroutine":{"id":1,"currentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":17178566,"file":"/usr/local/go/src/runtime/asm_amd64.s","line":220,"function":{"name":"runtime.rt0_go","value":17178256,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":16998528,"file":"/usr/local/go/src/runtime/proc.go","line":113,"function":{"name":"runtime.main","value":16998528,"type":0,"goType":0,"optimized":true}},"threadID":8099903,"unreadable":""},"Threads":[{"id":8099904,"pc":16862226,"file":"\u003cautogenerated\u003e","line":1,"function":{"name":"runtime.heapBits.bits","value":16862208,"type":0,"goType":0,"optimized":true},"goroutineID":1000049,"ReturnValues":null},{"id":8099856,"pc":16861268,"file":"/usr/local/go/src/runtime/mbitmap.go","line":456,"function":{"name":"runtime.heapBits.next","value":16861216,"type":0,"goType":0,"optimized":true},"goroutineID":1000034,"ReturnValues":null},{"id":8099900,"pc":140735118227286,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099901,"pc":140735118227586,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":8099902,"pc":16908520,"file":"/usr/local/go/src/runtime/mgcmark.go","line":1260,"function":{"name":"runtime.scanobject","value":16908224,"type":0,"goType":0,"optimized":true},"goroutineID":1000018,"ReturnValues":null},{"id":8099903,"pc":17583455,"file":"/Users/polina/go/src/issue129/issue129.go","line":20,"function":{"name":"main.done","value":17583216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""
ThreadsRequest
To client: {"seq":0,"type":"event","event":"output","body":{"category":"stderr","output":"2020-11-02T09:21:46-08:00 debug layer=rpc <- RPCServer.ListGoroutines(rpc2.ListGoroutinesIn{\"Start\":0,\"Count\":0})\n"}}
2020-11-02T09:21:46-08:00 debug layer=rpc <- RPCServer.ListGoroutines(rpc2.ListGoroutinesIn{"Start":0,"Count":0})

Things get stuck where we request all the goroutines. This happens before loading the stacktrace or variables, so at least at this stage those request do not contribute to the issue.

Unlike StrackTrace Request,Threads Request does not offer any settings for partial retrieval. There is not a feature in the UI to retrieve more threads or a specific thread.

Realistically a user won't be able to examine 1M goroutines by hand, would they? So why don't we set the limit internally and only retrieve the selected goroutine and N more goroutines?

[polinasok]

When truncating the threads list, we should signal to the user that this happened by writing to the DEBUG console with an OutputEvent. If paging is added to DAP( microsoft/debug-adapter-protocol#159) and then to vscode UI, we can revisit this design. Ideally the CALL STACK would display something like "showing N threads out of M" with a button to load more and/or a search field to look up an individual thread.

[polinasok]

When trimming the list of threads to return, we should favor the threads that are stopped on breakpoints in user code over those in runtime.gopark because those are the ones the users might want to examine more closely, checking their stack and variables. This is related to #130 and #118.