microsoft / vscode-cpptools

Official repository for the Microsoft C/C++ extension for VS Code.
Other
5.45k stars 1.53k forks source link

Stepping in C++ debugger with moderately deep call stack unusably slow #2901

Closed lilbill39 closed 3 years ago

lilbill39 commented 5 years ago

Type: Debugger This looks like: https://github.com/Microsoft/vscode-cpptools/issues/363 however the issue still exists for me. When stepping in the debugger in our team's code base, next takes several seconds. I'm able to reproduce with a trivial project where next takes on the order of 1 second. The time seems to scale with stack depth and number of arguments of the callees in the stack.

Describe the bug

To Reproduce See attached: slow-step.zip

This contains a synthetic recursive function whose depth is controlled by the argument to main:

int rec (int x, int ub, std::vector<int> &v, std::vector<int> &v1, std::vector<int> &v2, std::vector<int> &v3, std::vector<int> &v4) {
    v[x] = x;
    if (x < ub) {
        return rec(x+1,ub,v,v1,v2,v3,v4);
    }
    return final(x,v,v1,v2,v3,v4);
}

where ub is read from the command line. I've artificially added std::vector as inputs to make rendering the stack frames more expensive and to model the actual production code I'm unable to debug. That code has several non-trivial inputs.

Use the configs:

  1. Build
  2. Set a breakpoint at main.cpp:5 on the first line of final
  3. Step over and notice the lag
  4. Increase the argument in the launch config and notice that debugging is progressively slower as you increase that.

Note that I was able to use CodeLLDB with lldb without any delays. I'd prefer to be able to use GDB.

BaronZemo commented 5 years ago

I've noticed this issue as well over the past couple of months, and two developers I work with have noticed this as well. I timed it, and it takes about 36 seconds to do a Step call.

BaronZemo commented 5 years ago

Also, this may be a separate issue, but in the past, the active call stack would show up in the Call Stack View. Now, I have to hunt through the 50 different threads I have active to find what call stack I'm currently in.

sean-mcmanus commented 5 years ago

@BaronZemo The issue you're describing is a VS Code bug being tracked by https://github.com/Microsoft/vscode/issues/68616 . It's supposed to be fixed in the February update, but the fix hasn't been made yet.

andrewleech commented 5 years ago

I'm also seeing this issue in a big way when debugging embedded targets, where the debugger link is slower I guess. The deeper the call stack, the slower the debugging. It's making embedded debugging of larger projects impossible with vscode

dwilliamson commented 5 years ago

Any update on this? My C++ app is taking 10 seconds between each step.

My callstack depth is only around 7 but there are over 30 threads that go into some kind of spin state before I can step again or inspect local variables:

image

pieandcakes commented 5 years ago

If you are doing multithreaded debugging, with the newer version of VS Code. They are requesting a Call stack for every thread when stopping, which is new behavior. Microsoft/vscode#68648 is open for this issue.

If your problem is single threaded stepping is slow, then comment below.

dbldippy commented 4 years ago

I also attach to a large remote GDB application. I see pages and pages of symbol requests (?):

