Profiling question

[Tripp Scott]

Given this script:

$ cat ./profile1.rb
#!/usr/bin/ruby

def f1; i = 0; 10_000.times do i += 1 end end
def f2; i = 0; 10_000.times do i -= 1 end end
def f3; i = 0; (1..100).each do |x| i += Math.log(x) end end
def f4; 10.times do f3 end end

f1
f2
10.times do f3 end
f4

Profiling this gives:

$ ruby -rprofile ./profile1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
60.26 2.29 2.29 4 572.50 950.00 Integer#times
12.89 2.78 0.49 10000 0.05 0.05 Fixnum#-
12.89 3.27 0.49 20 24.50 33.50 Range#each
8.95 3.61 0.34 10020 0.03 0.03 Fixnum#+
2.89 3.72 0.11 2000 0.06 0.06 Math.log
1.84 3.79 0.07 1980 0.04 0.04 Float#+
0.53 3.81 0.02 1 20.00 20.00 Profiler__.start_profile
0.26 3.82 0.01 20 0.50 34.00 Object#f3
0.00 3.82 0.00 1 0.00 3800.00 #toplevel
0.00 3.82 0.00 1 0.00 1640.00 Object#f2
0.00 3.82 0.00 1 0.00 350.00 Object#f4
0.00 3.82 0.00 4 0.00 0.00 Module#method_added
0.00 3.82 0.00 1 0.00 1480.00 Object#f1

This is good and all, but how to profile in a higher granularity? That
is, I want to know how many times each of my methods is called (e.g.
f1 once and f3 20 times) and how much total time do they take?

Tripp

 

[Ilmari Heikkinen]

Hello,

Profiling this gives:

$ ruby -rprofile ./profile1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
[snip]
0.26 3.82 0.01 20 0.50 34.00 Object#f3
[snip]
0.00 3.82 0.00 1 0.00 1640.00 Object#f2
0.00 3.82 0.00 1 0.00 350.00 Object#f4
[snip]
0.00 3.82 0.00 1 0.00 1480.00 Object#f1

Are those what you're after?

 

[Tripp Scott]

Hello,

Profiling this gives:

$ ruby -rprofile ./profile1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
[snip]
0.26 3.82 0.01 20 0.50 34.00 Object#f3
[snip]
0.00 3.82 0.00 1 0.00 1640.00 Object#f2
0.00 3.82 0.00 1 0.00 350.00 Object#f4
[snip]
0.00 3.82 0.00 1 0.00 1480.00 Object#f1

Are those what you're after?

LOL. Actually yes. Now why did I miss that?

Thanks,
Tripp

 

[David Garamond]

$ ruby -rprofile ./profile1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
[snip]
0.26 3.82 0.01 20 0.50 34.00 Object#f3
[snip]
0.00 3.82 0.00 1 0.00 1640.00 Object#f2
0.00 3.82 0.00 1 0.00 350.00 Object#f4
[snip]
0.00 3.82 0.00 1 0.00 1480.00 Object#f1

Are those what you're after?

LOL. Actually yes. Now why did I miss that?

Btw, I notice that the times the profiler reports are slower/larger due
to the profiling overhead. Suppose that the profiler reports total
ms/call = X1. The real time from the "time" command when invoking the
script without the profiler = X2 secs. Real time with the profiler = X3
secs. Can I assume that the actual time when running without profiler is
X2/X3 * X1?

$ time ruby script.rb

real 0m0.148s
user 0m0.020s
sys 0m0.010s

$ time ruby -rprofile script.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
...
0.00 0.31 0.00 10 0.00 28.00 Object#f3
...

real 0m0.659s
user 0m0.310s
sys 0m0.060s

$ irb
irb(main):001:0> 0.148/0.659*28.00
=> 6.28831562974203
irb(main):002:0>

So f3 takes about 6.29ms when running normally (without profiler)?