Lost time in ruby-prof results?

[Radosław Bułat]

I'm profiling my application. One section of the result looks like this:

--------------------------------------------------------------------------------

                      0.092      0.000      0.000      0.092             6/39      Paperclip::Processor#convert

                      0.107      0.000      0.000      0.107             9/39      Paperclip::FileCommandContentTypeDetector#type_from_file_command

                      0.113      0.000      0.000      0.113             6/39      Paperclip::GeometryDetector#geometry_string

                      0.115      0.000      0.000      0.115             6/39      Paperclip::Processor#identify

                      0.160      0.000      0.000      0.160            12/39      Paperclip::MediaTypeSpoofDetector#type_from_file_command

  43.68%   0.05%      0.588      0.001      0.000      0.587               39      Paperclip::Helpers#run

                      0.025      0.000      0.000      0.025          39/7396      Class#new

                      0.001      0.000      0.000      0.000            39/39      <Class::Cocaine::CommandLine>#path=

                      0.000      0.000      0.000      0.000            9/232      String#split

                      0.000      0.000      0.000      0.000           39/266      Hash#merge

                      0.000      0.000      0.000      0.000            39/39      Paperclip::Logger#logging?

                      0.000      0.000      0.000      0.000           39/396      Array#flatten

                      0.000      0.000      0.000      0.000            9/138      String#match

                      0.000      0.000      0.000      0.000           39/462      Array#uniq

                      0.000      0.000      0.000      0.000            39/39      Paperclip::Logger#logger

                      0.000      0.000      0.000      0.000           39/350      Array#compact

                      0.000      0.000      0.000      0.000           78/117      <Module::Paperclip>#options

                      0.000      0.000      0.000      0.000            39/39      <Class::Cocaine::CommandLine>#path

                      0.000      0.000      0.000      0.000           9/3205      Kernel#nil?

--------------------------------------------------------------------------------

(https://gist.githubusercontent.com/radarek/21188eecded211e2a617/raw/6ae2fc90e1417dcd875dfd82966d309556b4ab85/profile.txt)

As you can see Paperclip::Helpers#run takes 43% (0.588s), its self time is 0.001s. Time spent in children is 0.587 but looking at the following child results this time disappeared. Class#new takes 0.025s and <Class::Cocaine::CommandLine>#path= takes 0.001s, the rest is just 0s.

I'm using WALL_TIME measure mode, GC is disabled (using GC.disable method). Ruby is 2.1.0 ruby 2.1.0p0, Mac OSX 10.10.

Am I doing something wrong or there is a bug in ruby-prof?

[Radosław Bułat]

Problem solved. If you are interested in details look at the discussion: https://github.com/ruby-prof/ruby-prof/issues/136