Debug Excessively Slow Stepping Through Code

[teschste-reyrey]

Please answer the following before submitting your issue:

Note: Please include any substantial examples (debug session output, stacktraces, etc) as linked gists.

If this is about source listing not showing up (or breakpoints not being accepted) while running in a container please read our FAQ first.

1. What version of Delve are you using (dlv version)? 1.22.1

2. What version of Go are you using? (go version)? 1.22.1

3. What operating system and processor architecture are you using? Windows 10 Pro amd64 (actual processor Intel(R) Core(TM) i9-9900 CPU @ 3.10GHz 3.10 GHz)

4. What did you do? Stepped through Go code in VS Code.

5. What did you expect to see? Each step occurring almost instantly as it always has in the past.

6. What did you see instead? Instead of each step being almost instantaneous as usual, each step takes anywhere from 2-3 seconds for a 2 line application, to 12-13 seconds for a larger application.

I am not certain what triggered it, though it was shortly after upgrading to Go v1.22.1 that I noticed it.

If I just run the app in VS Code (assuming there are no errors), it runs fast as usual, this only occurs when stepping through the code.

I moved back down to Go v1.21.8 to see if it was related to my recent upgrade but the issue remained, so I moved back up to 1.22.1.

Since I saw no other issues like this reported, this is likely something unique to me (though another person on my team is having the same issue) but I even tried completely uninstalling and reinstalling Go and Delve with no improvement and nothing else changed in the timeframe this occurred.

I tried reverting from VS Code 1.87, back down to 1.86 but that did not help so I moved back up to 1.87.

I originally reported this under golang (https://github.com/golang/go/issues/66173) but they closed it claiming it looked like a Delve issue, so here I am.

[aarzilli]

Does this reproduce when using delve from the command line? If it doesn't it would help to see the logs of delve, you can get them by setting showLog and logOutput=dap in launch.json.

[teschste-reyrey]

It happens when I run delve from the command line as well.

However, for completeness, I have also attached the log you mentioned when running in the IDE. I set a breakpoint, and stepped through that one line, then stopped the code. Delve.log

[aarzilli]

If you have antivirus/security software running you should try disabling them to rule them out as a cause. You should also check task manager to see if there's anything strange going on when delve is stepping.

Other than that you can go in pkg/proc/native/proc.go and add log lines to ContinueOnce to see what it is that is taking so much time.

[teschste-reyrey]

I added logging to that function in proc.go but it does not appear that function is executing because nothing I do has any effect. Does delve need to be recompiled? If so, I cannot do that, as when I load delve into Visual Studio, there are over 700 errors generated, most seeming to be regarding packages that cannot be loaded, that I am not able to resolve.

[aarzilli]

Does delve need to be recompiled?

Yes

If so, I cannot do that, as when I load delve into Visual Studio, there are over 700 errors generated, most seeming to be regarding packages that cannot be loaded, that I am not able to resolve.

I'm not sure what you are doing exactly to have this problem, you should be able to make a checkout of delve's repository, change it and then do go install github.com/go-delve/delve/cmd/dlv from the checkout directory.

[teschste-reyrey]

Obviously I was doing it wrong! 🤣 Thanks for setting me straight. I went a bit excessive on the logging because I wanted to do this once (updated file attached for reference as proc.txt).

I saw no delays in ContinueOnce. I have attached the debug.log again, the first time ContinueOnce executes is at startup, running to the breakpoint I set. The second timeContinueOnce executes, is after the delay happens (i.e. after the step executed). You can see the approximately 9 second delay occurring between the following2 lines:

2024-03-08T12:17:51-06:00 debug layer=debugger  17532 PC=0x7fffac44d064
2024-03-08T12:18:00-06:00 debug layer=debugger switching to goroutine 1

Any other thoughts?

[aarzilli]

Any other thoughts?

if it's not that I think the only other thing it could be is something in the next function in pkg/proc/target_exec.go.

[teschste-reyrey]

I added logging to target_exec.Next() and the hangup occurred at this line:

if err = next(grp.Selected, false, false); err != nil {

Then I added logging in target_exec.next(), which I saw running the following loop 86 times, which seemed to account for the delay. Note that the if statement never errored.

for _, pc := range pcs {
  if _, err := allowDuplicateBreakpoint(dbp.SetBreakpoint(0, pc, NextBreakpoint, sameFrameCond)); err != nil {
    dbp.ClearSteppingBreakpoints()
    return err
  }
}

After I removed my logging, which was adding to the delay, you can see the delay is indeed happening in target_exec.next() from the following log lines. The first line showing next starting and the last line showing next exiting.

2024-03-08T15:31:12-06:00 debug layer=dap [<- from client]{"seq":13,"type":"request","command":"next","arguments":{"threadId":1}}
2024-03-08T15:31:12-06:00 debug layer=dap [-> to client]{"seq":0,"type":"event","event":"continued","body":{"threadId":1,"allThreadsContinued":true}}
2024-03-08T15:31:12-06:00 debug layer=dap [-> to client]{"seq":0,"type":"response","request_seq":13,"success":true,"command":"next"}
2024-03-08T15:31:52-06:00 debug layer=dap "next" command stopped - reason "next finished", location E:/Dev/Programs/Hardware Manuals DB Sync/main.go:65

Hope that helps!

[aarzilli]

If it's a big function it's fine for that loop to execute many times, the problem is that SetBreakpoint is slow. It looks like reading/writing process memory is slow on your system for some reason. My guess is still that this is a problem with an antivirus.

[aarzilli]

Similar thing happening: https://developercommunity.visualstudio.com/t/vs-2017-1554-debugging-extremely-slow/183838

[derekparker]

Going to close this issue as not a bug in Delve unless more information comes out. Thanks!

[ankon]

For future readers: I had a similar "excessively slow stepping" issue with the most recent delve, and noticed that during the time where nothing happens one of the vscode processes would consume 100% of a single CPU core. The process pointed to the debug adapter itself.

For me the problem vanished completely after switching to the nightly golang extension: https://github.com/golang/vscode-go/wiki/nightly; I didn't see any particular fix though that would look related. Still, worth a shot.

[teschste-reyrey]

Switching to Go Nightly did not resolve this issue for me, nor did disabling all anti-virus.