Slow backtraces due to inspect of large local variables

[dpeacock]

Your environment

• ruby -v: ruby 3.1.2p20 (2022-04-12 revision 4491bb740a) [arm64-darwin21]
• rdbg -v: rdbg 1.5.0

Describe the bug
Backtraces are very slow at some points. I added logging and was able to pin the slowness to frame_info.rb in parameters_info:

          local_var = local_variable_get(var)
          t1 = Time.now
          value = DEBUGGER__.safe_inspect(local_var, short: true)
          t2 = Time.now - t1
          if t2 > 0.1
            ::DEBUGGER__.info  "Slow parameters info, safe inspect... length: #{local_var.inspect.length}, type: #{local_var.class}, var: #{var}, value: #{value}, time#{t2}"
          end

This resulted in some output for slow parameters like the following:

DEBUGGER (INFO): Slow parameters info, safe inspect... length: 11729953, type: Hash, var: env, value: {"rack.version"=>[1, 6], "rack.errors"=>..., time0.321832
DEBUGGER (INFO): Slow parameters info, safe inspect... length: 11729955, type: Array, var: args, value: [{"rack.version"=>[1, 6], "rack.errors"=..., time0.436716

I believe the slowness is attributed to the obj.inspect in the safe_inspect. I have a stack with 100+ depth which is resulting in about 25 seconds for the backtrace to return due to slowness on a bunch of frames (most seem to be with the env variable). With the dap_client it doesn't even look like the parameters are used, so it feels a bit pointless retrieving these. However the thread_client however does use this to output the shortened info. Here's a sample output on the rdbg session for one of the slow entries:

  #35	Rails::Engine#call(env={"rack.version"=>[1, 6], "rack.errors"=>...) at ~/.gem/ruby/3.1.2/gems/railties-7.0.2.4/lib/rails/engine.rb:530

To Reproduce
I'm not super clear what's unique about the environment, but it's something to do with having a very large environment variable that causes this type of behavior. I was able to reproduce in the dap client (VS Code) and with the regular thread client (using rdbg -A).

Expected behavior
Backtraces should not take really long times to execute.

[ko1]

I have a stack with 100+ depth which is resulting in about 25 seconds for the backtrace to return due to slowness on a bunch of frames (most seem to be with the env variable)

Wow, 25 seconds...!! with bt command?

[ko1]

DEBUGGER (INFO): Slow parameters info, safe inspect... length: 11729953, type: Hash, var: env, value: {"rack.version"=>[1, 6], "rack.errors"=>..., time0.321832
DEBUGGER (INFO): Slow parameters info, safe inspect... length: 11729955, type: Array, var: args, value: [{"rack.version"=>[1, 6], "rack.errors"=..., time0.436716

So repeating safe_inspect on ENV about 50 times? (it seems to take 0.5 sec per 1 call ENV.inspect)

[ko1]

For example, caching the result can help this case, but it doesn't help in general. Hmm.

Ideas:

• cache the inspect result (describe above)
• skip inspect after 1 second (specified time) in one bt command
• others...?

[dpeacock]

Wow, 25 seconds...!! with bt command?

Correct! This is on my M1, on our cloud environment it's 1-2 minutes.

So repeating safe_inspect on ENV about 50 times?

Yes, the call stack is 100+ and once we're about 35 deep into the stack the majority of the calls have ENV.

others...?

The DAP server doesn't actually use the result of the inspect. I put up a PR so it doesn't actually call the method anymore since the result isn't used which helps for the DAP clients but the issue still exists for thread client. The thread client at least supports requesting the depth of the stack i.e. bt 30, where the DAP server doesn't support this right now (#637).

[rockorequin]

I'm getting the same problem with when safe_inspect calls object.inspect with a RubyXL worksheet, but in my case it's taking almost ten minutes to complete. With debug output around the obj.inspect line, I get:

DEBUGGER: 2022-05-26 19:44:58 +0800 Starting ob.inspect for RubyXL::Worksheet
DEBUGGER: 2022-05-26 19:53:56 +0800 obj.inspect returned string of length 16937866
D

So some sort of timeout for the obj.inspect would be good...

[rockorequin]

Perhaps the safe_inspect could only return the string values of standard data classes such as String, Numeric, TrueClass, FalseClass, etc and just return something like the class name for other classes?

[st0012]

Perhaps the safe_inspect could only return the string values of standard data classes such as String, Numeric, TrueClass, FalseClass, etc and just return something like the class name for other classes?

Yeah I think this is a good suggestion. We can just call #to_s on non-primitive type objects. I'll work on a PR for that.

[rockorequin]

Just a note that I was making safe_inspect convert all Strings using to_s, and when I ran into a binary string representing a JPEG, it crashed rdbg when I tried to inspect the variable. The crash occurred in server_dap.rb:send at line 163 calling JSON.dump (in `generate': source sequence is illegal/malformed utf-8 (JSON::GeneratorError) and trying to rescue this in send didn't work - it just made rdbg detach and the application continue running when it hit the error.

So now in safe_inspect I'm checking for s.encoding being UTF-8 before using to_s to inspect it and if it is another encoding I just make safe_inspect indicate that it's a String with encoding XYZ.

[ko1]

could you try the master?

[rockorequin]

I don't think that change has fixed the problem: I just tried the master branch in my VSCode project: when the program stopped at my breakpoint I get a spinning cursor next to the "Local Variables" section. I'll let it run for a while to see if it finishes.

[rockorequin]

To update my earlier comment, the spinning cursor next to "Local Variables" in VSCode didn't go away before my laptop went to sleep (ie an hour after I left it).

The code for the class LimitedPP in the commit looks fine, if I load a spreadsheet using rubyXL and call LimitedPP.pp on either a workbook or a worksheet it works fine, so I think it's another problem causing this spinning cursor. Do you have any suggestions for where I could find out what is causing rdbg to hang?

I noticed a few weeks ago when I tried to rescue an exception in server_dap.rb:send() it didn't work (see my comment above), so could there be an issue with the catch and throw in LimitedPP or with maybe another exception?

If I use my modified debug gem from earlier where safe_inspect returns just the classname for non-primitive types, the breakpoint that master hangs on works fine, but if I type @workbook.inspect or @worksheet.inspect in the debug window, rdbg hangs. These instance vars are obviously in the %self variable that appears first in the Local variables window, so I suspect one or both of these are the cause of the hang at the breakpoint when using the latest master.

[rockorequin]

I think the problem isn't in the LimitedPP.pp code, it happens when safe_inspect() calls obj.inspect for the "self" class for the local variables window. If I call LimitedPP.pp(obj, 1024) instead of obj.inspect, the local variables window comes up quickly. So I'm experiencing a second problem loading the local variables window rather than the backtrace.

[rockorequin]

So my question is: should we always use LimitedPP.pp even if there is no max length specified? If I limit it to say 128kB, there's a slight pause loading the local variables in VSCode, which is acceptable, but just "obj.inspect" causes this hang. What is a reasonable size to expect from an inspect, in any case?

Should I open a different ticket because this is strictly speaking not related to the backtrace now, but to the normal safe_inspect with no maximum string length?

[rockorequin]

I have added a new issue at #674 for the slow loading/hang of the local variables window.