Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Time taken by particular child underestimated #136

Closed
agrimm opened this issue Jan 16, 2014 · 24 comments
Closed

Time taken by particular child underestimated #136

agrimm opened this issue Jan 16, 2014 · 24 comments
Labels

Comments

@agrimm
Copy link
Contributor

agrimm commented Jan 16, 2014

Given the following code

class SlowClass
  def time_sink
    1234567890 ** 300
    false
  end
end

class SlowSearcher
  def do_find(slow_objects)
    slow_objects.find(&:time_sink)
  end
end

class MainClass
  def self.main_method
    slow_objects = [SlowClass.new] * 100_000
    slow_searcher = SlowSearcher.new
    slow_searcher.do_find(slow_objects)
  end
end

[1].each do
  MainClass.main_method
end

the time taken by a child of Enumerable#find is underestimated:

                      3.418      0.000      0.000      3.418              1/1      SlowSearcher#do_find
  99.99%   0.00%      3.418      0.000      0.000      3.418                1      Enumerable#find
                      0.000      0.000      0.000      0.000              1/2      Array#each

The values describing the parent, and the method being profiled are correct, but it wrongly claims that no time is taken in Array#each or its children. However, when profiling SlowClass#time_sink, it correctly calculates the time taken by Array#each and its children:

                      3.361      0.129      0.000      3.232    100000/100000      Array#each
  98.33%   3.78%      3.361      0.129      0.000      3.232           100000      SlowClass#time_sink
                      3.232      3.232      0.000      0.000    100000/100000      Fixnum#**

Getting rid of [1].each makes the profile data correct.

https://gist.github.com/agrimm/8464764 contains full profiling data, plus confirmation that it's not a problem with the stack trace, as was the case with #123 . I ran it on Ruby 2.2.0-dev, with a recent enough version to have Ruby bug 9321 fixed.

@skaes
Copy link
Member

skaes commented Feb 15, 2015

I know what's going wrong, but I'm not sure whether I really want to fix it.

RubyProf has been computing incorrect timings in the presence of recursive methods for a long time until I fixed that in 12c8c9a, based on http://railsexpress.de/papers/callgraph.pdf. Now the overall timings per method are correct for recursive methods, but the child values in the graph display are now wrong for these methods.

Fixing would require recomputing time values each time a method is displayed, which changes the graph printer into a O(n*n) algorithm. For large programs with thousands of methods, this seems to be problematic.

I have a rough sketch ready on this branch, but I haven't tried it yet on larger programs. Need to think about how this can be optimized, before I can release (if at all).

Could you let me know what you think?

@agrimm
Copy link
Contributor Author

agrimm commented Feb 18, 2015

Hi Skaes,

Thanks for looking into this. Unfortunately, I haven't been doing any code profiling lately, so I can't say what its performance would be like on my application, and whether O(n^2) would be problematic.

If it does end up as WONTFIX, there should be documentation explaining that this problem can occur.

@skaes
Copy link
Member

skaes commented Feb 19, 2015

thx for your feedback. I'll investigate whether large programs can still be analyzed.

@skaes
Copy link
Member

skaes commented Feb 22, 2015

@agrimm I will fix it.

@ioquatix
Copy link

Can you use some kind of cache or memorisation so that the recursion detection isn't so expensive?

@skaes
Copy link
Member

skaes commented Feb 22, 2015

memoization, yes, of course.

@radarek
Copy link

radarek commented Feb 22, 2015

Hi.

I have similar problem described here: https://groups.google.com/forum/#!topic/ruby-optimization/dq29hcsGgqc

Is it the same bug/feature?

@skaes
Copy link
Member

skaes commented Feb 22, 2015

@radarek that's impossible to tell without having the full ruby-prof output.

@radarek
Copy link

radarek commented Feb 22, 2015

@skaes Here is full output: https://gist.githubusercontent.com/radarek/21188eecded211e2a617/raw/full.txt

(its new profile taken a minute ago so it is a little different than previous but the same problem exists)

@skaes
Copy link
Member

skaes commented Feb 22, 2015

@radarek I suggest you override ActiveRecord's inspect method to produce a more readable output (see https://github.com/skaes/railsbench/blob/master/lib/railsbench/railsbenchmark.rb#L89).

Apart from that: yes you are affected, as you have methods marked as recursive.

