Debugging with debase is 2-3x Slower than ruby-debug-base19x

[tleish]

We recently migrated a large Rails 3 application from Ruby 1.9.3 to Ruby 2.0 and noticed that debugging with ruby-debug-ide and debase it became significantly slower. In fact, many of our developers often switch back to Ruby 1.9.3 temporarily just to use ruby-debug-base19x for debugging because it's so much faster than debugging in 2.0 with debase. To give an example, one area of the code with heavy lifting takes 3-5 seconds in 1.9.3 debugging but 15-20 seconds in 2.0 debugging.

Any ideas on how to improve the speed to match 1.9.3 ?

Setup: Ruby 2.0.0p247 ruby-debug-ide 0.4.17 debase 0.0.3

IDE: Rubymine 5.4.3.2.1 Rails 3.2.13 OS: OS X 10.8.4

[tpodom]

Definitely seeing the same thing here. A request that took about 400ms in 1.9.3 with debug is taking about 2s with 2.0.0.

My setup is roughly the same, OS X 10.8.4 but debase 0.0.4 and ruby-debug-ide 0.4.18.

[s12chung]

same here....

[denofevil]

Guys, I've pushed 31cbdee703ec3d1dc258997e7a43b0b12d6482da that is approximately 2x faster on simple render action on my machine. Please try building from repo and see if that helps.

[tpodom]

OK so from my initial testing the new commit is definitely faster but still noticeably slower than the 1.9 debug. I tested a JSON request on ruby 1.9 debug, debase 0.0.4, and the debase from that commit and I saw results of 700ms, 1.4s, 2.2s. And on a large page load with a lot of dynamic requests (178 total requests) I saw times of 18s with ruby 1.9 debug, 41s with the new debase and 1.0m with debase 0.0.4.

[denofevil]

I'm trying to reuse full lazy stack evaluation using rb_debug_inspector like ko1/debugger2 does and it brings time on par with 1.9, but there are two main issues:

1. Calculated vs real stack size mismatch rendering stepping unusable
2. Segfault on breakpoints

[denofevil]

I've pushed b0aa71dd9d1894500ddbeb0574594a1d65d532ae resolving issue 1 and d52ec18b5cbbbc8975a499f2c9a77beeb1b9f13a resolving issue 2. Please update and try again

[tpodom]

OK I just pulled down the latest version and it seems really fast now. I would have to do more testing but it seems faster than 1.9 debug.

However, I'm running into it restarting unicorn on breakpoint hit so I'm guessing it must be segfaulting still. I ran gdb on the unicorn process and here's what it output:

Program received signal EXC_BAD_ACCESS, Could not access memory. Reason: KERN_INVALID_ADDRESS at address: 0x0000000000000009 [Switching to process 98390 thread 0xc07] 0x000000010ffc36a8 in context_create (thread=140247853841280, cDebugThread=140247787270720) at context.c:137 137 context->stack_size = (int)RARRAY_LEN(rb_funcall(thread, rb_intern("backtrace_locations"), 1, INT2FIX(1)));

[denofevil]

Can you please attach output from bt command in gdb?

[tpodom]

