Evaluating expression of large objects from the debug console is extremely slow

[dobos]

I'm seeing an issue that apparently hasn't been reported yet. I have a fairly large dictionary in memory and when I want to get its length from the debug console it takes tens of seconds. Obviously, getting the repr of the dict takes that much time but I only want to get its length.

Code to reproduce:

from unittest import TestCase
from collections import defaultdict
import numpy as np
from types import SimpleNamespace

class MyTest(TestCase):
    def test_large_defaultdict(self):
        d = defaultdict(lambda: defaultdict(list))
        for k in 'abcdef':
            for l in 'ghijk':
                for i in range(10000):
                    d[k][l].append(SimpleNamespace(
                        key = k,
                        cycle = np.arange(20),
                        value = np.zeros(20)
                    ))

        pass

Set breakpoint on pass and try to evaluate len(d) from the debug console after the breakpoint is hit. This warning is printed in the console:

pydevd warning: Computing repr of d (defaultdict) was slow (took 42.36s)
Customize report timeout by setting the `PYDEVD_WARN_SLOW_RESOLVE_TIMEOUT` environment variable to a higher timeout (default is: 0.5s)

Yes, it is slow but why is repr called to print the number of items?

[dobos]

The culprit can be the variables window (auto-watch). I've tried hiding it but it didn't help.

[connor4312]

pydevd warning: Computing repr of d (defaultdict) was slow (took 42.36s)

This looks like it's on the Python debugger side @eleanorjboyd

If there is renderer issues: VS Code and DAP support paginating arrays via indexedVariables, I recommend the Python debugger adopt this if it hasn't already to avoid slowdowns.

[eleanorjboyd]

Thanks Connor for taking a look.

Ill investigate this @dobos, one question; if you don't run "len(d) from the debug console after the breakpoint is hit" do you still see the pydevd warning? Trying to understand if you are saying the calculation is done by the variables window or only once you take the action

[dobos]

I was also suspicious about the watch or variables window but the issue seems to only happen when I actually try to access a variable, be it the console or the variables windows. From the console, even len(d) seems to count as variable access that triggers the expansion of the variable. I don't know how to debug vscode and the extensions themselves so I can't investigate this further but the issue is very easy to reproduce with the code I posted.

[eleanorjboyd]

@rchiodo - would this be in your wheelhouse regarding the time taken for variable access during debugging?

[rchiodo]

I would imagine that anything that causes the dictionary to be eval'd is going to cause the repr slowdown.

Turning this on would log what we were asked to evaluate:

https://github.com/microsoft/debugpy/wiki/Enable-debugger-logs#logging-using-debug-configuration

One of the logs should have the DAP request from VS code.

[rchiodo]

Repr of a dictionary should short circuit though, so not sure why it's taking so long.
https://github.com/microsoft/debugpy/blob/99b202ee21441f844b4c8fa3f79d518834fa5ff5/src/debugpy/_vendored/pydevd/_pydevd_bundle/pydevd_safe_repr.py#L33

Perhaps the dict is not being flagged as a collection object for some reason.

[eleanorjboyd]

@dobos could you give that a try to enable that debugging and let us know- thanks!

[dobos]

I missed one piece of important information, I'm running a debugger in a remote SSH session. I turned on logging from debugpy and I can now see the string representation of the big dictionary in the log so it's generated at some point for some reason, even though the expression I wanted to evaluate in the Debug Console is simply the length of the dictionary: len(d).

Here's the relevant part of the log:

6138 Client --> Adapter:
{
    "command": "variables",
    "arguments": {
        "variablesReference": 3
    },
    "type": "request",
    "seq": 15
}
11348 Client --> Adapter:
{
    "command": "evaluate",
    "arguments": {
        "expression": "len(d)",
        "frameId": 2,
        "context": "repl"
    },
    "type": "request",
    "seq": 16
}
43343 Client <-- Adapter:
{
    "seq": 33,
    "type": "response",
    "request_seq": 15,
    "success": true,
    "command": "variables",
    "body": {
        "variables": [
            {
                "name": "d",
                "value": "defaultdict(<function MyTest.test_large_defaultdict.<locals>.<lambda> at 0x7f70e03b9e10>, {'a': defaultdict(.... this is the full __repr__ of d ....)",
                "type": "defaultdict",
                "evaluateName": "d",
                "variablesReference": 5
            },
            {
                "name": "i",
                "value": "9999",
                "type": "int",
                "evaluateName": "i",
                "variablesReference": 0
            },
            {
                "name": "k",
                "value": "'f'",
                "type": "str",
                "evaluateName": "k",
                "variablesReference": 0,
                "presentationHint": {
                    "attributes": [
                        "rawString"
                    ]
                }
            },
            {
                "name": "l",
                "value": "'k'",
                "type": "str",
                "evaluateName": "l",
                "variablesReference": 0,
                "presentationHint": {
                    "attributes": [
                        "rawString"
                    ]
                }
            },
            {
                "name": "self",
                "value": "<test_bigrepr.MyTest testMethod=test_large_defaultdict>",
                "type": "MyTest",
                "evaluateName": "self",
                "variablesReference": 6
            }
        ]
    }
}
43344 Client <-- Adapter:
{
    "seq": 34,
    "type": "event",
    "event": "output",
    "body": {
        "output": "pydevd warning: Computing repr of d (defaultdict) was slow (took 37.20s)\nCustomize report timeout by setting the `PYDEVD_WARN_SLOW_RESOLVE_TIMEOUT` environment variable to a higher timeout (default is: 0.5s)\n",
        "category": "important",
        "source": {}
    }
}
43385 Client <-- Adapter:
{
    "seq": 35,
    "type": "response",
    "request_seq": 16,
    "success": true,
    "command": "evaluate",
    "body": {
        "result": "6",
        "variablesReference": 0,
        "type": "int",
        "presentationHint": {}
    }
}