Slow stepping. Here is why I think

[BitFlipper]

Hi,

I have posted a thread about this issue before but I can’t locate it now. But I want to bring this up again because it seems there is opportunity to greatly reduce this issue.

I have a pretty large project, and single stepping through the code is very slow. It takes about 3 seconds for each step. It doesn’t sounds like a lot, but it is painful to step through 1000’s of lines of code a day with this delay.

I looked at the timing of the GDB commands, and noticed that the step itself completes quickly at roughly 100 ms. But then VGDB issues a lot of stack/frame related commands to get the current state. However it repeats the same command 3 or 4 times, with the exact same reply from GDB. Why does it issue the same command multiple times if the result is just going to be the same?

For example, below is output from VGDB for a single step operation. Note I filtered out everything but the actual commands that VGDB sends to GDB. After each command there is of course the GDB reply, but for now we don’t care about those. It is important to know that GDB responds with exactly the same reply if VGDB sends it the exact same command. So:

 

[   27908 ms] -exec-step
[   28024 ms] -stack-list-frames –thread 1
[   28049 ms] -stack-list-frames –thread 1
[   28053 ms] -stack-list-arguments –thread 1 1
[   28165 ms] -stack-list-frames –thread 1
[   28170 ms] -stack-list-arguments –thread 1 0
[   28181 ms] -stack-list-frames –thread 1
[   28185 ms] -stack-list-arguments –thread 1 0
[   28194 ms] -stack-list-frames –thread 2
[   28201 ms] -stack-list-arguments –thread 2 0
[   28316 ms] -stack-list-frames –thread 2
[   28322 ms] -stack-list-arguments –thread 2 0
[   28454 ms] -stack-list-frames –thread 3
[   28472 ms] -stack-list-arguments –thread 3 0
[   28686 ms] -stack-list-frames –thread 3
[   28695 ms] -stack-list-arguments –thread 3 0
[   28971 ms] -stack-list-frames –thread 4
[   28988 ms] -stack-list-arguments –thread 4 0
[   29240 ms] -stack-list-frames –thread 4
[   29252 ms] -stack-list-arguments –thread 4 0
[   29519 ms] -stack-list-frames –thread 5
[   29535 ms] -stack-list-arguments –thread 5 0
[   29718 ms] -stack-list-frames –thread 5
[   29725 ms] -stack-list-arguments –thread 5 0
[   29945 ms] -stack-list-frames –thread 6
[   29965 ms] -stack-list-arguments –thread 6 0
[   30295 ms] -stack-list-frames –thread 6
[   30304 ms] -stack-list-arguments –thread 6 0
[   30624 ms] -stack-list-frames –thread 7
[   30632 ms] -stack-list-arguments –thread 7 0
[   30717 ms] -stack-list-frames –thread 7
[   30733 ms] -stack-list-arguments –thread 7 0
[   30922 ms] -stack-list-frames –thread 8
[   30926 ms] -stack-list-arguments –thread 8 0
[   30969 ms] -stack-list-frames –thread 8
[   30973 ms] -stack-list-arguments –thread 8 0
[   31088 ms] -stack-list-frames –thread 1

 

I bolded one of the commands that is repeated 4 times. Most others are repeated 2 times. So my question is why is VGDB sending the same commands to GDB if the result is going to be the same? If each unique command is only sent once, it can easily cut the delay by more than half.

In addition to the above, I’m also wondering if VGDB can send all the commands without first waiting for the response from GDB for each one. Is there a reason to wait?  You are still going to get the same stream of responses from GDB in exactly the same order. So you should be able to match them up easily with the original list of commands that were sent.

Another thought. Is it really necessary to get stack frame info on all threads after each step? Unless the Threads or the Parallel Stacks window is open (can VGDB tell?), why is any stack info needed for any but the current thread? Maybe an option to only retrieve info for the current thread.

BTW I did play with the “Force single-threaded mode” but it made no difference whatsoever.

Thanks in advance for any help with this.

