Author Topic: Very slow stepping while debugging on Linux  (Read 11140 times)

Offline bsccara

  • Single posting newcomer
  • *
  • Posts: 2
Very slow stepping while debugging on Linux
« on: October 22, 2023, 01:37:49 am »
I'm running Code::Blocks svn-r13284, compiled with GCC 11.3.0, and using GDB 12.1 to debug a program compiled to Linux 64 bits. The OS is Kubuntu 22.04 and is running on a AMD Phenom(tm) II X4 955 with 6 GB of RAM.
Stepping through my program's C++ code is very slow, taking up to several seconds to update the UI after a single step and hanging the debugging session if F7 is pressed multiples times without waiting for the UI to refresh, requiring killing the GDB process. If the machine is loaded with other real-time tasks I may even get an error message shown on a dialog box complaining about pipe problems.
This happens even without any watches setup but is clearly worse the more / bigger watches there are.
Are there any known mitigations for this ? I've found other posts reporting the same issue but no real answers.

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5916
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: Very slow stepping while debugging on Linux
« Reply #1 on: October 22, 2023, 04:50:18 am »
This happens even without any watches setup but is clearly worse the more / bigger watches there are.

Do you have enable the option: "Watch function arguments" and "Watch local variables"? Those options are in the Settings->Debugger setting dialog.

I normally disable those two options. Because when you run each step command, C::B(GDB debugger plugin) will ask GDB to fetch all the function arguments and local variables, and refresh the watch window.

