Profile.rb overhead

ruby-talk
1

I have a script.

tim@zaphod:~/ruby$ ruby -v
ruby 1.6.7 (2002-03-19) [i386-linux]
tim@zaphod:~/ruby$ time ruby test1.rb

real 0m22.490s
user 0m20.010s
sys 0m0.340s

So far, so good.
But when I try to profile this script, it runs for ages:

tim@zaphod:~/ruby$ time ruby -r profile test1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
39.60 395.46 395.46 77090 5.13 17.16 Array#each
…

real 18m37.780s
user 16m38.740s
sys 0m6.580s

Now I realise that the profiler must have some overhead, but this is
ridiculous - it’s taking 50 times longer! I’ve run similar scripts through
the profiler before, and I’ve never seen an increase like this. Any ideas?

Tim Bates

···

–
tim@bates.id.au

2

thats typical since it installs a trace proc which is invoked for each
source code line.

rbprof might be what you need but it hasn’t been updated in ages… Check
RAA.

/Robert Feldt

···

On Wed, 16 Apr 2003, Tim Bates wrote:

I have a script.

tim@zaphod:~/ruby$ ruby -v
ruby 1.6.7 (2002-03-19) [i386-linux]
tim@zaphod:~/ruby$ time ruby test1.rb

real 0m22.490s
user 0m20.010s
sys 0m0.340s

So far, so good.
But when I try to profile this script, it runs for ages:

tim@zaphod:~/ruby$ time ruby -r profile test1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
39.60 395.46 395.46 77090 5.13 17.16 Array#each
…

real 18m37.780s
user 16m38.740s
sys 0m6.580s

Now I realise that the profiler must have some overhead, but this is
ridiculous - it’s taking 50 times longer! I’ve run similar scripts through
the profiler before, and I’ve never seen an increase like this. Any ideas?

3

“Tim Bates” tim@bates.id.au schrieb im Newsbeitrag
news:200304161320.52562.tim@bates.id.au…

I have a script.

tim@zaphod:~/ruby$ ruby -v
ruby 1.6.7 (2002-03-19) [i386-linux]
tim@zaphod:~/ruby$ time ruby test1.rb

real 0m22.490s
user 0m20.010s
sys 0m0.340s

So far, so good.
But when I try to profile this script, it runs for ages:

tim@zaphod:~/ruby$ time ruby -r profile test1.rb
% cumulative self self total
time seconds seconds calls ms/call ms/call name
39.60 395.46 395.46 77090 5.13 17.16 Array#each
…

real 18m37.780s
user 16m38.740s
sys 0m6.580s

Now I realise that the profiler must have some overhead, but this is
ridiculous - it’s taking 50 times longer! I’ve run similar scripts
through
the profiler before, and I’ve never seen an increase like this. Any
ideas?

The profiler overhead increases with increased number of invocations of
small methods. Array#each seems to be called quite often, so this might
be the reason for the overhead.

Regards

robert