Could you rerun the profiling using my own ruby prof repo using branch "recalculate-recursiveness-when-printing" : https://github.com/skaes/ruby-prof/tree/recalculate-recursiveness-when-printing?

@radarek
Copy link

radarek commented Feb 22, 2015

Ok, I rerun this and here are new results: https://gist.githubusercontent.com/radarek/21188eecded211e2a617/raw/ee3faa09a398abf3d1563215ea5604c487abb1f8/profile2.txt

It definitely looks better now. It took about ~2h to generate report so it also needs optimization. Otherwise it is not usable at all for real worlds app size.

Thanks for tips for inspect method. I will try it.

@skaes
Copy link
Member

skaes commented Feb 22, 2015

@radarek I have released a new ruby-prof version (0.15.5), which should be faster.

Can you please try it? Hopefully it'll take only minutes now ...

@radarek
Copy link

radarek commented Feb 22, 2015

Hm. I have updated ruby-prof to 0.15.5 and it generates results where almost all children of Paperclip::Helpers#run have 0s. Are you sure that 0.15.5 includes correct changes?

@skaes
Copy link
Member

skaes commented Feb 22, 2015

Merge error. Sorry. Use version 0.15.6 please.

@radarek
Copy link

radarek commented Feb 22, 2015

Still the same problem: https://gist.githubusercontent.com/radarek/21188eecded211e2a617/raw/c3ea8043a8f6e37fa8259d838282422cb94cfd1d/profile3.txt

I rerun profile with updated branch recalculate-recursiveness-when-printing and results are the same as profile3.txt. I guess some logic has been lost during optimization.

@skaes
Copy link
Member

skaes commented Feb 22, 2015

@radarek thx for the feedback. I have tested the example given by @agrimm and it works as expected. Unfortunately your profile is really hard to read. Could you please apply my suggested change to the inspect method and also specify some useful min_percent value, e.g. 1% so we get a smaller profile?

@radarek
Copy link

radarek commented Feb 22, 2015

Yeah, sure. Give me a minute.

@radarek
Copy link

radarek commented Feb 22, 2015

@skaes Ok, here are results using 0.15.6: https://gist.githubusercontent.com/radarek/21188eecded211e2a617/raw/b9dd594d870bf602be4d13658d6f0d4ba2641473/profile4.txt

(btw, in rails 4 trick https://github.com/skaes/railsbench/blob/master/lib/railsbench/railsbenchmark.rb#L89 doesn't work because inspect is defined in one of included module so super call original method, quick fix is to call to_s instead)

@skaes
Copy link
Member

skaes commented Feb 22, 2015

Unfortunately, I still can't really make much of this, other than being a bit unsure about whether my implementation is correct.

Could you perform another profile, this time using the multi printer and collect the resulting files in some archive and send it to my email address? The stack profile should be correct in all cases and it should show you better where most of the time is spent. And it links to the graph html profile. And it will hopefully show me where things go wrong (if at all).

I'll pack it up for today. TTFN.

@skaes
Copy link
Member

skaes commented Feb 22, 2015

One last question: how long did it take to generate the graph profile output?

@radarek
Copy link

radarek commented Feb 22, 2015

I sent you results printed with multi printer.

Generating time looks as follows:

version 0.15.4

MultiPrinter
 21.900000   1.070000  22.970000 ( 23.059455)

GraphHtmlPrinter
  1.420000   0.040000   1.460000 (  1.464425)


version 0.15.6

MultiPrinter
 30.220000   1.120000  31.340000 ( 31.468126)

GraphHtmlPrinter
  1.720000   0.030000   1.750000 (  1.758516)

@radarek
Copy link

radarek commented Feb 22, 2015

@skaes suggested to me that I should rerun this with newer ruby version (I was using 2.1.0). Running ruby-prof 0.15.6 with ruby 2.1.5 gives me good results. Thank you @skaes for your time.

@skaes
Copy link
Member

skaes commented Feb 22, 2015

Closing the issue as it appears to be fixed.

@skaes
Copy link
Member

skaes commented Dec 6, 2015

Unfortunately, my method of caching the recursive property has both a faulty implementation and is conceptually wrong. Not clear how this can be fixed. See #170

@skaes skaes added the bug label Dec 6, 2015
@skaes skaes closed this as completed in 46f1676 Dec 9, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

4 participants