If you have many function arguments and local variables, the communication will be slow. There are several reasons, one big reason is currently GDB debugger plugin is not using the MI interface, but Using the old (deprecated) annotations mechanism (please fix them!), I see Code::Blocks listed in that wiki.  :(

Note that I think parsing the text returned by GDB CLI is slow. The more watches you add, the slower it will become.

I think if we switch to MI, the speed will be improved, but maybe, there are modern interfaces such as: Debug Adapter Protocol (DAP) for communication between debuggers and IDEs , maybe it is faster and better.
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline Pecan

  • Plugin developer
  • Lives here!
  • ****
  • Posts: 2778
Re: Very slow stepping while debugging on Linux
« Reply #2 on: October 22, 2023, 06:47:35 am »
There are plans to develop a debugger DAP client to GDB.
It'll take quite awhile.
It will not be in the coming release.

Offline bsccara

  • Single posting newcomer
  • *
  • Posts: 2
Re: Very slow stepping while debugging on Linux
« Reply #3 on: October 22, 2023, 01:27:24 pm »
ollydbg, this happens even with an empty watch list.

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5916
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: Very slow stepping while debugging on Linux
« Reply #4 on: October 23, 2023, 12:25:47 pm »
ollydbg, this happens even with an empty watch list.

That's strange, I don't have slow debugging issue, maybe you can share the debugger plugin log?
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5916
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: Very slow stepping while debugging on Linux
« Reply #5 on: October 26, 2023, 01:34:15 pm »
Another question: is it slow when you debug a program under GDB directly, I mean start GDB from bash command line without C::B.
If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline tomazzi

  • Single posting newcomer
  • *
  • Posts: 5
Re: Very slow stepping while debugging on Linux
« Reply #6 on: November 04, 2023, 08:04:34 pm »
Hi,

I'm experiencing the same annoying problem for some time (Debian12, CB svn13368) and today I decided to do some research.
To track the issue I've added stderr logging to DebuggerDriver::RunQueue() as follows:
Code
void DebuggerDriver::RunQueue()
{
   wxLogStderr ErrLog;
   wxString    tmps;

    if (m_QueueBusy || !m_DCmds.GetCount() || !IsProgramStopped())
        return;

    DebuggerCmd *command = CurrentCommand();

   tmps.Printf("DebuggerDriver::RunQueue(): m_DCmds.Count %ld, m_Cmd: '",
               m_DCmds.GetCount());
   tmps << command->m_Cmd << "'\n";
   ErrLog.LogText(tmps);

//    Log(_T("Running command: ") + CurrentCommand()->m_Cmd);
    // don't send a command if empty; most debuggers repeat the last command this way...
    if (!command->m_Cmd.IsEmpty())
    {
        m_QueueBusy = true;
        m_pDBG->DoSendCommand(command->m_Cmd);
        if (command->IsContinueCommand())
            m_ProgramIsStopped = false;
    }

    // Call Action()
    command->Action();

    // If the command was an action (i.e. no command specified,
    // remove it from the queue and run the next command.
    // For other commands, this happens in driver's ParseOutput().
    if (command->m_Cmd.IsEmpty())
    {
        RemoveTopCommand(true);
        RunQueue();
    }
}

Here's the output:
Code
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'run'
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'show language'
DebuggerDriver::RunQueue(): m_DCmds.Count 5, m_Cmd: 'info locals'
DebuggerDriver::RunQueue(): m_DCmds.Count 4, m_Cmd: 'info args' << THIS: Freezes for tens of seconds
DebuggerDriver::RunQueue(): m_DCmds.Count 3, m_Cmd: ''
DebuggerDriver::RunQueue(): m_DCmds.Count 2, m_Cmd: 'bt 30'
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'x/64xb 0x0'
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'next'
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'info locals'
DebuggerDriver::RunQueue(): m_DCmds.Count 4, m_Cmd: 'info args' << Frozen again after "next"
DebuggerDriver::RunQueue(): m_DCmds.Count 3, m_Cmd: ''
DebuggerDriver::RunQueue(): m_DCmds.Count 2, m_Cmd: 'bt 30'
DebuggerDriver::RunQueue(): m_DCmds.Count 1, m_Cmd: 'x/64xb 0x0'

Now to see what data are returned by GDB, I've added stderr logging to GDB_driver::ParseOutput() as follows:
Code
void GDB_driver::ParseOutput(const wxString& output)
{
   wxLogStderr ErrLog;
   wxString    tmps;

   tmps  = ">> GDB_driver::ParseOutput():\n";
   tmps << output << "\n << \n";
   ErrLog.LogText(tmps);
   ...
}
Result:
Code
DebuggerDriver::RunQueue(): m_DCmds.Count 4, m_Cmd: 'info args'
___FROZEN___100%_CPU_LOAD__HERE___
>> GDB_driver::ParseOutput():
this = 0x555555745170
 <<
>> GDB_driver::ParseOutput():
evt = @0x555555b4b780: {<wxEvent> = {<No data fields>}, <wxEventBasicPayloadMixin> = {m_cmdString = {m_impl = L"", m_convertedToChar = {m_str = 0x0, m_len = 0}}, m_commandInt = 131072, m_extraLong = 0}, m_clientData = 0x0, m_clientObject = 0x0, static ms_classInfo = {m_className = 0x7ffff7ca0488 L"wxCommandEvent", m_objectSize = 168, m_objectConstructor = 0x7ffff792dec0 <wxCommandEvent::wxCreateObject()>, m_baseInfo1 = 0x7ffff74b4f80 <wxEvent::ms_classInfo>, m_baseInfo2 = 0x0, static sm_first = 0x7ffff7fc2200 <wxAuiToolBarXmlHandler::ms_classInfo>, m_next = 0x7ffff74b4f00 <wxThreadEvent::ms_classInfo>}}
 <<
>> GDB_driver::ParseOutput():
>>>>>>cb_gdb:
 <<
DebuggerDriver::RunQueue(): m_DCmds.Count 3, m_Cmd: ''
DebuggerDriver::RunQueue(): m_DCmds.Count 2, m_Cmd: 'bt 30'

As You can see, this is not a problem with the amount of data to parse.
The process that is consuming 100% CPU time is GDB ... but when I run the the same application from GDB in terminal, the response time to "info args" is nearly zero.

I'm suspecting that this problem is related to Input/Output streams, but for now I don't have the time to analyse and understand the related code.

For sure, this worked flawlessly in the past - the regression happened after ~ svn11200, which I have used for a very long time.

Regards

EDIT:
I've just realized that the GDB response to 'info locals' is received after 'info args' -> this means that something went wrong in the command queue ...

« Last Edit: November 04, 2023, 10:30:44 pm by tomazzi »

Offline ollydbg

  • Developer
  • Lives here!
  • *****
  • Posts: 5916
  • OpenCV and Robotics
    • Chinese OpenCV forum moderator
Re: Very slow stepping while debugging on Linux
« Reply #7 on: November 05, 2023, 01:44:40 am »

I'm suspecting that this problem is related to Input/Output streams, but for now I don't have the time to analyse and understand the related code.

For sure, this worked flawlessly in the past - the regression happened after ~ svn11200, which I have used for a very long time.


Thanks for the test.

The svn rev11200 is committed in 2017-10-16. That's several years ago.  :)

Quote
Author: fuscated <fuscated@2a5c6006-c6dd-42ca-98ab-0921f2732cef>
Date: 2017/10/16 8:12:22
Commit hash: e3f8b41bed48a10059019719544901b0b1994039

* UI: Add 'Enable both' and 'Disable both' menu items in the Options submenu for the files in the project tree

> Most of the times when I use this menu, I want to toggle both options, so
  these two new menu items optimise the workflow a bit.

git-svn-id: https://svn.code.sf.net/p/codeblocks/code/trunk@11200 2a5c6006-c6dd-42ca-98ab-0921f2732cef

If some piece of memory should be reused, turn them to variables (or const variables).
If some piece of operations should be reused, turn them to functions.
If they happened together, then turn them to classes.

Offline blauzahn

  • Almost regular
  • **
  • Posts: 162
Re: Very slow stepping while debugging on Linux
« Reply #8 on: November 05, 2023, 08:20:32 am »
@tomazzi did not state that it became slow directly after that commit. He just used that version for a long time. So the regression(s) seem to have been introduced between that commit and now. Maybe, that are even several small things that made debugging with gdb on Linux slower and slower.

With our not so small projects I also observe, that debugging on several different Linux systems is painfully slow. It has been like that on trunk for ages. Not only for startup reading in all symbols, but also single stepping. Settings: startup scripts is checked (DISabled), everything else is unchecked (disabled) including watches on args and locals. Its slow even though the project has zero 3rd-party dependency. And sluggishness does neither come from our program nor from my machine (threadripper).

If I had the time, I would inspect cb with https://github.com/KDAB/hotspot and https://github.com/KDE/heaptrack.

Offline blauzahn

  • Almost regular
  • **
  • Posts: 162
Re: Very slow stepping while debugging on Linux
« Reply #9 on: November 05, 2023, 08:23:04 am »
This is cb observed via heaptrack after having run up to a breakpoint, then quit.

Offline blauzahn

  • Almost regular
  • **
  • Posts: 162
Re: Very slow stepping while debugging on Linux
« Reply #10 on: November 05, 2023, 08:30:17 am »
forgot to mention: System: arch x86_64 GNU/Linux, kernel: 6.5.9, wx: trunk, cb: trunk, g++ 13.2.1, cb compiled via configure and make

Offline tomazzi

  • Single posting newcomer
  • *
  • Posts: 5
Re: Very slow stepping while debugging on Linux
« Reply #11 on: November 06, 2023, 11:48:55 am »
I had the answer before my eyes but I couldn't see it ...
The problem is with GDB and not with Code::Blocks


The functions PipedProcess::SendString() and PipedProcess::HasInput() are responsible for communicating with the GDB, so they can be used to measure GDB response time. I've modified those function as follows:
Code
void PipedProcess::SendString(const wxString& text)
{
    //Manager::Get()->GetLogManager()->Log(m_PageIndex, cmd);
    wxOutputStream* pOut = GetOutputStream();
    if (pOut)
    {
        wxLogStderr ErrLog;
        wxString    tmps;
        tmps = "PipedProcess::SendString(): '"; tmps << text << "'\n";
        ErrLog.LogText(tmps);

        //stopwatch is a small class which uses linux-specific
        //clock_gettime( CLOCK_MONOTONIC ) to get timestamps and compute delta time.
        stopwatch.start();

        wxTextOutputStream sin(*pOut);

        wxString msg = text + _T('\n');
        sin.WriteString(msg);
    }
}

bool PipedProcess::HasInput()
{
    if (IsErrorAvailable())
    {
        cbTextInputStream serr(*GetErrorStream());

        wxString msg;
        msg << serr.ReadLine();

        if (m_Stopped)
            return true;

        CodeBlocksEvent event(cbEVT_PIPEDPROCESS_STDERR, m_Id);
        event.SetString(msg);
        event.SetX(m_Index);
        wxPostEvent(m_Parent, event);

        return true;
    }

    if (IsInputAvailable())
    {
        cbTextInputStream sout(*GetInputStream());

        wxString msg;
        msg << sout.ReadLine();

        if (m_Stopped)
            return true;

        CodeBlocksEvent event(cbEVT_PIPEDPROCESS_STDOUT, m_Id);
        event.SetString(msg);
        event.SetX(m_Index);
        wxPostEvent(m_Parent, event);

        //The delta time is reletive to SendString()
        //or to previous call to HasInput()
        stopwatch.stop();
        stopwatch.print_result(stderr, "PipedProcess::HasInput(): Tdelta");
        stopwatch.start();

        return true;
    }

    return false;
}
Delta time format is s.ms.us.ns, so "11.505.454.348" means 11.505454348 seconds.
Here's the log:
Code
PipedProcess::SendString(): 'run'
PipedProcess::HasInput(): Tdelta[s] 0.016.484.358
PipedProcess::HasInput(): Tdelta[s] 0.710.774.575
PipedProcess::HasInput(): Tdelta[s] 0.001.420.998
PipedProcess::HasInput(): Tdelta[s] 0.345.093.249
PipedProcess::HasInput(): Tdelta[s] 0.001.195.401
PipedProcess::HasInput(): Tdelta[s] 0.040.110.444
PipedProcess::HasInput(): Tdelta[s] 0.001.373.342
PipedProcess::HasInput(): Tdelta[s] 0.001.328.177
PipedProcess::HasInput(): Tdelta[s] 0.001.136.616
PipedProcess::HasInput(): Tdelta[s] 0.001.389.211
PipedProcess::HasInput(): Tdelta[s] 0.001.179.652
PipedProcess::HasInput(): Tdelta[s] 0.000.888.481
PipedProcess::HasInput(): Tdelta[s] 0.000.767.153
PipedProcess::HasInput(): Tdelta[s] 0.000.762.243
PipedProcess::HasInput(): Tdelta[s] 0.000.843.945
PipedProcess::HasInput(): Tdelta[s] 0.000.834.766
PipedProcess::HasInput(): Tdelta[s] 0.050.730.331
PipedProcess::HasInput(): Tdelta[s] 0.001.293.400
PipedProcess::HasInput(): Tdelta[s] 0.001.152.325
PipedProcess::HasInput(): Tdelta[s] 0.001.179.072
PipedProcess::HasInput(): Tdelta[s] 0.001.238.166
PipedProcess::HasInput(): Tdelta[s] 0.001.131.507
PipedProcess::HasInput(): Tdelta[s] 0.001.148.185
PipedProcess::HasInput(): Tdelta[s] 0.001.318.428
PipedProcess::HasInput(): Tdelta[s] 0.001.147.016
PipedProcess::HasInput(): Tdelta[s] 0.001.120.408
PipedProcess::HasInput(): Tdelta[s] 0.001.134.216
PipedProcess::HasInput(): Tdelta[s] 0.001.178.172
PipedProcess::HasInput(): Tdelta[s] 0.000.922.107
PipedProcess::HasInput(): Tdelta[s] 0.000.777.372
PipedProcess::HasInput(): Tdelta[s] 0.000.791.341
PipedProcess::HasInput(): Tdelta[s] 0.000.849.745
PipedProcess::HasInput(): Tdelta[s] 0.337.395.860
PipedProcess::HasInput(): Tdelta[s] 0.000.884.931
PipedProcess::HasInput(): Tdelta[s] 0.000.769.323
PipedProcess::HasInput(): Tdelta[s] 0.000.897.840
PipedProcess::HasInput(): Tdelta[s] 3.442.988.458
PipedProcess::HasInput(): Tdelta[s] 0.000.827.147
PipedProcess::HasInput(): Tdelta[s] 0.000.776.222
PipedProcess::HasInput(): Tdelta[s] 0.047.712.046
PipedProcess::HasInput(): Tdelta[s] 0.000.888.941
PipedProcess::HasInput(): Tdelta[s] 0.000.751.125
PipedProcess::HasInput(): Tdelta[s] 0.000.767.763
PipedProcess::HasInput(): Tdelta[s] 0.000.750.145
PipedProcess::HasInput(): Tdelta[s] 0.000.743.626
PipedProcess::HasInput(): Tdelta[s] 0.000.753.375
PipedProcess::HasInput(): Tdelta[s] 0.000.742.316
PipedProcess::HasInput(): Tdelta[s] 0.011.577.705
PipedProcess::HasInput(): Tdelta[s] 0.000.808.239
PipedProcess::HasInput(): Tdelta[s] 0.000.751.905
PipedProcess::HasInput(): Tdelta[s] 0.000.750.515
PipedProcess::HasInput(): Tdelta[s] 0.000.815.349
PipedProcess::HasInput(): Tdelta[s] 0.000.770.563
PipedProcess::HasInput(): Tdelta[s] 0.000.751.035
PipedProcess::HasInput(): Tdelta[s] 0.000.751.665
PipedProcess::HasInput(): Tdelta[s] 0.011.854.087
PipedProcess::HasInput(): Tdelta[s] 0.000.806.090
PipedProcess::HasInput(): Tdelta[s] 0.519.426.402
PipedProcess::HasInput(): Tdelta[s] 0.020.601.193
PipedProcess::HasInput(): Tdelta[s] 0.061.801.452
PipedProcess::HasInput(): Tdelta[s] 0.001.000.530
PipedProcess::HasInput(): Tdelta[s] 5.330.846.025  << ???
PipedProcess::HasInput(): Tdelta[s] 0.001.169.954
PipedProcess::HasInput(): Tdelta[s] 0.001.293.651
PipedProcess::HasInput(): Tdelta[s] 0.001.716.809
PipedProcess::HasInput(): Tdelta[s] 0.001.473.923
PipedProcess::HasInput(): Tdelta[s] 0.001.716.140
PipedProcess::HasInput(): Tdelta[s] 0.000.990.791
PipedProcess::HasInput(): Tdelta[s] 0.000.801.770
PipedProcess::HasInput(): Tdelta[s] 11.505.454.348 << ???
PipedProcess::HasInput(): Tdelta[s] 3.264.648.845
PipedProcess::HasInput(): Tdelta[s] 0.001.081.163
PipedProcess::HasInput(): Tdelta[s] 0.001.037.887
PipedProcess::HasInput(): Tdelta[s] 0.000.933.928
PipedProcess::SendString(): 'show language'
PipedProcess::HasInput(): Tdelta[s] 0.022.428.642
PipedProcess::HasInput(): Tdelta[s] 0.000.846.746
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.017.106.586
PipedProcess::HasInput(): Tdelta[s] 0.001.214.471
PipedProcess::HasInput(): Tdelta[s] 0.001.155.556
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 0.514.855.978
PipedProcess::HasInput(): Tdelta[s] 0.000.784.223
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 4.525.707.812 << backtrace
PipedProcess::HasInput(): Tdelta[s] 0.001.264.986
PipedProcess::HasInput(): Tdelta[s] 0.001.131.819
PipedProcess::HasInput(): Tdelta[s] 0.001.066.735
PipedProcess::HasInput(): Tdelta[s] 0.001.042.057
PipedProcess::HasInput(): Tdelta[s] 0.001.226.620
PipedProcess::HasInput(): Tdelta[s] 0.001.223.290
PipedProcess::HasInput(): Tdelta[s] 0.001.232.149
PipedProcess::HasInput(): Tdelta[s] 0.001.267.256
PipedProcess::HasInput(): Tdelta[s] 0.001.015.430
PipedProcess::HasInput(): Tdelta[s] 0.000.846.407
PipedProcess::HasInput(): Tdelta[s] 0.000.837.888
PipedProcess::HasInput(): Tdelta[s] 0.000.820.609
PipedProcess::HasInput(): Tdelta[s] 0.000.866.795
PipedProcess::HasInput(): Tdelta[s] 0.000.791.053
PipedProcess::HasInput(): Tdelta[s] 0.000.819.569
PipedProcess::HasInput(): Tdelta[s] 0.000.793.162
PipedProcess::HasInput(): Tdelta[s] 0.000.834.248
PipedProcess::HasInput(): Tdelta[s] 0.000.811.350
PipedProcess::HasInput(): Tdelta[s] 0.000.785.393
PipedProcess::HasInput(): Tdelta[s] 0.000.806.241
PipedProcess::HasInput(): Tdelta[s] 0.000.818.360
PipedProcess::HasInput(): Tdelta[s] 0.000.913.500
PipedProcess::HasInput(): Tdelta[s] 0.000.799.751
PipedProcess::HasInput(): Tdelta[s] 0.000.784.423
PipedProcess::HasInput(): Tdelta[s] 0.000.803.781
PipedProcess::HasInput(): Tdelta[s] 0.000.788.383
PipedProcess::HasInput(): Tdelta[s] 0.000.803.921
PipedProcess::HasInput(): Tdelta[s] 0.000.815.110
PipedProcess::HasInput(): Tdelta[s] 0.000.784.213
PipedProcess::HasInput(): Tdelta[s] 0.000.748.666
PipedProcess::HasInput(): Tdelta[s] 0.000.736.488
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.007.698.525
PipedProcess::SendString(): 'next'
PipedProcess::HasInput(): Tdelta[s] 0.008.489.805
PipedProcess::HasInput(): Tdelta[s] 0.023.431.486
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.001.404.774
PipedProcess::HasInput(): Tdelta[s] 0.000.832.459
PipedProcess::HasInput(): Tdelta[s] 0.000.749.897
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 0.566.549.758
PipedProcess::HasInput(): Tdelta[s] 0.000.803.482
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 4.773.168.900 << backtrace @frame0
PipedProcess::HasInput(): Tdelta[s] 0.001.132.451
PipedProcess::HasInput(): Tdelta[s] 0.001.106.003
PipedProcess::HasInput(): Tdelta[s] 0.001.075.906
PipedProcess::HasInput(): Tdelta[s] 0.001.046.459
PipedProcess::HasInput(): Tdelta[s] 0.001.050.108
PipedProcess::HasInput(): Tdelta[s] 0.001.042.209
PipedProcess::HasInput(): Tdelta[s] 0.001.055.898
PipedProcess::HasInput(): Tdelta[s] 0.001.080.825
PipedProcess::HasInput(): Tdelta[s] 0.001.219.652
PipedProcess::HasInput(): Tdelta[s] 0.001.071.016
PipedProcess::HasInput(): Tdelta[s] 0.000.941.199
PipedProcess::HasInput(): Tdelta[s] 0.000.814.121
PipedProcess::HasInput(): Tdelta[s] 0.000.854.117
PipedProcess::HasInput(): Tdelta[s] 0.000.798.713
PipedProcess::HasInput(): Tdelta[s] 0.000.835.580
PipedProcess::HasInput(): Tdelta[s] 0.000.795.263
PipedProcess::HasInput(): Tdelta[s] 0.000.806.932
PipedProcess::HasInput(): Tdelta[s] 0.000.801.262
PipedProcess::HasInput(): Tdelta[s] 0.000.787.694
PipedProcess::HasInput(): Tdelta[s] 0.000.817.431
PipedProcess::HasInput(): Tdelta[s] 0.000.820.421
PipedProcess::HasInput(): Tdelta[s] 0.000.787.904
PipedProcess::HasInput(): Tdelta[s] 0.000.785.614
PipedProcess::HasInput(): Tdelta[s] 0.000.786.104
PipedProcess::HasInput(): Tdelta[s] 0.000.824.170
PipedProcess::HasInput(): Tdelta[s] 0.000.792.933
PipedProcess::HasInput(): Tdelta[s] 0.000.809.772
PipedProcess::HasInput(): Tdelta[s] 0.000.805.122
PipedProcess::HasInput(): Tdelta[s] 0.000.925.361
PipedProcess::HasInput(): Tdelta[s] 0.000.762.007
PipedProcess::HasInput(): Tdelta[s] 0.000.742.818
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.007.519.512
PipedProcess::SendString(): 'whatis m_str'
PipedProcess::HasInput(): Tdelta[s] 3.699.436.156 << wxString
PipedProcess::HasInput(): Tdelta[s] 0.000.801.624
PipedProcess::SendString(): 'output m_str'
PipedProcess::HasInput(): Tdelta[s] 8.512.269.309 << wxString dereference
PipedProcess::SendString(): 'frame 1'
PipedProcess::HasInput(): Tdelta[s] 2.516.084.068 << stack frame change
PipedProcess::HasInput(): Tdelta[s] 0.001.063.773
PipedProcess::HasInput(): Tdelta[s] 0.000.949.073
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.024.822.421
PipedProcess::HasInput(): Tdelta[s] 0.000.894.328
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 8.990.980.695 << single argument, "this" pointer
PipedProcess::HasInput(): Tdelta[s] 0.001.395.263
PipedProcess::HasInput(): Tdelta[s] 0.000.948.424
PipedProcess::SendString(): 'whatis m_str'
PipedProcess::HasInput(): Tdelta[s] 9.012.024.286 << same wxString again, 2x longer response
PipedProcess::HasInput(): Tdelta[s] 0.000.763.521
PipedProcess::SendString(): 'output m_str'
PipedProcess::HasInput(): Tdelta[s] 9.023.580.999 << same wxString dereference, 1 second slower
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 12.329.483.518 << backtrace @frame1, 3x longer
PipedProcess::HasInput(): Tdelta[s] 0.001.124.379
PipedProcess::HasInput(): Tdelta[s] 0.001.094.482
PipedProcess::HasInput(): Tdelta[s] 0.001.067.114
PipedProcess::HasInput(): Tdelta[s] 0.001.169.695
PipedProcess::HasInput(): Tdelta[s] 0.001.043.286
PipedProcess::HasInput(): Tdelta[s] 0.001.034.307
PipedProcess::HasInput(): Tdelta[s] 0.001.040.366
PipedProcess::HasInput(): Tdelta[s] 0.001.070.114
PipedProcess::HasInput(): Tdelta[s] 0.001.058.175
PipedProcess::HasInput(): Tdelta[s] 0.001.050.226
PipedProcess::HasInput(): Tdelta[s] 0.000.920.147
PipedProcess::HasInput(): Tdelta[s] 0.000.809.527
PipedProcess::HasInput(): Tdelta[s] 0.000.855.923
PipedProcess::HasInput(): Tdelta[s] 0.000.795.198
PipedProcess::HasInput(): Tdelta[s] 0.000.836.155
PipedProcess::HasInput(): Tdelta[s] 0.000.826.615
PipedProcess::HasInput(): Tdelta[s] 0.000.796.568
PipedProcess::HasInput(): Tdelta[s] 0.000.790.819
PipedProcess::HasInput(): Tdelta[s] 0.000.775.590
PipedProcess::HasInput(): Tdelta[s] 0.000.812.197
PipedProcess::HasInput(): Tdelta[s] 0.000.780.450
PipedProcess::HasInput(): Tdelta[s] 0.000.807.618
PipedProcess::HasInput(): Tdelta[s] 0.000.909.948
PipedProcess::HasInput(): Tdelta[s] 0.000.774.540
PipedProcess::HasInput(): Tdelta[s] 0.000.802.758
PipedProcess::HasInput(): Tdelta[s] 0.000.782.640
PipedProcess::HasInput(): Tdelta[s] 0.000.794.939
PipedProcess::HasInput(): Tdelta[s] 0.000.789.939
PipedProcess::HasInput(): Tdelta[s] 0.000.774.441
PipedProcess::HasInput(): Tdelta[s] 0.000.757.382
PipedProcess::HasInput(): Tdelta[s] 0.000.729.315
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.008.001.712

The "info args" for single argument (self pointer) took 9s,  dereferencing simple wxString took 8.5s, and If You try to dereference pointer to some bigger object, like wxWindow, it would take few minutes to complete (yes, I've tried this).
Backtrace takes ridiculous amount of time - so closing "Call Stack" window can significanlty reduce total response time.

....

But besides that, there is something wrong with C::B event/cmd queue handling:
When the GDB response is really slow (minutes), the call stack can be displayed in "Memory" window, while the "Call Stack" window is left blank.
This happens extremely rarely, so it's hard to catch.

Regards.

EDIT: Fixed spelling.
« Last Edit: November 06, 2023, 10:12:51 pm by tomazzi »

Offline tomazzi

  • Single posting newcomer
  • *
  • Posts: 5
Re: Very slow stepping while debugging on Linux
« Reply #12 on: November 09, 2023, 11:39:57 am »
I have temporarily resolved the problem by compiling the GDB from official Debian source package gdb-source_13.1-3_all.deb

Build flags:
Code
export target_configargs="--enable-threading --with-gnu-ld --enable-libbacktrace --with-zstd --with-system-readline --with-system-zlib --with-xxhash=yes --disable-unit-tests --disable-sim"

./configure --enable-lto --enable-vtable-verify --disable-libstdcxx --prefix=<install path>

Result:
Code
PipedProcess::SendString(): 'run'
PipedProcess::HasInput(): Tdelta[s] 0.027.727.643
PipedProcess::HasInput(): Tdelta[s] 0.000.860.821
PipedProcess::SendString(): 'info frame'
PipedProcess::HasInput(): Tdelta[s] 0.148.860.854
PipedProcess::HasInput(): Tdelta[s] 0.000.779.847
PipedProcess::HasInput(): Tdelta[s] 0.105.216.543
PipedProcess::HasInput(): Tdelta[s] 0.000.887.738
PipedProcess::HasInput(): Tdelta[s] 0.039.975.400
PipedProcess::HasInput(): Tdelta[s] 0.000.914.175
PipedProcess::HasInput(): Tdelta[s] 0.000.855.401
PipedProcess::HasInput(): Tdelta[s] 0.000.848.252
PipedProcess::HasInput(): Tdelta[s] 0.000.849.851
PipedProcess::HasInput(): Tdelta[s] 0.000.876.469
PipedProcess::HasInput(): Tdelta[s] 0.000.723.033
PipedProcess::HasInput(): Tdelta[s] 0.000.664.538
PipedProcess::HasInput(): Tdelta[s] 0.000.667.268
PipedProcess::HasInput(): Tdelta[s] 0.000.665.688
PipedProcess::HasInput(): Tdelta[s] 0.000.664.508
PipedProcess::HasInput(): Tdelta[s] 0.053.802.971
PipedProcess::HasInput(): Tdelta[s] 0.000.887.438
PipedProcess::HasInput(): Tdelta[s] 0.000.847.302
PipedProcess::HasInput(): Tdelta[s] 0.000.846.382
PipedProcess::HasInput(): Tdelta[s] 0.003.353.470
PipedProcess::HasInput(): Tdelta[s] 0.000.885.558
PipedProcess::HasInput(): Tdelta[s] 0.000.700.365
PipedProcess::HasInput(): Tdelta[s] 0.000.653.189
PipedProcess::HasInput(): Tdelta[s] 0.000.651.959
PipedProcess::HasInput(): Tdelta[s] 0.000.651.640
PipedProcess::HasInput(): Tdelta[s] 0.000.651.510
PipedProcess::HasInput(): Tdelta[s] 0.000.657.859
PipedProcess::HasInput(): Tdelta[s] 0.000.652.349
PipedProcess::HasInput(): Tdelta[s] 0.000.652.770
PipedProcess::HasInput(): Tdelta[s] 0.000.653.640
PipedProcess::HasInput(): Tdelta[s] 0.000.652.789
PipedProcess::HasInput(): Tdelta[s] 11.981.450.283
PipedProcess::HasInput(): Tdelta[s] 0.000.881.518
PipedProcess::HasInput(): Tdelta[s] 0.000.953.032
PipedProcess::HasInput(): Tdelta[s] 0.001.531.568
PipedProcess::HasInput(): Tdelta[s] 0.001.234.346
PipedProcess::HasInput(): Tdelta[s] 0.011.361.368
PipedProcess::HasInput(): Tdelta[s] 0.000.735.492
PipedProcess::HasInput(): Tdelta[s] 0.000.695.026
PipedProcess::HasInput(): Tdelta[s] 3.436.243.927
PipedProcess::HasInput(): Tdelta[s] 0.312.885.971
PipedProcess::HasInput(): Tdelta[s] 0.001.025.345
PipedProcess::HasInput(): Tdelta[s] 0.001.003.967
PipedProcess::HasInput(): Tdelta[s] 0.000.947.333
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.022.776.171
PipedProcess::HasInput(): Tdelta[s] 0.000.704.305
PipedProcess::HasInput(): Tdelta[s] 0.000.684.866
PipedProcess::HasInput(): Tdelta[s] 0.000.709.864
PipedProcess::HasInput(): Tdelta[s] 0.000.742.641
PipedProcess::HasInput(): Tdelta[s] 0.000.681.657
PipedProcess::HasInput(): Tdelta[s] 0.000.704.924
PipedProcess::HasInput(): Tdelta[s] 0.000.709.024
PipedProcess::SendString(): 'show language'
PipedProcess::HasInput(): Tdelta[s] 0.009.941.010
PipedProcess::HasInput(): Tdelta[s] 0.000.741.732
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.019.930.195
PipedProcess::HasInput(): Tdelta[s] 0.001.138.524
PipedProcess::HasInput(): Tdelta[s] 0.000.890.687
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 0.017.222.606
PipedProcess::HasInput(): Tdelta[s] 0.000.738.062
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 0.006.839.756 << backtrace: was 4.525 seconds !!
PipedProcess::HasInput(): Tdelta[s] 0.001.005.857
PipedProcess::HasInput(): Tdelta[s] 0.000.825.113
PipedProcess::HasInput(): Tdelta[s] 0.000.785.897
PipedProcess::HasInput(): Tdelta[s] 0.000.807.595
PipedProcess::HasInput(): Tdelta[s] 0.000.939.963
PipedProcess::HasInput(): Tdelta[s] 0.000.784.367
PipedProcess::HasInput(): Tdelta[s] 0.000.766.939
PipedProcess::HasInput(): Tdelta[s] 0.000.772.588
PipedProcess::HasInput(): Tdelta[s] 0.000.768.468
PipedProcess::HasInput(): Tdelta[s] 0.000.759.010
PipedProcess::HasInput(): Tdelta[s] 0.000.827.103
PipedProcess::HasInput(): Tdelta[s] 0.000.751.130
PipedProcess::HasInput(): Tdelta[s] 0.000.816.574
PipedProcess::HasInput(): Tdelta[s] 0.000.746.231
PipedProcess::HasInput(): Tdelta[s] 0.000.751.211
PipedProcess::HasInput(): Tdelta[s] 0.000.787.357
PipedProcess::HasInput(): Tdelta[s] 0.000.739.392
PipedProcess::HasInput(): Tdelta[s] 0.000.754.500
PipedProcess::HasInput(): Tdelta[s] 0.000.731.403
PipedProcess::HasInput(): Tdelta[s] 0.000.728.693
PipedProcess::HasInput(): Tdelta[s] 0.000.786.647
PipedProcess::HasInput(): Tdelta[s] 0.000.759.030
PipedProcess::HasInput(): Tdelta[s] 0.002.828.798
PipedProcess::HasInput(): Tdelta[s] 0.000.971.650
PipedProcess::HasInput(): Tdelta[s] 0.000.747.780
PipedProcess::HasInput(): Tdelta[s] 0.000.737.862
PipedProcess::HasInput(): Tdelta[s] 0.000.758.929
PipedProcess::HasInput(): Tdelta[s] 0.000.746.871
PipedProcess::HasInput(): Tdelta[s] 0.000.804.005
PipedProcess::HasInput(): Tdelta[s] 0.000.697.315
PipedProcess::HasInput(): Tdelta[s] 0.000.682.037
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.007.782.819
PipedProcess::SendString(): 'next'
PipedProcess::HasInput(): Tdelta[s] 0.031.714.634
PipedProcess::HasInput(): Tdelta[s] 0.009.118.856
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.001.288.271
PipedProcess::HasInput(): Tdelta[s] 0.000.780.367
PipedProcess::HasInput(): Tdelta[s] 0.000.690.436
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 0.024.993.935
PipedProcess::HasInput(): Tdelta[s] 0.000.839.342
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 0.005.156.253
PipedProcess::HasInput(): Tdelta[s] 0.000.958.912
PipedProcess::HasInput(): Tdelta[s] 0.000.838.902
PipedProcess::HasInput(): Tdelta[s] 0.000.794.816
PipedProcess::HasInput(): Tdelta[s] 0.000.768.019
PipedProcess::HasInput(): Tdelta[s] 0.000.775.928
PipedProcess::HasInput(): Tdelta[s] 0.000.918.954
PipedProcess::HasInput(): Tdelta[s] 0.000.772.499
PipedProcess::HasInput(): Tdelta[s] 0.000.777.318
PipedProcess::HasInput(): Tdelta[s] 0.000.769.019
PipedProcess::HasInput(): Tdelta[s] 0.000.759.650
PipedProcess::HasInput(): Tdelta[s] 0.000.738.192
PipedProcess::HasInput(): Tdelta[s] 0.000.788.517
PipedProcess::HasInput(): Tdelta[s] 0.000.770.618
PipedProcess::HasInput(): Tdelta[s] 0.000.736.402
PipedProcess::HasInput(): Tdelta[s] 0.000.749.100
PipedProcess::HasInput(): Tdelta[s] 0.000.743.441
PipedProcess::HasInput(): Tdelta[s] 0.000.730.002
PipedProcess::HasInput(): Tdelta[s] 0.000.757.820
PipedProcess::HasInput(): Tdelta[s] 0.000.730.602
PipedProcess::HasInput(): Tdelta[s] 0.000.729.712
PipedProcess::HasInput(): Tdelta[s] 0.003.267.117
PipedProcess::HasInput(): Tdelta[s] 0.000.780.967
PipedProcess::HasInput(): Tdelta[s] 0.000.819.114
PipedProcess::HasInput(): Tdelta[s] 0.000.758.020
PipedProcess::HasInput(): Tdelta[s] 0.000.891.367
PipedProcess::HasInput(): Tdelta[s] 0.000.735.552
PipedProcess::HasInput(): Tdelta[s] 0.000.748.731
PipedProcess::HasInput(): Tdelta[s] 0.000.741.981
PipedProcess::HasInput(): Tdelta[s] 0.000.743.581
PipedProcess::HasInput(): Tdelta[s] 0.000.692.006
PipedProcess::HasInput(): Tdelta[s] 0.000.684.496
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.007.911.597
PipedProcess::SendString(): 'whatis m_str'
PipedProcess::HasInput(): Tdelta[s] 0.011.275.716 << wxString type info, was 3.699s
PipedProcess::HasInput(): Tdelta[s] 0.000.886.928
PipedProcess::SendString(): 'output m_str'
PipedProcess::HasInput(): Tdelta[s] 0.339.380.461 << wxString dereference, was 8.512s
PipedProcess::SendString(): 'frame 1'
PipedProcess::HasInput(): Tdelta[s] 0.018.964.413 << stack frame change, was 2.516s
PipedProcess::HasInput(): Tdelta[s] 0.000.995.748
PipedProcess::HasInput(): Tdelta[s] 0.000.855.071
PipedProcess::SendString(): 'info locals'
PipedProcess::HasInput(): Tdelta[s] 0.041.064.846
PipedProcess::HasInput(): Tdelta[s] 0.000.884.548
PipedProcess::SendString(): 'info args'
PipedProcess::HasInput(): Tdelta[s] 0.019.802.126
PipedProcess::HasInput(): Tdelta[s] 0.000.849.141
PipedProcess::HasInput(): Tdelta[s] 0.000.710.794
PipedProcess::SendString(): 'whatis m_str'
PipedProcess::HasInput(): Tdelta[s] 0.028.132.995
PipedProcess::HasInput(): Tdelta[s] 0.000.819.254
PipedProcess::SendString(): 'output m_str'
PipedProcess::HasInput(): Tdelta[s] 0.018.960.294
PipedProcess::SendString(): 'bt 30'
PipedProcess::HasInput(): Tdelta[s] 0.012.968.459 << backtrace @frame1, was 12.329s
PipedProcess::HasInput(): Tdelta[s] 0.009.850.288
PipedProcess::HasInput(): Tdelta[s] 0.000.919.505
PipedProcess::HasInput(): Tdelta[s] 0.000.817.504
PipedProcess::HasInput(): Tdelta[s] 0.000.792.996
PipedProcess::HasInput(): Tdelta[s] 0.000.970.240
PipedProcess::HasInput(): Tdelta[s] 0.000.807.456
PipedProcess::HasInput(): Tdelta[s] 0.000.943.843
PipedProcess::HasInput(): Tdelta[s] 0.000.798.166
PipedProcess::HasInput(): Tdelta[s] 0.000.794.566
PipedProcess::HasInput(): Tdelta[s] 0.000.785.617
PipedProcess::HasInput(): Tdelta[s] 0.010.247.510
PipedProcess::HasInput(): Tdelta[s] 0.000.821.444
PipedProcess::HasInput(): Tdelta[s] 0.000.787.657
PipedProcess::HasInput(): Tdelta[s] 0.000.782.867
PipedProcess::HasInput(): Tdelta[s] 0.000.781.518
PipedProcess::HasInput(): Tdelta[s] 0.000.920.535
PipedProcess::HasInput(): Tdelta[s] 0.000.756.940
PipedProcess::HasInput(): Tdelta[s] 0.000.774.188
PipedProcess::HasInput(): Tdelta[s] 0.000.764.399
PipedProcess::HasInput(): Tdelta[s] 0.009.787.323
PipedProcess::HasInput(): Tdelta[s] 0.001.253.984
PipedProcess::HasInput(): Tdelta[s] 0.000.941.423
PipedProcess::HasInput(): Tdelta[s] 0.000.830.043
PipedProcess::HasInput(): Tdelta[s] 0.000.777.798
PipedProcess::HasInput(): Tdelta[s] 0.000.906.146
PipedProcess::HasInput(): Tdelta[s] 0.000.762.879
PipedProcess::HasInput(): Tdelta[s] 0.000.796.186
PipedProcess::HasInput(): Tdelta[s] 0.009.620.759
PipedProcess::HasInput(): Tdelta[s] 0.000.824.624
PipedProcess::HasInput(): Tdelta[s] 0.000.735.542
PipedProcess::HasInput(): Tdelta[s] 0.000.743.102
PipedProcess::SendString(): 'x/64xb 0x0'
PipedProcess::HasInput(): Tdelta[s] 0.024.565.365
With newly compiled GDB the response times are typically below 20ms, wxString deference takes 339ms instead of 8.5 seconds, and backtrace is nearly 1000 times faster!

Now I can get back to work on my own projects  8)

... but first I have to file a BUG report in Debian BTS ...

EDIT:
BUG reported: #1055646
« Last Edit: November 09, 2023, 10:43:00 pm by tomazzi »