Vim-go: GoDebugContinue experiences delays in Windows

[liwnn]

What did you do? (required: The issue will be closed when not provided)

Debug a file in windows 10.

// main.go in path D:\GOPATH\src\foo, and main.go is the only file.
package main

func main() {
        var i = 10;
    println(i)
}

1. Open main.go with gvim.
2. :GoDebugStart
3. :GoDebugBreakpoint add a breakpoint on line "println(i)"
4. :GoDebugContinue

What did you expect to happen?

Debugging is ok

What happened instead?

Gvim will be blocked for more than 1minutes.
I found that the "call s:update_goroutines()" and "call s:update_variables()" cause the block.
Every call in RPCServer.State RPCServer.ListGoroutines RPCServer.Stacktrack RPCServer.ListLocalVars and RPCServer.ListFunctionArgs will sleep 20 seconds when call function "ch_readraw".

ERR: 2019-12-24T11:20:08+08:00 info layer=debugger launching process with args: [C:\Users\master\AppData\Local\Temp\VID94B4.tmp]
ERR: 2019-12-24T11:20:09+08:00 debug layer=rpc <- RPCServer.CreateBreakpoint(rpc2.CreateBreakpointIn{"Breakpoint":{"id":0,"name":"","addr":0,"addrs":null,"file":"D:/GOPATH/src/foo/main.go","line":5,"Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":null,"totalHitCount":0}})
ERR: 2019-12-24T11:20:09+08:00 info layer=debugger created breakpoint: &api.Breakpoint{ID:1, Name:"", Addr:0x454b4d, Addrs:[]uint64{0x454b4d}, File:"D:/GOPATH/src/foo/main.go", Line:5, FunctionName:"main.main", Cond:"", Tracepoint:false, TraceReturn:false, Goroutine:false, Stacktrace:0, Variables:[]string(nil), LoadArgs:(*api.LoadConfig)(nil), LoadLocals:(*api.LoadConfig)(nil), HitCount:map[string]uint64{}, TotalHitCount:0x0}
ERR: 2019-12-24T11:20:09+08:00 debug layer=rpc -> *rpc2.CreateBreakpointOut{"Breakpoint":{"id":1,"name":"","addr":4541261,"addrs":[4541261],"file":"D:/GOPATH/src/foo/main.go","line":5,"functionName":"main.main","Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":{},"totalHitCount":0}} error: ""
ERR: 2019-12-24T11:20:19+08:00 debug layer=rpc (async 2) <- RPCServer.Command(api.DebuggerCommand{"name":"continue","ReturnInfoLoadConfig":null})
ERR: 2019-12-24T11:20:19+08:00 debug layer=debugger continuing
ERR: 2019-12-24T11:20:19+08:00 debug layer=rpc (async 2) -> rpc2.CommandOut{"State":{"Running":false,"currentThread":{"id":19612,"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"breakPoint":{"id":1,"name":"","addr":4541261,"addrs":[4541261],"file":"D:/GOPATH/src/foo/main.go","line":5,"functionName":"main.main","Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":{"1":1},"totalHitCount":1},"breakPointInfo":{},"ReturnValues":null},"currentGoroutine":{"id":1,"currentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":4508261,"file":"c:/go/src/runtime/asm_amd64.s","line":201,"function":{"name":"runtime.rt0_go","value":4507952,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":4370432,"file":"c:/go/src/runtime/proc.go","line":110,"function":{"name":"runtime.main","value":4370432,"type":0,"goType":0,"optimized":true}},"threadID":19612,"unreadable":""},"Threads":[{"id":10544,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":1420,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":6576,"pc":140734434230596,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":18828,"pc":140734434230596,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":5472,"pc":140734433734176,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":19612,"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"breakPoint":{"id":1,"name":"","addr":4541261,"addrs":[4541261],"file":"D:/GOPATH/src/foo/main.go","line":5,"functionName":"main.main","Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":{"1":1},"totalHitCount":1},"breakPointInfo":{},"ReturnValues":null},{"id":6632,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""
ERR: 2019-12-24T11:20:19+08:00 debug layer=rpc <- RPCServer.State(rpc2.StateIn{"NonBlocking":false})
ERR: 2019-12-24T11:20:19+08:00 debug layer=rpc -> *rpc2.StateOut{"State":{"Running":false,"currentThread":{"id":19612,"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"breakPoint":{"id":1,"name":"","addr":4541261,"addrs":[4541261],"file":"D:/GOPATH/src/foo/main.go","line":5,"functionName":"main.main","Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":{"1":1},"totalHitCount":1},"ReturnValues":null},"currentGoroutine":{"id":1,"currentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":4508261,"file":"c:/go/src/runtime/asm_amd64.s","line":201,"function":{"name":"runtime.rt0_go","value":4507952,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":4370432,"file":"c:/go/src/runtime/proc.go","line":110,"function":{"name":"runtime.main","value":4370432,"type":0,"goType":0,"optimized":true}},"threadID":19612,"unreadable":""},"Threads":[{"id":6632,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":10544,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":1420,"pc":140734434245204,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":6576,"pc":140734434230596,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":18828,"pc":140734434230596,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":5472,"pc":140734433734176,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":19612,"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false},"goroutineID":1,"breakPoint":{"id":1,"name":"","addr":4541261,"addrs":[4541261],"file":"D:/GOPATH/src/foo/main.go","line":5,"functionName":"main.main","Cond":"","continue":false,"traceReturn":false,"goroutine":false,"stacktrace":0,"LoadArgs":null,"LoadLocals":null,"hitCount":{"1":1},"totalHitCount":1},"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListGoroutines(rpc2.ListGoroutinesIn{"Start":0,"Count":0})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListGoroutinesOut{"Goroutines":[{"id":1,"currentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"userCurrentLoc":{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false}},"goStatementLoc":{"pc":4508261,"file":"c:/go/src/runtime/asm_amd64.s","line":201,"function":{"name":"runtime.rt0_go","value":4507952,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":4370432,"file":"c:/go/src/runtime/proc.go","line":110,"function":{"name":"runtime.main","value":4370432,"type":0,"goType":0,"optimized":true}},"threadID":19612,"unreadable":""},{"id":2,"currentLoc":{"pc":4371787,"file":"c:/go/src/runtime/proc.go","line":302,"function":{"name":"runtime.gopark","value":4371568,"type":0,"goType":0,"optimized":true}},"userCurrentLoc":{"pc":4371787,"file":"c:/go/src/runtime/proc.go","line":302,"function":{"name":"runtime.gopark","value":4371568,"type":0,"goType":0,"optimized":true}},"goStatementLoc":{"pc":4371212,"file":"c:/go/src/runtime/proc.go","line":239,"function":{"name":"runtime.init.5","value":4371152,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":4371232,"file":"c:/go/src/runtime/proc.go","line":242,"function":{"name":"runtime.forcegchelper","value":4371232,"type":0,"goType":0,"optimized":true}},"threadID":0,"unreadable":""},{"id":3,"currentLoc":{"pc":4371787,"file":"c:/go/src/runtime/proc.go","line":302,"function":{"name":"runtime.gopark","value":4371568,"type":0,"goType":0,"optimized":true}},"userCurrentLoc":{"pc":4371787,"file":"c:/go/src/runtime/proc.go","line":302,"function":{"name":"runtime.gopark","value":4371568,"type":0,"goType":0,"optimized":true}},"goStatementLoc":{"pc":4281071,"file":"c:/go/src/runtime/mgc.go","line":208,"function":{"name":"runtime.gcenable","value":4280976,"type":0,"goType":0,"optimized":true}},"startLoc":{"pc":4314320,"file":"c:/go/src/runtime/mgcsweep.go","line":64,"function":{"name":"runtime.bgsweep","value":4314320,"type":0,"goType":0,"optimized":true}},"threadID":0,"unreadable":""}],"Nextg":-1} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.Stacktrace(rpc2.StacktraceIn{"Id":1,"Depth":5,"Full":false,"Defers":false,"Opts":0,"Cfg":null})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.StacktraceOut{"Locations":[{"pc":4541261,"file":"D:/GOPATH/src/foo/main.go","line":5,"function":{"name":"main.main","value":4541216,"type":0,"goType":0,"optimized":false},"Locals":null,"Arguments":null,"FrameOffset":-104,"FramePointerOffset":-120,"Defers":[],"Err":""},{"pc":4370865,"file":"c:/go/src/runtime/proc.go","line":200,"function":{"name":"runtime.main","value":4370432,"type":0,"goType":0,"optimized":true},"Locals":null,"Arguments":null,"FrameOffset":-32,"FramePointerOffset":-48,"Defers":[],"Err":""},{"pc":4516673,"file":"c:/go/src/runtime/asm_amd64.s","line":1337,"function":{"name":"runtime.goexit","value":4516672,"type":0,"goType":0,"optimized":true},"Locals":null,"Arguments":null,"FrameOffset":-24,"FramePointerOffset":-824633974784,"Defers":[],"Bottom":true,"Err":""}]} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListLocalVars(rpc2.ListLocalVarsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListLocalVarsOut{"Variables":[{"name":"i","addr":824633974656,"onlyAddr":false,"type":"int","realType":"int","flags":0,"kind":2,"value":"10","len":0,"cap":0,"children":[],"base":0,"unreadable":"","LocationExpr":"[block] DW_OP_fbreg -0x18 ","DeclLine":4}]} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListFunctionArgs(rpc2.ListFunctionArgsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListFunctionArgsOut{"Args":[]} error: ""

Configuration (MUST fill this out):

vim-go version:

The master branch

vimrc you used to reproduce (use a minimal vimrc with other plugins disabled; do not link to a 2,000 line vimrc):

vimrc

set encoding=utf-8

set fileencodings=ucs-bom,utf-8,gbk

set shiftwidth=4

filetype plugin indent on

syntax on

set tabstop=4


let g:go_fmt_command = "goimports"

let g:go_gocode_unimported_packages = 1

let g:go_list_type = 'quickfix'

let g:go_list_height = 10

let g:go_highlight_types = 2

let g:go_highlight_fields = 1

let g:go_highlight_functions = 1

let g:go_highlight_function_calls = 1

let g:go_highlight_operators = 1

let g:go_highlight_variable_declarations = 1

let g:go_highlight_variable_assignments = 1

let g:go_debug=['debugger-commands']

Vim version (first three lines from :version):

VIM - Vi Improved 8.2 (2019 Dec 12, compiled Dec 15 2019 23:02:11)
MS-Windows 64-bit GUI version with OLE support
Included patches: 1-12

Go version (go version):

go version go1.12.9 windows/amd64

Go environment

go env Output:

set GOARCH=amd64

set GOBIN=

set GOCACHE=C:\Users\master\AppData\Local\go-build

set GOEXE=.exe

set GOFLAGS=

set GOHOSTARCH=amd64

set GOHOSTOS=windows

set GOOS=windows

set GOPATH=D:\GOPATH;

set GOPROXY=

set GORACE=

set GOROOT=c:\go

set GOTMPDIR=

set GOTOOLDIR=c:\go\pkg\tool\windows_amd64

set GCCGO=gccgo

set CC=gcc

set CXX=g++

set CGO_ENABLED=1

set GOMOD=

set CGO_CFLAGS=-g -O2

set CGO_CPPFLAGS=

set CGO_CXXFLAGS=-g -O2

set CGO_FFLAGS=-g -O2

set CGO_LDFLAGS=-g -O2

set PKG_CONFIG=pkg-config

set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\master\AppData\Local\Temp\go-build111512062=/tmp/go-build -gno-record-gcc-switches

[bhcleek]

I'm confused.

ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListLocalVars(rpc2.ListLocalVarsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListLocalVarsOut{"Variables":[{"name":"i","addr":824633974656,"onlyAddr":false,"type":"int","realType":"int","flags":0,"kind":2,"value":"10","len":0,"cap":0,"children":[],"base":0,"unreadable":"","LocationExpr":"[block] DW_OP_fbreg -0x18 ","DeclLine":4}]} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListFunctionArgs(rpc2.ListFunctionArgsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListFunctionArgsOut{"Args":[]} error: ""

seems to show that ListLocalVars and ListFunctionArgs are processed by delve very quickly. 🤔

[liwnn]

I'm confused.

ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListLocalVars(rpc2.ListLocalVarsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListLocalVarsOut{"Variables":[{"name":"i","addr":824633974656,"onlyAddr":false,"type":"int","realType":"int","flags":0,"kind":2,"value":"10","len":0,"cap":0,"children":[],"base":0,"unreadable":"","LocationExpr":"[block] DW_OP_fbreg -0x18 ","DeclLine":4}]} error: ""
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc <- RPCServer.ListFunctionArgs(rpc2.ListFunctionArgsIn{"Scope":{"GoroutineID":1,"Frame":0,"DeferredCall":0},"Cfg":{"FollowPointers":false,"MaxVariableRecurse":0,"MaxStringLen":20,"MaxArrayValues":20,"MaxStructFields":0}})
ERR: 2019-12-24T11:21:59+08:00 debug layer=rpc -> *rpc2.ListFunctionArgsOut{"Args":[]} error: ""

seems to show that ListLocalVars and ListFunctionArgs are processed by delve very quickly. 🤔

But i do DebugContine in at time 2019-12-24T11:20:19+08:00.

[liwnn]

I add some debug code.

Here is a gif of RPCServer.State waiting the return for 20 seconds.

[bhcleek]

If your analysis is correct and it's simply waiting for ch_readraw to return, then I'm not sure that anything can be done by vim-go to improve this performance.

Here's some things that could help us narrows down to a root cause, though:

1. Do you see the same delay after running :GoDebugStop and then running :GoDebug again?
2. Do you see delays when running :GoDebugContinue after hitting a breakpoint?
3. Do you see this same delay when using delve's command line client to debug the same application?
4. Update to the latest delve by running :GoUpdateBinaries dlv - does it change the behavior you're seeing now or either of the answers to the two previous questions?
5. Can duplicate this behavior when in a different GOPATH -- is this behavior somehow related to the size of your GOPATH)?

https://github.com/go-delve/delve/issues/970 may be relevant here.

edit: added another question

[liwnn]

If your analysis is correct and it's simply waiting for ch_readraw to return, then I'm not sure that anything can be done by vim-go to improve this performance.

Here's some things that could help us narrows down to a root cause, though:

1. Do you see the same delay after running `:GoDebugStop` and then running `:GoDebug` again?

2. Do you see delays when running `:GoDebugContinue` after hitting a breakpoint?

3. Do you see this same delay when using delve's command line client to debug the same application?

4. Update to the latest delve by running `:GoUpdateBinaries dlv` - does it change the behavior you're seeing now or either of the answers to the two previous questions?

5. Can duplicate this behavior when in a different GOPATH  -- is this behavior somehow related to the size of your GOPATH)?

go-delve/delve#970 may be relevant here.

edit: added another question

1. Do you see the same delay after running :GoDebugStop and then running :GoDebug again?
   Yes. It has the same delay.
2. Do you see delays when running :GoDebugContinue after hitting a breakpoint?
   Yes. It has the same delay.
3. Do you see this same delay when using delve's command line client to debug the same application?
   Delve's command works well.
4. Update to the latest delve by running :GoUpdateBinaries dlv - does it change the behavior you're seeing now or either of the answers to the two previous questions?
   I use the newest dlv version of 1.3.2.
5. Can duplicate this behavior when in a different GOPATH -- is this behavior somehow related to the size of your GOPATH)?
   It have the same problem.

I have install VSCode, and it use the same dlv. The VSCode works well. So, i don't konw whether it is dlv's bug or vim's.

[bhcleek]

Thank you for the prompt replies. I'll look into more soon when I have access to a Windows machine again.

[bhcleek]

I was able to duplicate the issue you're describing. I'll do more analysis this week and try to identify a fix.

[bhcleek]

I've been able to narrow this down. It seems that ch_readraw on Windows is blocking for the full timeout period. Since vim-go sets the timeout to 20 seconds, each call to ch_readraw blocks for 20 seconds on Windows. I should be able to address this. I'm going to look for a proper fix, but if I can't find one, I'll craft a workaround.

[bhcleek]

@liwnn I'm curious whether #2932 resolves this for you. Can you give it a try?

[liwnn]

@liwnn I'm curious whether #2932 resolves this for you. Can you give it a try?

Yes, it resolved this.