Core dump debugging performance too slow

[borjamunozf]

Environment

• OS and version: Windows 11
• VS Code: 1.93.1
• C/C++ extension: v1.22.6 (pre-release), v1.21.6
• OS and version of remote machine (if applicable): WSL 2.2.4 - Ubuntu 22
• GDB / LLDB version: 15.1, 12.1 multiarch, 7.1

Bug Summary and Steps to Reproduce

Bug Summary:

Core dump debugging is quite slow with real world C++ scenarios. Last sample data we received from other devs throws a bad performance and overall experience.

Sample measurements:

• GDB commnd line takes ~1min-30-45 secs.
• VScode C++ breakpoint stop ~9 minutes, but I have other samples taking 14 minutes or 20 minutes
• This is not specific to any laptop. Other colleagues have roughly same numbers.

From what we have seen, the symbol loading is not the main pain point, but the requests done afterwards the symbols have been loaded.

• The elapsed time for a lot ot threads takes ~17 seconds (and there's total of 64 threads)

Tested in different OS versions, VScode and C++ ext. I don't think it's an issue or regression because this performance problems with debugging production C++ projects has been not new since a few years at least when I started working with vscode.

I also tested with different gdb versions with no effect regarding perf in Vscode core dump debugging:

• gdb-multiarch v12.1
• gdb 15.1 (latest release). I built this as I could from source, but I see some error logs in the debug console that could impact...

Debugger Configurations

{
  "version": "0.2.0",
  "configurations": [
    {
      "name": "(gdb) Launch Core Dump",
      "type": "cppdbg",
      "request": "launch",
      "program": "/mnt/disk1/asd/app/bin/DispApp",
      "args": ["-g "],
      "stopAtEntry": false,
      "coreDumpPath": "${workspaceFolder}/coreDump",
      "sourceFileMap": {
          "/asdshell": "${workspaceFolder}"
      },
      "additionalSOLibSearchPath": "/mnt/disk1/asd/app/lib;/opt/sdks/whatever-1.1.0/x86/sysroots/x86-what-linux-dev/lib/.debug;/opt/sdks/whatever-1.1.0/x86/sysroots/x86-what-linux/usr/lib",
      "cwd": "${workspaceFolder}",
      "miDebuggerPath": "/usr/bin/gdb-multiarch",
      "MIMode": "gdb",
      "logging": {
        "engineLogging":"verbose",
        "trace": true,
        "traceResponse": true
      },
     "setupCommands": [
      {
        "description": "set sysroot",
        "text": "-gdb-set sysroot ${input:sdkSysPath}/sysroots/x86-what-linux/",
        "ignoreFailures": false
      },
        {
          "text": "-gdb-set auto-load safe-path /",
          "description": "enable safe path",
          "ignoreFailures": false
        }
      ]
    }
  ],
  "inputs": [
    {
      "id": "sdkSysPath",
      "type": "command",
      "command": "shellCommand.execute",
      "args": {
        "command": "ls -d -1 /opt/sdks/*/*",
        "useSingleResult": true
      }
    }
  ]
}

Debugger Logs

Providing logs in .txt because too long for 15.1, 12.1..

Other Extensions

No response

Additional Information

Log file (too huge for pasting)
coredump_issue_debug_vscodelog_15.txt

gdb-multiarch 12.1 (20 minutes!)

gdb_multiarch_12.1_20minutes.txt

gdb15_fresh_wsl(1).txt

[borjamunozf]

I have a dummy python script to calculate elapsed time and map the IDs of the request. It shows the top 10.

import argparse
from pathlib import Path
import re


ELAPSED_PATTERN = r'\d+: \(\d+\) (\d+): elapsed time (\d+)'


def sum_elapsed_time(file: Path):
    elapsed_time_by_id = {}
    pattern = re.compile(ELAPSED_PATTERN)
    with file.open('r') as f:
        for line in f:
            match = pattern.search(line)
            if match:
                unique_id = int(match.group(1))
                elapsed_time = int(match.group(2))

                if unique_id not in elapsed_time_by_id:
                    elapsed_time_by_id[unique_id] = elapsed_time
    
    total_elapsed_time = sum(elapsed_time_by_id.values())

    total_elapsed_time = total_elapsed_time / (1000 * 60)
    return total_elapsed_time, elapsed_time_by_id


def main() -> None:

    parser = argparse.ArgumentParser(description='Calculate elapsed time info - VScode debug')

    parser.add_argument("logfile", nargs='?', help="Log file to parse")
    args = parser.parse_args()

    if not args.logfile:
        print("No log file provided")
        parser.print_usage()
        return

    logpath = Path(args.logfile).resolve()

    total, ids_req = sum_elapsed_time(logpath)
    
    print(f"Total elapsed time: {total} minutes")
    print("Top requests IDs: <id> : <elapsed time> miliseconds")
    print(sorted(ids_req.items(), key=lambda x: x[1], reverse=True)[:10])


main()

However, something it's be wrong because the total elapsed time is way too high always, not the real one. Probably the conc requests and so on, but at least it's helpful to get the longest requests...?

For the gdb_multiarch txt:

Total elapsed time: 39.5403 minutes
Top requests IDs: <id> : <elapsed time> miliseconds
[(**1100**, **1009105**), (1007, 71709), (1072, 20475), (1070, 20474), (1071, 20474), (1068, 20473), (1069, 20473), (1008, 19430), (1016, 19415), (1017, 19415)]

The 1100 takes ~16 minutes itself, which maps to this request (var-create cutFrames)

-> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (100338) <-1100-var-create  - * \"cutFrames\"\n"},"seq":3203}
1: (100338) <-1100-var-create  - * "cutFrames"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (1109438) ->1100^done,name=\"var9\",numchild=\"0\",value=\"4\",type=\"size_t\",thread-id=\"1\",has_more=\"0\"\n"},"seq":3205}
1: (1109438) ->
^done,name="var9",numchild="0",value="4",type="size_t",thread-id="1",has_more="0"
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (1109443) ->(gdb)\n"},"seq":3207}
1: (1109443) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (1109443) 1100: elapsed time 1009105\n"},"seq":3209}
1: (1109443) 1100: elapsed time 1009105

The 1007 request is file-exec-and-symbols, took ~1min 30secs

--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (578) <-1007-file-exec-and-symbols /mnt/disk1/asd/app/bin/DispApp\n"},"seq":86}
1: (578) <-1007-file-exec-and-symbols /mnt/disk1/asd/app/bin/DispApp
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (72285) ->1007^done\n"},"seq":88}
1: (72285) ->1007^done
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (72288) ->(gdb)\n"},"seq":90}
1: (72288) ->(gdb)
--> E (output): {"type":"event","event":"output","body":{"category":"console","output":"1: (72288) 1007: elapsed time 71709\n"},"seq":92}

Could be this issue linked to #9988 ?