# Ruby -r profile gives wrong percentage? **URL:** \ **Category:** Ruby\ **Created:** [December 20, 2005, 4:30pm UTC](https://www.ruby-forum.com/t/ruby-r-profile-gives-wrong-percentage/73423 "2005-12-20T16:30:43Z")\ **Posts on this page:** 4\ **Page:** 1
**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\ **Post date:** [December 20, 2005, 4:30pm UTC](https://www.ruby-forum.com/t/ruby-r-profile-gives-wrong-percentage/73423/1 "2005-12-20T16:30:43Z")
I am using Windows, and I was testing the profiler with the simple sieve.rb program. I may not have a good understanding of Ruby’s profiler but It seems that it gives me wrong percentages… I guess it is due to the overhead of the profiler while the process is not too much cpu bound. However if it shows wrong percentages, to me it’s still a bug. So according to the output below, 100% of the time is gone with Profiler\_\_.start\_profile, while 51.61% is gone with Numeric#step. All this totaling 151.61%! Am I missing something? Thanks in advance. I am such a newbie 🙂 JC C:\code\ruby\>ruby -r profile sieve.rb 2, 3, 5, 7, 11, 13, 17, 19, 23, 29, 31, 37, 41, 43, 47, 53, 59, 61, 67, 71, 73, 79, 83, 89, 97 % cumulative self self total time seconds seconds calls ms/call ms/call name 100.00 0.03 0.03 1 31.00 31.00 Profiler\_\_.start\_profile 51.61 0.05 0.02 4 4.00 4.00 Numeric#step 0.00 0.05 0.00 1 0.00 0.00 Kernel.Integer 0.00 0.05 0.00 2 0.00 8.00 Range#each 0.00 0.05 0.00 1 0.00 31.00 #toplevel 0.00 0.05 0.00 9 0.00 0.00 Array#[] 0.00 0.05 0.00 2 0.00 0.00 IO#write 0.00 0.05 0.00 26 0.00 0.00 Kernel.respond\_to? 0.00 0.05 0.00 8 0.00 0.00 Integer#succ 0.00 0.05 0.00 4 0.00 0.00 Fixnum#\* 0.00 0.05 0.00 10 0.00 0.00 Float#\<=\> 0.00 0.05 0.00 1 0.00 0.00 Kernel.puts 0.00 0.05 0.00 25 0.00 0.00 Fixnum#to\_s 0.00 0.05 0.00 10 0.00 0.00 Float#coerce 0.00 0.05 0.00 1 0.00 0.00 Array#shift 0.00 0.05 0.00 1 0.00 0.00 Array#compact 0.00 0.05 0.00 4 0.00 0.00 Fixnum#== 0.00 0.05 0.00 10 0.00 0.00 Fixnum#\<=\> 0.00 0.05 0.00 1 0.00 0.00 Array#join 0.00 0.05 0.00 1 0.00 0.00 Math.sqrt 0.00 0.05 0.00 203 0.00 0.00 Array#[]= ---
**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\ **Post date:** [December 20, 2005, 5:18pm UTC](https://www.ruby-forum.com/t/ruby-r-profile-gives-wrong-percentage/73423/2 "2005-12-20T17:18:54Z")
removed\_email\_address@domain.invalid wrote: > this totaling 151.61%! > Am I missing something? Yes. Some figures are cumulative. This confused me in the beginning, too. I guess the rest of the confusion is caused by rounding errors - your figures are quite smallish. HTH > Thanks in advance. I am such a newbie 🙂 JC We all were once. 🙂 Kind regards ``` robert ``` ---
**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\ **Post date:** [December 20, 2005, 8:23pm UTC](https://www.ruby-forum.com/t/ruby-r-profile-gives-wrong-percentage/73423/3 "2005-12-20T20:23:33Z")
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On 2005.12.21 01:17, “Robert K.” [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) wrote: > > Profiler\_\_.start\_profile, while 51.61% is gone with Numeric#step. All > > this totaling 151.61%! > > Am I missing something? > > Yes. Some figures are cumulative. This confused me in the beginning, > too. I guess the rest of the confusion is caused by rounding errors - > your figures are quite smallish. HTH Specifically it is taking nesting of method calls into account. It is basically telling you this: # Quite pseudo here def Profiler\_\_.start\_profile() loop { foo(bar); Numeric.step(); bar(baz) + quux; } end So, you are spending all of your time inside start\_profile() because everything else is executing while you are inside that method. If you just did this: def foo() 5000.times { puts ‘foo!’ } end foo You would see Kernel.puts consuming x amount, Integer#times consuming the total amount of all Kernel.puts calls plus its own overhead and foo consuming the amount of all Integer#times plus its own overhead. foo should come up to 100% (more or less). > > Thanks in advance. I am such a newbie 🙂 JC > > We all were once. 🙂 > > Kind regards > > ``` > robert > > ``` E -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.1 (GNU/Linux) iD8DBQFDqGLPxvA1l6h+MUMRAn94AKCO4pKbgCYw8ufjeHxOIlreachskQCfX9ao iLH8VP2v5roGX6DkSUWKvFY= =if5t -----END PGP SIGNATURE----- ---
**Author:** ![unknown](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/u/4bbf92/32.png) [@unknown](https://www.ruby-forum.com/u/unknown)\ **Post date:** [December 21, 2005, 11:08am UTC](https://www.ruby-forum.com/t/ruby-r-profile-gives-wrong-percentage/73423/4 "2005-12-21T11:08:59Z")
Eero S. wrote: > > > overhead of the profiler while the process is not too much cpu > > > rounding errors - your figures are quite smallish. HTH > > > because everything else is executing while you are inside that > > > own overhead and foo consuming the amount of all Integer#times > > > plus its own overhead. foo should come up to 100% (more or less). Sample: ruby -r profile -e ‘def foo() 5000.times { puts “x” } end; foo’ x … % cumulative self self total time seconds seconds calls ms/call ms/call name 54.21 1.48 1.48 5000 0.30 0.48 Kernel.puts 27.94 2.25 0.76 10000 0.08 0.08 IO#write 12.69 2.59 0.35 1 347.00 2734.00 Integer#times 5.16 2.73 0.14 5000 0.03 0.03 Kernel.respond\_to? 0.00 2.73 0.00 1 0.00 0.00 Module#method\_added 0.00 2.73 0.00 1 0.00 2734.00 Object#foo 0.00 2.73 0.00 1 0.00 2734.00 #toplevel First column is percentage of “self seconds”. “cumulative seconds” is the sum of all “self seconds” up to that line. “self seconds” is the time spent in a method while “total” includes methods invoked from there. Kind regards ``` robert ```