(gdb) bt
#0  0x000000010ffc36a8 in context_create (thread=140247853841280, cDebugThread=140247787270720) at context.c:137
#1  0x000000010ffc49ec in Debase_thread_context [inlined] () at /Users/odom/.rvm/gems/ruby-2.0.0-p247@focal-rails/bundler/gems/debase-b0aa71dd9d18/ext/debase_internals.c:31
#2  0x000000010ffc49ec in Debase_current_context [inlined] () at /Users/odom/.rvm/gems/ruby-2.0.0-p247@focal-rails/bundler/gems/debase-b0aa71dd9d18/ext/debase_internals.c:40
#3  0x000000010ffc49ec in process_return_event (trace_point=140247820879200, data=<value temporarily unavailable, due to optimizations>) at debase_internals.c:233
#4  0x000000010fc93a8b in tp_call_trace (tpval=140247820879200, trace_arg=<value temporarily unavailable, due to optimizations>) at vm_trace.c:935
#5  0x000000010fc95583 in exec_hooks (th=0x7f8e05950340, list=0x7f8dfa8035d0, trace_arg=0x111977980, can_clean_hooks=<value temporarily unavailable, due to optimizations>) at vm_trace.c:268
#6  0x000000010fc93096 in rb_threadptr_exec_event_hooks_orig (trace_arg=0x111977980, pop_p=1) at vm_trace.c:309
#7  0x000000010fc86d11 in vm_exec (th=<value temporarily unavailable, due to optimizations>) at vm.c:1405
#8  0x000000010fc8a433 in invoke_block_from_c (th=<value temporarily unavailable, due to optimizations>, block=0x7f8dfe0a0580, self=140247933859040, argc=0, argv=<value temporarily unavailable, due to optimizations>, blockptr=<value temporarily unavailable, due to optimizations>, cref=<value temporarily unavailable, due to optimizations>, defined_class=<value temporarily unavailable, due to optimizations>) at vm.c:648
#9  0x000000010fc855cb in vm_invoke_proc (th=0x7f8e05950340, proc=0x7f8e0591cf60, self=<value temporarily unavailable, due to optimizations>, defined_class=<value temporarily unavailable, due to optimizations>, argc=0, argv=0x7f8dff823bb8, blockptr=<value temporarily unavailable, due to optimizations>) at vm.c:696
#10 0x000000010fc85510 in rb_vm_invoke_proc [inlined] () at vm.c:715
#11 0x000000010fc85510 in rb_vm_invoke_proc [inlined] () at /Users/odom/.rvm/src/ruby-2.0.0-p247/vm.c:224
#12 0x000000010fc85510 in vm_call0_body (th=<value temporarily unavailable, due to optimizations>, ci=<value temporarily unavailable, due to optimizations>, argv=<value temporarily unavailable, due to optimizations>) at vm.c:1669
Previous frame identical to this frame (gdb could not unwind past this frame)

[tpodom]

It appears to something with the rb_funcall. My gdb is kind of rusty but I set a breakpoint and was stepping through and hit this line:

(gdb) next
rb_funcall (recv=<value temporarily unavailable, due to optimizations>, mid=<value temporarily unavailable, due to optimizations>, n=<value temporarily unavailable, due to optimizations>) at vm_eval.c:794
794     return rb_call(recv, mid, n, argv, CALL_FCALL);
(gdb) next
Program received signal EXC_BAD_ACCESS, Could not access memory.

[denofevil]

I've removed stack size calculation from context_create because it's no longer needed, probably should fix your problem

[tpodom]

Seems to work perfectly now. I'm able to set a break point and step through the code. The stepping seems more accurate now too. And performance-wise now it looks to be roughly identical to ruby 1.9 debug speed.

Thanks! This is a major improvement!

[denofevil]

Great!

I'm a little bit disappointed because I had to use Ruby VM internal headers to get proper stack size, but I'll try to discuss that with Koichi (debugger2 is suffering from the same problem) and probably we'll be able to improve that part too.

[tleish]

I'm only seeing a slight performance increase with this update, not the same amount as other have reported.

6sec > Ruby 2.0 w debase 0.0.4 7sec > Ruby 2.0 w debase 0.0.3 3sec > Ruby 1.9.3

[denofevil]

Are you sure you're trying latest version from sources? These fixes are not pushed to rubygems yet. To make sure latest version is used by RubyMine you need to clone repo, and perform following commands: bundle install rake build gem install pkg/debase-0.0.4.gem

On 27.08.2013, at 20:16, tleish notifications@github.com wrote:

I'm only seeing a slight performance increase with this update, not the same amount as other have reported.

6sec > Ruby 2.0 w debase 0.0.4 7sec > Ruby 2.0 w debause 0.0.3 3sec > Ruby 1.9.3

— Reply to this email directly or view it on GitHub.

[tleish]

Yes, that's exactly how I installed it with the above results I reported.

[denofevil]

And what are run times (without debugger) on 2.0 and 1.9?

[tleish]

I was incorrect. I cleared out everything and reinstalled my gems. I ran some additional tests and found it's just as fast as 1.9.3 now. I must've had an older 0.0.4 still in there.

Unit Tests Benchmark

13.63268s - 2.0.0 165.7345s - 2.0.0 w debase (0.0.3) 83.67467s - 2.0.0 w debase (head)

13.63268s - 1.9.3 83.97262s - 1.9.3 w ruby-debug-base19x

Very excited to have the debugging speed back. Thank you.

[denofevil]

That's good to hear, thank you!