• This topic was modified 8 years, 2 months ago by BitFlipper.

[support]

Hi,

Can you try VisualGDB 5.2 Beta 2? We have optimized the thread-related logic in v5.2, so if the threads window is hidden, it should not query and thread information at all and will cache things as well.

[BitFlipper]

Hi,

OK I will give it a try but I’m very hesitant of trying beta builds. Can I revert if it breaks something?

I did the following experiment:

1. Created a GDB command file with this content:
   # Step once and get stacks info from all threads
   define stepone
   step
   thread apply all bt
   end
2. Added the following under GDB Startup Commands:
   source <path to command file>
3. After hitting a breakpoint, execute the following command:
   stepone

The whole command takes about 300ms to execute, vs 3000ms. AFAICT, the backtraces contain the same info than what you get from all the individual commands that VGDB executes after each step or after hitting a breakpoint.

This should make a huge difference with slower connections. “Use a faster connection” just isn’t always a possible option.

[BitFlipper]

After upgrading to VGDB 5.2. Beta 2, the VGDB project settings on the context menu is gone. Did something change that could cause this? When I press F5, it says the *.vgdbsettings file does not exist. I went into the VS NMake properties of the project and noticed the “Output” value of *vgdbsettings file name was changed, with “-” converted to “_”. I changed them back, but still got an error that the *.vgdbsettings file is not a valid Win32 executable.

Next I created a new test solution with a VGDB project. The wizard wanted me to enter the build/debug machine’s info, which I did. But it then tried to build something there which is not what I use VGDB for. I only use it for debugging alone, not building or deploying. I was able to configure the previous version of VGDB to only debug. In fact the debug machine has no ability to compile anything and this should not be required.

TBH I don’t remember exactly how I created the original VGDB project, so maybe I just didn’t go through the same wizard back then.

Can you let me know how to make VGDB 5.2. Beta 2 work the same way as 5.1 did? In the meantime I reverted back to 5.1 and now it works again.

Thanks in advance for any help with this.

• This reply was modified 8 years, 2 months ago by BitFlipper.

[support]

Hi,

This looks like a bug. The v5.2 uses a different internal mechanism for locating the .vgdbsettings files (using the name from NMake Project Properties for all cases). Perhaps there is a typo somewhere or some special character in the project name is causing trouble? Would you be able to share your .vcxproj and .vgdbsettings files so that we could quickly check what is causing this and fix it?

VisualGDB always tries to check that the toolchain can build valid code when you create a new project. You can simply ignore any errors it discovers and proceed with the project creation if you don’t care about building. We did not change any logic related to this in v5.2. Please feel free to send us the project file (and the .vgdbsettings file) so that we could help you resolve this.

[BitFlipper]

I have reverted to 5.1 for now, but if you say the .vgdsettings name is using a different way to locate the .vgdbsettings file then that must be the problem.

My .vgdbsettings file is named like this:

MyProject.vcxproj
MyProject-MyProject.vgdbsettings

I’m not sure why it is following that specific naming pattern but IIRC that is the pattern I originally saw the 1st time I created a VGDB project a few years ago.

So are you saying that if I change the name to MyProject.vgdbsettings that it should then work? My deadlines are very aggressive so I’m hesitant to make drastic changes (upgrade to beta version for instance) to my dev environment since it is quite elaborate and TBH, a bit fragile.

Thanks again in advance for any help with this.

[BitFlipper]

I finally got some time to look further into the issue with the beta not working for me. I created a new test project I found there were two issues. One is that if the project has a “-” in its name, then the.vgdbsettings filename get renamed by replacing “-” with “_”. E.g, if the project name is “My-Project.vcxproj”, it will be renamed to something like “My_Project-Debug.vgdbsettings”.

The second problem was that in the old projects, the NMake Output values is set to “My-Project-Debug.vgdbsettings”, while in the beta project it is “$(ProjectDir)My-Project-Debug.vgdbsettings”. So there is a missing “$(ProjectDir)” when an old project is opened in the beta version. Maybe your path logic can add it automatically if it is missing in order to still support older projects.

