From: Robert Klemme Date: 2005-04-04T22:29:47+09:00 Subject: Re: Ruby optimization - re-implement in compiled language? "Randy Kramer" schrieb im Newsbeitrag news:200504040851.14886.rhkramer@gmail.com... > On Monday 04 April 2005 01:06 am, Aredridel wrote: > > > The profiler identifies all the major bottlenecks as low level ruby > > > methods (.each etc), so I'm considering re-implemented the guts of the > > > dependency analysis in C++. I'm sure people here have done similar > > > things, so I was wondering how beneficial it was for them? > > > > Each shows high in a profiler, because the entire contents of the inner > > part of the loop count against it. Just so you're warned. > > So, iiuc, you're saying that the profiler sort of counts things multiple > times--when you look at any individual part of the inner loop > (wherever/whatever that might be), the entire time spent in that inner loop > is "charged" to each individual part that you might look at? > > So, you really can't tell which of those parts is the biggest contributor to > the (presumed) problem? It's a bit different. First of all there is a column "cumulative seconds" in the output which actually sums up time through the output table (i.e. "cumulative seconds" of one row is the value of the previous row plus this rows "self seconds". (Note: percent values are garbled because of #sleep) 15:16:01 [source]: ruby -r profile -e '1000.times { sleep 0.01 }' % cumulative self self total time seconds seconds calls ms/call ms/call name 206.67 0.03 0.03 1 31.00 31.00 Profiler__.start_profile 100.00 0.05 0.01 1000 0.01 0.01 Kernel.sleep 0.00 0.05 0.00 1 0.00 15.00 Integer#times 0.00 0.05 0.00 1 0.00 15.00 #toplevel Then if you iterate only once through any Enumerable then #each shows up as 1 call - which can be confusing. But it's completely logical since it's actually called only once. Just the block is invoked multiple times. So, assuming that you have a lot of stuff going on in a block, that time can be seen nowhere else than within the time of #each - there's no extra marker for the block. Of course you'll see times of methods that are called from the block on rows of their own. Another example with ungarbled percent values: 15:22:48 [source]: ruby -r profile -e '100.times { i=0; i+=1 while i < 1000 }' % cumulative self self total time seconds seconds calls ms/call ms/call name 59.89 15.11 15.11 1 15113.00 25234.00 Integer#times 20.83 20.37 5.26 100000 0.05 0.05 Fixnum#+ 19.28 25.23 4.87 100100 0.05 0.05 Fixnum#< 0.12 25.27 0.03 1 31.00 31.00 Profiler__.start_profile 0.00 25.27 0.00 1 0.00 25234.00 #toplevel Kind regards robert