[lnkForumImage]
TotalShareware - Download Free Software
Confronta i prezzi di migliaia di prodotti.
Asp Forum
 Home | Login | Register | Search 


 

Forums >

comp.lang.ruby

Profiling question

Tripp Scott

1/22/2005 9:12:00 AM

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
3 Answers

Ilmari Heikkinen

1/22/2005 10:17:00 AM

0

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

Tripp Scott

1/22/2005 1:49:00 PM

0

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?

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

Thanks,
Tripp

David Garamond

1/22/2005 6:35:00 PM

0

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

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