Profiling question

ruby-talk
1

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

2

Hello,

···

On 22.1.2005, at 11:12, Tripp Scott wrote:

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?

--
Ilmari Heikkinen

3

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

Thanks,
Tripp

···

On Sat, 22 Jan 2005 19:17:25 +0900, Ilmari Heikkinen <kig@misfiring.net> wrote:

Hello,

On 22.1.2005, at 11:12, Tripp Scott wrote:
> 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?

4

Tripp Scott wrote:

$ 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? :slight_smile:

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)?

···

--
dave