So after fixing those two issues in my older projects, the beta works for me. However stepping is still as slow as always. I tried to play with all of the “Thread ans Execution” options but I still get the same repeated commands to GDB. I verified that I have 5.2 Beta 2. See the output from below of one single step:

[   27717 ms] -exec-next
[   28153 ms] -stack-list-frames –thread 9
[   28207 ms] -stack-list-frames –thread 9
[   28211 ms] -stack-list-arguments –thread 9 1
[   28263 ms] -stack-list-frames –thread 9
[   28266 ms] -stack-list-arguments –thread 9 0
[   28323 ms] -stack-list-frames –thread 1
[   28325 ms] -stack-list-arguments –thread 1 0
[   28340 ms] -stack-list-frames –thread 1
[   28342 ms] -stack-list-arguments –thread 1 0
[   28350 ms] -stack-list-frames –thread 2
[   28362 ms] -stack-list-arguments –thread 2 0
[   28447 ms] -stack-list-frames –thread 2
[   28451 ms] -stack-list-arguments –thread 2 0
[   28532 ms] -stack-list-frames –thread 3
[   28544 ms] -stack-list-arguments –thread 3 0
[   28692 ms] -stack-list-frames –thread 3
[   28698 ms] -stack-list-arguments –thread 3 0
[   28911 ms] -stack-list-frames –thread 4
[   28927 ms] -stack-list-arguments –thread 4 0
[   29093 ms] -stack-list-frames –thread 4
[   29100 ms] -stack-list-arguments –thread 4 0
[   29355 ms] -stack-list-frames –thread 5
[   29370 ms] -stack-list-arguments –thread 5 0
[   29537 ms] -stack-list-frames –thread 5
[   29545 ms] -stack-list-arguments –thread 5 0
[   29765 ms] -stack-list-frames –thread 6
[   29785 ms] -stack-list-arguments –thread 6 0
[   30148 ms] -stack-list-frames –thread 6
[   30157 ms] -stack-list-arguments –thread 6 0
[   30421 ms] -stack-list-frames –thread 7
[   30431 ms] -stack-list-arguments –thread 7 0
[   30523 ms] -stack-list-frames –thread 7
[   30527 ms] -stack-list-arguments –thread 7 0
[   30658 ms] -stack-list-frames –thread 8
[   30663 ms] -stack-list-arguments –thread 8 0
[   30686 ms] -stack-list-frames –thread 8
[   30689 ms] -stack-list-arguments –thread 8 0
[   30773 ms] -stack-list-frames –thread 9
[   30779 ms] -stack-list-arguments –thread 9 0
[   30821 ms] -stack-list-frames –thread 10
[   30825 ms] -stack-list-arguments –thread 10 0
[   30833 ms] -stack-list-frames –thread 10
[   30836 ms] -stack-list-arguments –thread 10 0

 

When I execute “thread apply all bt”, it takes 311 ms (10 x faster) and shows all required stack info AFAICT. It seems like a much faster way to do it, except if the improvements you mention above also solves the problem.

• This reply was modified 8 years, 2 months ago by BitFlipper.
• This reply was modified 8 years, 2 months ago by BitFlipper.

[support]

Hi,

Sorry, tried reproducing that with “f:\projects\temp\EmbeddedProject-16” and did not get anything to fail. Perhaps the problem is triggered by something else? Could you please clarify which wizard and what other settings were you using?

The new Beta 2 was indeed not handling relative paths in the “NMake output” properly. We have fixed this in the development branch and will include this fix in Beta 3.

Can you verify that the Threads window in Visual Studio is closed when you get the multiple ‘-stack-list-frames’ commands?

[BitFlipper]

I believe I used a Linux project wizard. But this is years ago, and since then I simply copy the .vgdbsettings file to any new VS project I create since it is just another instance of the same source git repository.