1: (51213) <-1020-symbol-list-lines something.cpp
1: (51261) ->1020^done,lines=[{pc="0x00000024",line="0"},{pc="0x00000028",line="0"},... // large amount of lines 

Is there a way to scale-down debugging fidelity? For example, if you are not interested in the call stack you could just close the call stack view. Then vscode would not request call stack info from gdb. Analog, if you close the local variable view, symbol information would not be fetched, etc.

pieandcakes commented 4 years ago

@wauisaui If you want changes with VS Code's debug protocol behavior, you would need to request it with VS Code.

We need to list symbol lines to be able to correlate which source file line ties in with the stopping breakpoint. In the 0.26.0-insiders coming this week, there will be [an option(https://github.com/microsoft/vscode-cpptools/pull/4194) to configure or fine tune symbol loading to avoid loading symbols you don't need.

HackerBaloo commented 4 years ago

VSCode now shows "load more stack frames" but it is still a lot slower to debug in a deeper callstack it seams, perhaps we need to be able to set the number of frames loaded to improve this. I'm more than willing to investigate this further. I do experiance very slow debugging, the last step-into took 25 s. And I have noticed that this happens in our deep request threads, if I set a breakpoint in a worker thread, with a more shallow callstack the delay is almost not noticable. And the debugging can still be in the same classes so the local symbols is more or less the same.

pieandcakes commented 4 years ago

@HackerBaloo One of the issues we have is that for each frame, we make 2-3 requests to the debugger to get information such as the frame's variables and their types so that we can display all that information in the frame. This causes additional delay.

If you want to take a look, the MIEngine adapter is here and these are the instructions to patch your local extension.

HackerBaloo commented 4 years ago

OK, I'm very confused about how to setup a debugging environment for VSCode - gdb on Ubuntu 18.04. First, if I want to log what happens, I found this instruction: https://github.com/microsoft/VSDebugAdapterHost/wiki/Logging But that seems to be an instruction for Visual Studio, not for VSCode. And then for debugging: How To Debug MIEngine It seems that you have to build it on Windows, that's OK. But then here I get a bit confused: Debugging MIEngine running on Linux or Mac OS X Should I install GTK & Xamarin Studio on the Windows machine? Because it says: cd "\Program Files (x86)\MonoDevelop\bin" ... So I can't debug it directly on my Linux machine? Or is this the way to go: With VS Code + Mono Debug?

HackerBaloo commented 4 years ago

Well, I found out how to turn logging on, and it helped me understand the problem. step-out.zip I found that some var-create took a very long time. I then tried to disable our own python pretty-printers. First todays test case took around 13 s to step, but after disabling our pretty-printers it came down to around 5 s. Much better, but if I look in the attached log it is still a few "var-create" that takes hundreds of times more time than any of the other, and the ones taking time is very uninteresting to me. So are there any way to exclude the slow ones? And as I understand it, it should be possible to use natvis visualizers instead of the pretty-printers on Linux with VSCode to, but how do I do to let the environment now about our natvis files?

And also, this variables lives in frames of the callstack that I have not yet visited and probably will not visit, so why do they have to be loaded. Is that a question for MIEgine or for the cpp-extension?

pieandcakes commented 4 years ago

@HackerBaloo our documentation is to build and debug remotely the extension from Windows. If you want to debug on Linux you can use VS Code and the Mono extension.

First todays test case took around 13 s to step, but after disabling our pretty-printers it came down to around 5 s. Much better, but if I look in the attached log it is still a few "var-create" that takes hundreds of times more time than any of the other, and the ones taking time is very uninteresting to me. So are there any way to exclude the slow ones?

The problem is our goal is to decorate the entire stackframe with its variables. I think we can do the all/none approach but having it pick and choose is difficult.

And as I understand it, it should be possible to use natvis visualizers instead of the pretty-printers on Linux with VSCode to, but how do I do to let the environment now about our natvis files?

Natvis files will make more calls to gdb and then do the visualization in our debug adapter. I don't know if it is faster but it will allow you customize it.

And also, this variables lives in frames of the callstack that I have not yet visited and probably will not visit, so why do they have to be loaded. Is that a question for MIEgine or for the cpp-extension?

MIEngine is part of the cpptools extension and we contribute back to it. My above comment holds true in that we may be able to support all frame variables or none, which might help your scenario.

HackerBaloo commented 4 years ago

About the all/none or pick and choose, it's just annoying in my case that while most variables are created in 1 or 2 ms, there are 6 out of 50 var-create operations that is more than one digit in elapsed time. This four are more or less totally uninteresting, and consume almost all of the time. std::istream& elapsed time 2197 // who looks at istream in the debugger? std::istream& elapsed time 2144 MessageBuffer& elapsed time 524 MessageBuffer& elapsed time 521

The two last might be of interest GetPathsFromGuidsResult elapsed time 550 GetPathsFromGuidsResponseEncoder elapsed time 42

But what do you mean by the none in all/none? I would be fine with only loading the variables in the current frame, and only loading variables in other frames when those are selected.

Internet doesn't know how to setup natvis for VSCode, but it is said that it should work.

HackerBaloo commented 4 years ago

Well, I found out how to turn logging on, and it helped me understand the problem.

BTW for other reading this, to turn on the log: put this in one of you debug targets in launch.json "logging": { "trace": false, "traceResponse": false, "engineLogging": true } You get more output if you turn on the two trace settings, but I found it useful with just engineLogging. You get the output in the debug console.

HackerBaloo commented 4 years ago

I found a little bit of a workaround, I registered an extremely simple pretty printer like this:

class null_printer():
    """Pretty printer to avoid hevy printer for uninteresing types."""

    def __init__(self, val):
        pass

    def to_string(self):
        return "null_printer"

pp = gdb.printing.RegexpCollectionPrettyPrinter("my_printers")
pp.add_printer('istream', '^std::basic_.*stream<.*>$', null_printer)
pp.add_printer('MessageBuffer', '^tac::nsp::MessageBuffer$', null_printer)

That shaved of 500 ms from the istream and 300 ms from my message buffers, so now I'm down to ~ 4 s to step, a lot better than 13 s at least, and I now which variables that cause trouble. But there must still be something wrong, somewhere, to need 1600 ms to prepare to show "null_printer" for std::istream.

pieandcakes commented 4 years ago

But what do you mean by the none in all/none? I would be fine with only loading the variables in the current frame, and only loading variables in other frames when those are selected.

I would think we would show it for the current frame only and ignore the rest, but the feature will need to be specced out so it is a defined behavior.

But there must still be something wrong, somewhere, to need 1600 ms to prepare to show "null_printer" for std::istream.

If you look at the engineLog, that contains the requests from us to gdb and gdb's response. It also should include timings. unfortunately if the time is being spent by gdb you're probably better off filing an issue with gdb to let them know that theres a performance problem there.

BTW for other reading this, to turn on the log: put this in one of you debug targets in launch.json "logging": { "trace": false, "traceResponse": false, "engineLogging": true }

The documentation on engineLogging explains the settings in more detail. trace and traceResponse track communication from VS Code through the DebugAdapter Protocol to our debugAdapter. engineLogging tracks our communication to and from the debugger using the mi interface.

HackerBaloo commented 4 years ago

I would think we would show it for the current frame only and ignore the rest, but the feature will need to be specced out so it is a defined behavior.

Sounds great, I would be an eager beta tester of that.

If you look at the engineLog, that contains the requests from us to gdb and gdb's response. It also should include timings. unfortunately if the time is being spent by gdb you're probably better off filing an issue with gdb to let them know that theres a performance problem there.

I will investigate that more tomorrow.

HackerBaloo commented 4 years ago

It seems to me that: "engineLogging": true is what is needed to see what I get from gdb, but I'm not sure. Is the elapsed time here, time spent in gdb? and with: "trace": true I also get the requests to gdb I think. What I have found out today is that is not as simple as std::istream always takes a lot of time, in a simple sample project it takes just around 1 ms to create that variable.

So would the gdb project recognize the content of the log and be able to help, or would the just blame the extension?

pieandcakes commented 4 years ago

with engineLogging those are the commands in mi format that we send to gdb and its responses. If you send those to the gdb project they should be able to investigate further.

As a side note, can you try regular gdb (not mi mode) and see if its slow too? They will probably want to know if it is a bug in their mi interface code.

gdb/mi related documentation.

HackerBaloo commented 4 years ago

Well, the gdb-people wanted me to profile the issue. So I would like to start gdb under valgrind. Can I "trick" VSCode to do that? Or do I need to try to mimic how VSCode runs gdb by hand?

HackerBaloo commented 4 years ago

Well I have found the work around that solves the problem for me. I use another VSCode extension called "Native Debug" for debugging.

rlivings39 commented 4 years ago

Are you using gdb with native debug and getting good performance? If so then that seems to rule out gdb being slow.

Note that we've recently seen another debugging regression with cpptools and gdb. The stack rendering is very slow and that blocks all interaction with the debugger until it finishes. That makes hitting breakpoints and stepping take 5-10s in our code base. In that same place doing (gdb) bt in the debug console is very fast.

Frankly the fact that stack rendering is synchronous and blocks the rest of the debugger seems like a huge design flaw. When I'm stepping I don't need a stack until I find where I'm going and pause for a while.

andrewleech commented 4 years ago

It's definitely not just a gdb problem. Ive been switching between vscode-cpptools and the cortex-debug extension for working with embedded arm devices. Same gdb exe used for both. Cortex-debug has equally fast stepping/breakpoints no matter how far down the stack it is. I think it only fetches a few/limited frames worth by default or something.

HackerBaloo commented 4 years ago

Well I think it is quite clear, I found a little performance problem that makes it worse for vscode-cpptoles less than optimal way of getting all variables in the call stack when hitting a breakpoint, instead of just getting the variables at the current frame.

konradsa commented 4 years ago

Any update on this? Overall this is a big problem for people that use the debugger frequently, and would be good if that can be addressed. Native Debug plugin offers much better performance, but it has some other issues that make it a non starter for me. Overall the performance in Vscode is even significantly worse than what Eclipse CDT offers. There are also a couple of tricks in Eclipse CDT to make debugging faster that don't work in Vscode:

These actions make Eclipse not update the Variables or Call Stack views after every step, and makes it significantly faster. Unfortunately, this doesn't work in Vscode, even after hiding these views, it looks like the data is still pulled after every step.

And like others have said, this is not a gdb problem, gdb itself is quite fast. It's pulling all the data for the views that makes it slow.

github-actions[bot] commented 3 years ago

This issue has been closed automatically because it has not had recent activity.

philipcraig commented 3 years ago

There's no recent activity as the problem isn't fixed. Not a lot to say about it except request for it to be fixed. For a workaround, use the code-lldb extension. The downside is worse out-of-the-box visualiser support

konradsa commented 3 years ago

I second the opinion that this problem has not been solved. This should really be reopened and investigated, it's a constant nuisance when debugging with vscode.

I wish I could do this at my job, if I just ignore a problem long enough, it gets closed! :-)

DarshanRamakant commented 2 years ago

I am also facing exact same issue. Step is taking around 40 seconds while debugging clang source code. I tried to write customized .gdbinit but it did not help. Is there any gdb trick that I can use ( enable / disable pretty print) to make it fast ?

DarshanRamakant commented 2 years ago

Well I have found the work around that solves the problem for me. I use another VSCode extension called "Native Debug" for debugging.

Thanks, stepping is fast using this extension. But the information that we get on hovering on a variable seems less here.

fkap69 commented 2 years ago

I can confirm that I have this slow stepping behavior in Debian 11 with vs code 1.62.0. Makes debugging really annoying and time consuming. So much that I decided to search about it and found this ticket. We are all developers here, this ticket should not be closed, it's a shame !! In the meantime I will also try the "native debug" extension.

rlivings39 commented 2 years ago

@pieandcakes @sean-mcmanus @WardenGnaw Since people are still seeing slowness, what's the right way to ask for help? Reopen this issue? Make a new issue? Any debug info we can give to help isolate the source of the problem?

This has recently blocked some folks on my team as well. They had to switch to using other debugging extensions as a result.

konradsa commented 2 years ago

I agree, this issue is really frustrating. Especially since I think there could be some easy optimizations to alleviate the problem for the most part. For instance Eclipse CDT has a similar slowness issue, mostly brought on by the fact that the debugger UI queries the stack and local variables after every step, which is a very expensive operation. But in Eclipse at least, you can minimize the Stack or Variables views in the UI, and the extension stops querying the information, which speeds up debugging a lot. In Vscode however, minimizing the VARIABLES or CALL STACK views has no effect, it looks like the information still keeps getting queried on every step.

That's why native gdb is so much faster as well, it doesn't query variables and call stacks after every step.

Lounarok commented 2 years ago

Might related to https://github.com/microsoft/vscode/issues/132025

27629678 commented 1 year ago

use 「Native Debug Extension: https://marketplace.visualstudio.com/items?itemName=webfreak.debug 」instead。

VascoFraga commented 1 year ago

This native debugger extension didn't help in my case. On the other hand CodeLLDB vscode extension did the trick for me.

rerdavies commented 1 year ago

Please fetch the stack frames on demand!! There is absolutely no reason to get every stack frame of every thread except programmer laziness. The easier fix would be not to fetch the stack frames if the thread stack view isn't expanded. Not a complete solution, by any means, but it would at least make it possible to painfully debug projects with deep stacks.

Projects are Linux (Ubuntu, Raspberry Pi), variously using GCC 10.2, Clang 14 or Clang 15. Clang 15 is a much faster build; but all of them have problems with debug performance.

I have two projects that are moderately painful (15 or 29 seconds to step), although I only just made the connection with threads and stack frames. And a third which which is completely unusable.

I'm attaching to this project https://github.com/Ardour/ardour, built with debug symbols., trying to debug a problem with an LV2 audio plugin. It takes 3 minutes to single-step. Sure. it's a medium-sized project (~120k lines of source code), but not remotely close to a huge project. And the stack usage is nothing out of the ordinary for a GTK/gtkmm application.

doug65536 commented 5 months ago

I investigated painful stops (15 seconds per step is unbearable). It was the backtrace (call stack window) killing it. Running GDB CLI everything seemed instant, until I did bt, then saw the cause. The debugger is getting the stack trace even when the call stack pane is collapsed. vscode is getting the backtrace for nothing.

vipcxj commented 4 months ago

The vscode c++ debugger is currently unavailable, it takes a few minutes for a single STEP, I don't see the point of this debugger.