rack-mini-profile slowing down mysql transactions (or measurement?)

[mipearson]

Did a big deploy earlier in this week and was surprised to see our average response time jump from 100ms to 200ms. The deploy did not include any major database work. Part of that deploy was pushing rack-mini-profiler to production.

Surprisingly, removing rack-mini-profiler restored our application to its previous performance levels.

I am not certain yet whether this is an actual regression caused by rack-mini-profiler or merely a NewRelic measurement problem. If it is an actual regression, I suspect that miniprofiler is adding 3-4ms to each database call.

[SamSaffron]

3-4ms per db call is pretty much impossible even when profiling, lets just clarify here, you don't have rack-mini-profiler enabled for all users on the site?

the work it performs when disabled is minuscule, it adds a method call and thread lookup.

[mipearson]

Nope, only enabled for logged in administrators and users from trusted IP addresses (eg, our office). For control I will re-add the gem but not include the before_filter that enables it in those cases.

[mipearson]

Restored the gem, and the configuration, but commented out the logic that enables it for admins & local users.

Very interesting!

Versions

    rack-mini-profiler (0.1.26)
    rails (3.2.13)
    newrelic_rpm (3.6.2.96)

$ ruby --version
ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-linux]

Configuration

# Don't show it by default, only if the user pressers alt-p
Rack::MiniProfiler.config.start_hidden = true
# Move to RHS
Rack::MiniProfiler.config.position = :right

Ruby compiled using RVM and the "falcon" patches as described at https://gist.github.com/funny-falcon/4136373

[SamSaffron]

How are you determining current user

see: https://github.com/discourse/discourse/blob/master/config/initializers/06-mini_profiler.rb

your Rack::MiniProfiler.config.user_provider

[mipearson]

We haven't set up anything fun with the user detection - it's still using the request IP, as is the default. I suspect there's a bug in our code which was making our authorization method fire incorrectly.

However, I found something else interesting. I set up a simple benchmark on the train this morning in one of our views:

%ul
  - range = (Advert.minimum(:product_id)..Advert.maximum(:product_id)).to_a[0..1000]
  %li= "Range: #{range.length} elements"
  %li
    = Benchmark.measure { range.each { |a| Advert.connection.select_value("SELECT title FROM adverts WHERE product_id = #{a}")} }

With MiniProfiler enabled I'd get: Range: 1001 elements 1.680000 0.070000 1.750000 ( 1.892392)

Without: 0.150000 0.020000 0.170000 ( 0.210001)

So, that's about 1.6ms added to each DB request. Remembering what you said about Ruby 1.9.3 and backtrace performance, I added pp=no-backtrace to query. Doing so returned the performance back to pre-miniprofiler levels.

I started work on a PR to both add a skip-backtrace option to config and make it the default for Ruby versions pre 2.x. Thoughts?

[SamSaffron]

I would prefer not to make it default but would be more than happy to add the option

[mipearson]

Thinking about this over the weekend: I was thinking of instead adding an option that omits stacktraces if the query takes less than a certain time to execute.

This could then be set to a sane default on various rubies: ie 10ms for Ruby 1.9, 0ms for Ruby 2.x.

My concern is that if you add MiniProfiler to a Ruby 1.9 project, and you have lots of queries, you'll have a severe case of the observer changing the observed.

Alternatively I could add something to the README.md about this instead.

On Mon, May 20, 2013 at 9:47 AM, Sam notifications@github.com wrote:

I would prefer not to make it default but would be more than happy to add the option

— Reply to this email directly or view it on GitHubhttps://github.com/SamSaffron/MiniProfiler/issues/156#issuecomment-18127124 .

Michael Pearson

[mipearson]

I'm happy to close this request now that my PR has been merged. Do you agree, @SamSaffron ?

[SamSaffron]

sure ... closing