I’m 100% sure neither of the Treads window nor the Parallel Stacks window is open. Also, since I still see multiple duplicate GDB commands issued for each single step as shown in my previous reply, the version I’m using doesn’t seem to contain the optimizations you mention. But I have confirmed that it is v 5.2 Beta 2, so I don’t know why I’m not seeing these optimizations. I looked through all of the settings to see if it is optional, but nothing seemed to indicate that it is an optional optimization.

[support]

Hi,

Thanks for confirming this. Looks like either something in your project prevents this optimization from turning on, or some other VS extension is requesting information about all threads.

Typically doing a single step even in a multi-threaded environment should result in something like this:

-stack-select-frame 0
^done
-thread-select 1
^done,new-thread-id="1",frame={level="0",addr="0x00000000004008d4",func="main",args=[{name="argc",value="1"},{name="argv",value="0x7fffffffeb48"}],file="LinuxProject3.cpp",fullname="/tmp/VisualGDB/f/PROJECTS/TEMP/LinuxProject3/LinuxProject3.cpp",line="7"}
-exec-next
^running
*running,thread-id="all"
*stopped,reason="end-stepping-range",frame={addr="0x00000000004008ef",func="main",args=[{name="argc",value="1"},{name="argv",value="0x7fffffffeb48"}],file="LinuxProject3.cpp",fullname="/tmp/VisualGDB/f/PROJECTS/TEMP/LinuxProject3/LinuxProject3.cpp",line="8"},thread-id="1",stopped-threads="all",core="0"
-stack-list-frames --thread 1
^done,stack=[frame={level="0",addr="0x00000000004008ef",func="main",file="LinuxProject3.cpp",fullname="/tmp/VisualGDB/f/PROJECTS/TEMP/LinuxProject3/LinuxProject3.cpp",line="8"}]
-stack-list-arguments --thread 1 0
^done,stack-args=[frame={level="0",args=[name="argc",name="argv"]}]

Could you please check if you get more than one “-stack-list-frames” command per step with this basic program and your toolchain:

#include <iostream>
#include <pthread.h>
#include <unistd.h>

using namespace std;

void *thread(void *)
{
    for (;;)
    {
        usleep(100000);        
    }
}

int main(int argc, char *argv[])
{
    pthread_t thr;
    pthread_create(&thr, 0, thread, 0);
    char sz[] = "Hello, World!";    //Hover mouse over "sz" while debugging to see its contents
    cout << sz << endl;    //<================= Put a breakpoint here
    for (;;)
    {
        usleep(100000);        
    }
    return 0;
}

[BitFlipper]

Hi,

So I tried the above program and got the same type of output as before, see below (note I trimmed the long lines):

