Useless callgraph because of Kernel#sleep and Rack::RubyProf#call

[gioele]

I am using ruby-prof to trace a performance problem in a Rails application. Unfortunately the call graph it produces says that most of the time is used in Kernel#sleep (or in workers thread of Puma) and that Rack::RubyProf#call is the caller of everything.

This happens regardless of the used measurement type: I tried with wall time, process time and cpu time.

The call graph is generated by the git version of the ruby-prof gem (commit 820cc26b646a1d9232097838aeecf32d532715db) and I am reading it using KCachegrind 0.7.4kde (the version bundled with Ubuntu 14.04 LTS).

The profiled code runs on Rails 4.2.5 and the Rack::RubyProf piece of middleware is loaded using

config.middleware.use Rack::RubyProf,
    :path => Rails.root + 'tmp/web-profile',
    :printers => { RubyProf::CallTreePrinter => 'calltree.cachegrind.out' }

inside config/environments/development.rb.

I can provide via mail the quite chubby call graph file if needed.

[skaes]

Without the code, it's impossible for me to say whether this is be a ruby-prof bug or whether your program just sleeps a lot. However, when measuring cpu time, sleep should not appear as prominent as you said it is. Maybe you didn't really measure cpu time?

Also, I haven't used kcachegrind before. Could you please use the multi printer to produce a linked stack and graph profile? The stack profile should tell you much better where sleep is being called.

[gioele]

The source code can be found at https://github.com/cceh/sanskrit-web but it will be hard to run because it relies on a non-standard DB: BaseX.

This is the output of RubyProf::MultiPrinter using the wall measurement method:

• https://gigamove.rz.rwth-aachen.de/download/id/bpTDFL377e4GYV

These other two files are the output of the same code measured using the cpu method.

• MultiPrinter files: https://gigamove.rz.rwth-aachen.de/download/id/eqT99c9h3iKrwQ
• CacheGrind file: https://gigamove.rz.rwth-aachen.de/download/id/PY6mxxbdsNnRK8

[skaes]

If you look at the stack profile, you can clearly see that the sleep time is accumulated in the puma thread pool.

You can get rid of the information collected by background threads by patching the ruby-prof rack middleware by adding the following ruby code in the rack middleware before the profile block:

RubyProf.exclude_threads = Thread.list.select{|t| t != Thread.current}

[skaes]

@gioele I'd love to get some feedback on this ticket. Did my comments help you to make progress?

[gioele]

I still get the same problem after the following modification to /lib/ruby-prof/rack.rb

        result = nil
+       ::RubyProf.exclude_threads = Thread.list.select{|t| t != Thread.current}
        data = ::RubyProf::Profile.profile do
          result = @app.call(env)
        end

Was that the right "profile block" you were referring to?

[skaes]

I would have expected only one thread to show up in the output of MultiPrinter (and the threads it spawns).

Don't know how to proceed from here. The thread exclusion code has tests and I manually tested it as well.

When you say you have the same problem: are you still looking at kcachegrind? In that case I suggest to use the stack profile instead. It clearly shows where your main thread spends its time.

[skaes]

I have tested one of my rails apps using the rack middleware shipped with ruby-prof. The thread exclusion approach works perfectly fine for me. Note however, that all backgrounds threads which are created lazily while processing the first request, will not be excluded from the profile. Reloading the url in the browser got rid of all background threads for me.

One could envision an option for ruby-prof to profile only a single thread. Would this help you?

[skaes]

I had a look at the callgrind file format specification (http://valgrind.org/docs/manual/cl-format.html#cl-format.reference.grammar). The grammar allows for multiple data sections, thereby supporting per thread profiling data. However, kcachegrind does not support loading such files. This means we'd have to write one file per thread.

On top of that, we will need to merge fiber call stacks into their originating thread.

[codegourmet]

@skaes @gioele the exclude_threads is not viable in a puma production setting, since new requests will show up during profiling and can't be excluded as threads before knowing about them. See issue #188 for a first solution.

[skaes]

I have implemented a solution as described above. Will push it soonish.

[skaes]

@gioele Please check out the current master.

The Rack middleware now has an option to focus on a single thread and also the possibility to merge all fibers into the thread information. This should give correct results for you.

[skaes]

@gioele did you have a chance to test? I would like to release the changes soonish.

[gioele]

@skaes: I tested the current master (407dc04db16da397f400173b85da9f82214ad7b3) and it looks like the problem is solved with the new options.

For the record, here is how I used RubyProf inside Rails on top of Puma:

config.middleware.use Rack::RubyProf,
    :request_thread_only => true,
    :merge_fibers => true,
    :path => Rails.root + 'tmp/web-profile',
    :printers => { RubyProf::CallTreePrinter => 'calltree' }

[rdp]

@skaes for president :)

On Thu, Mar 31, 2016 at 10:02 AM, Gioele notifications@github.com wrote:

@skaes https://github.com/skaes: I tested the current master (407dc04 https://github.com/ruby-prof/ruby-prof/commit/407dc04db16da397f400173b85da9f82214ad7b3) and it looks like the problem is solved with the new options.

For the record, here is how I used RubyProf inside Rails on top of Puma:

config.middleware.use Rack::RubyProf, :request_thread_only => true, :merge_fibers => true, :path => Rails.root + 'tmp/web-profile', :printers => { RubyProf::CallTreePrinter => 'calltree' }

— You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub https://github.com/ruby-prof/ruby-prof/issues/178#issuecomment-204000462

[codegourmet]

Indeed!

[skaes]

Seems the problem is solved. Closing issue.