[   49390 ms] -exec-next
[   49403 ms] ^running
[   49403 ms] *running,thread-id="all"
[   49502 ms] Hello, World!
[   49513 ms] *stopped,reason="end-stepping-range",frame=...
[   49565 ms] -stack-list-frames --thread 1
[   49567 ms] ^done,stack=[frame=...
[   49568 ms] -stack-list-frames --thread 1
[   49570 ms] ^done,stack=[frame=...
[   49570 ms] -stack-list-arguments --thread 1 1
[   49572 ms] ^done,stack-args=[frame=...
[   49588 ms] -stack-list-frames --thread 1
[   49590 ms] ^done,stack=[frame=...
[   49590 ms] -stack-list-arguments --thread 1 0
[   49592 ms] ^done,stack-args=[frame={level="0",args=[name="argc",name="argv"]}]
[   49592 ms] -stack-list-frames --thread 1
[   49594 ms] ^done,stack=[frame=...
[   49594 ms] -stack-list-arguments --thread 1 0
[   49595 ms] ^done,stack-args=[frame={level="0",args=[name="argc",name="argv"]}]
[   49595 ms] -stack-list-frames --thread 2
[   49598 ms] ^done,stack=[frame=...
[   49611 ms] -stack-list-arguments --thread 2 0
[   49613 ms] ^done,stack-args=[frame={level="0",args=[]},frame={level="1",args=[]}]
[   49623 ms] -stack-list-frames --thread 2
[   49625 ms] ^done,stack=[frame=...
[   49625 ms] -stack-list-arguments --thread 2 0
[   49627 ms] ^done,stack-args=[frame={level="0",args=[]},frame={level="1",args=[]}]

 

The above is from VS 2015. I have quite a few plugins enabled. So then I tried the same thing in VS 2010, which has just a few plugins installed. The output then looks like this:

[   21909 ms] -exec-next
[   21914 ms] ^running
[   21914 ms] *running,thread-id="all"
[   22003 ms] Hello, World!
[   22022 ms] *stopped,reason="end-stepping-range",frame=...
[   22036 ms] -break-after 1 0
[   22039 ms] ^done
[   22039 ms] -stack-list-frames --thread 1
[   22042 ms] ^done,stack=[frame={level="0",addr="0x000000889d552252",func="main",file=...
[   22049 ms] -stack-list-arguments --thread 1 0
[   22051 ms] ^done,stack-args=[frame={level="0",args=[name="argc",name="argv"]}]

 

I’m not sure why there is such a difference in output. You might be right there could be a plugin causing the extra GDB calls. But if so, won’t those calls still need to go through VGDB, and hence can’t VGDB cache thread and stack related requests for each time VS breaks into the debugger?

Also, it still seems to me that “bt” (current thread only) and “thread apply all bt” (all threads) seem much faster than the multiple commands that VGDB currently use. AFAICT it gives the same information, just in a different format, and just in a single command.

Thanks for your support, much appreciated!

[BitFlipper]

I tried debugging my main project using VS 2010 and stepping is much faster, to the point where the delay is no longer an issue (but I still think “bt” could speed it up even more :)).

So it is something to do with VS 2015 or one or more of the plugins. Do you have suggestions on how to track down which plugin could be causing this, e.g, are you aware of any plugins that you have seen causing such issues? I might need to disable each until I find the culprit(s).

In the meantime I’ll just go back to VS 2010 for now since I have a grueling deadline… 🙁

[support]

Hi,

This might be some sort of plugin interference. Can you try doing the same on a different machine with a clean VS installation (or under a different user account on the same machine)? If the behavior is not reproduced, please try disabling other VS plugins. If this solves the problem, please try enabling them one-by-one to see which one causes the issue.

[BitFlipper]

Aaaarrggg!

Well, good news and bad news… The bad news is I spent half the day trying everything under the sun to track down the issue. I don’t have the option to try this out on a different system, so I tried disabling/uninstalling every one of the plugins I possibly can, uninstalling/re-installing VGDB and a bunch of other things too.

The good news is I finally found the culprit: On the Debug toolbar, you will notice a button called “Show Threads in Source”. Mine was enabled but I didn’t know this because that toolbar was hidden since I never use it. As soon as I toggled the feature off, stepping became just as fast as in VS 2010. Finally!!!

I did a search for this feature, and there is very little info about it, other than it can slow down stepping in regular VS projects. But certainly nothing that also mentions VGDB. If you don’t already mention this somewhere in your documentation, it would be good to add it since it makes a huge difference.

Even better, a VS plugin can check the state of this button, so maybe VGDB can show a warning that this will impact debugging speed if it is enabled.

I still believe you can get even better stepping speed if using GDB’s bt command. Maybe there is a reason it can’t work for VGDB, but I briefly compared the outputs of the two different approaches and it seems you should get everything you need from the bt command. Maybe it is worth checking into if you are looking for more ways to optimize VGDB.

[support]

Hi,

Thanks, we will add this to our knowledge base.

Regarding ‘bt’, we use –stack–list–frames simply because it returns structured output that can be easily parsed; with ‘bt’ it could be tricky to separate arguments from function names, etc (e.g. when having namespaces and templates). If you believe using ‘bt’ makes a substantial difference, we could add a method to our extensibility API to replace the normal ‘list frames’ operation and you can experiment with writing a plugin based on the ‘bt’ command.

[Author]

Posts