-2

Attempting to profile the difference in runtime between "1+1" and "1x2" using Ruby and the gem ruby-prof.

Install the gem and hacked together some code that appears to work, but does not give me the answer I'm looking for, that being the difference in runtime.

Is this possible, and if so, what code would give me this answer.


This code appears to work, but does not allow me to see a runtime difference.


require 'ruby-prof'

result = RubyProf.profile do
1+1
end
printer = RubyProf::GraphPrinter.new(result)

result = RubyProf.profile do
1x2
end
printer = RubyProf::GraphPrinter.new(result)

Which returns this in IRB


irb(main):001:0> require 'ruby-prof'
=> true
irb(main):002:0>
irb(main):003:0* result = RubyProf.profile do
irb(main):004:1* 1+1
irb(main):005:1> end
=> #<RubyProf::Result:0x11050c8>
irb(main):006:0> printer = RubyProf::GraphPrinter.new(result)
=> #<RubyProf::GraphPrinter:0x1332c18 @result=#<RubyProf::Result:0x11050c8>, @ou
tput=nil, @options={}, @thread_times={6793716=>0.01}>
irb(main):007:0>
irb(main):008:0* result = RubyProf.profile do
irb(main):009:1* 1x2
irb(main):010:1> end
SyntaxError: (irb):9: syntax error, unexpected tIDENTIFIER, expecting keyword_en
d
        from C:/Ruby193/bin/irb:12:in `<main>'
irb(main):011:0> printer = RubyProf::GraphPrinter.new(result)
=> #<RubyProf::GraphPrinter:0x1124310 @result=#<RubyProf::Result:0x11050c8>, @ou
tput=nil, @options={}, @thread_times={6793716=>0.01}>
irb(main):012:0>
Marc-André Lafortune
  • 78,216
  • 16
  • 166
  • 166
blunders
  • 3,619
  • 10
  • 43
  • 65

4 Answers4

3

1x2 means nothing in ruby. Use 1*2 instead.

EDIT: You must run the code more times as it is too fast to measure.

require 'ruby-prof'

prof1 = RubyProf.profile do
  10_000_000.times {1+1}
end

prof2 = RubyProf.profile do
  10_000_000.times {1*2}
end

RubyProf::GraphPrinter.new(prof1).print
RubyProf::GraphPrinter.new(prof2).print

Anyway I think the best way to do it is with Benchmark:

require 'benchmark'

Benchmark.bm do |x|
  x.report("1+1") {15_000_000.times {1+1}}
  x.report("1*2") {15_000_000.times {1*2}}
end

It gives me:

         user     system      total        real
1+1  2.386000   0.000000   2.386000 (  2.392529)
1*2  2.403000   0.000000   2.403000 (  2.413323)

Multiplication is just a bit slower. But the difference is too small to mean anything.

Guilherme Bernal
  • 8,183
  • 25
  • 43
  • +1 Thanks, updated the typo, ran the code, and there's no difference in the specs reported by ruby-prof as above. Those being "6793716=>0.01". Is 6793716 a thread-ID or time? Clearly if 0.01 is the time value I'm going to need a deeper measure of time, is that possible. Thanks! Cross-posting this commnt to all answers, since all pointed out the typo, but none provide code to give the answer. Again, thanks - finding the answer to this is important to me. – blunders Dec 02 '11 at 16:27
  • Thanks, confirmed the code is what I need. One thing to confirm is the gem you used is "gem install better-benchmark", correct, or no? – blunders Dec 02 '11 at 16:47
  • 1
    @blunders: No, `benchmark` is included in default ruby installation. Just require it. – Guilherme Bernal Dec 02 '11 at 16:51
  • What if the multiplication attempted was more time-consuming (like two large Fixnums that still give another Fixnum)? – Andrew Grimm Dec 04 '11 at 23:00
1

Multiplication is done with * not with x. This is why you get the syntax error on your second example.

Michael Kohl
  • 66,324
  • 14
  • 138
  • 158
  • +1 Thanks, updated the typo, ran the code, and there's no difference in the specs reported by ruby-prof as above. Those being "6793716=>0.01". Is 6793716 a thread-ID or time? Clearly if 0.01 is the time value I'm going to need a deeper measure of time, is that possible. Thanks! Cross-posting this commnt to all answers, since all pointed out the typo, but none provide code to give the answer. Again, thanks - finding the answer to this is important to me. – blunders Dec 02 '11 at 16:27
  • 1
    Can I ask why the answer is important you? You can go a long time in Ruby without having to worry about performance, and if that's the ultimate goal of your program, Ruby may not be the language of choice anyway. – Michael Kohl Dec 02 '11 at 17:56
  • +1 @Micheal Kohl: I agree, guessing that was the logic used by someone else to downvote the question; which I don't care about, since I got the answer I needed. As for why, I'm trying to learn Ruby and that's why I used it, the problem it's trying to address is cover in depth at this question: [method-of-modeling-problem-complexity](http://math.stackexchange.com/questions/86788/method-of-modeling-problem-complexity) – blunders Dec 02 '11 at 18:06
1

You want to use 1 * 2, not 1x2...

If any case, you won't get any noticeable difference. You will be measuring the time it takes Ruby to make a method call, as the operation itself will take negligible time compared to that.

Marc-André Lafortune
  • 78,216
  • 16
  • 166
  • 166
  • +1 Thanks, updated the typo, ran the code, and there's no difference in the specs reported by ruby-prof as above. Those being "6793716=>0.01". Is 6793716 a thread-ID or time? Clearly if 0.01 is the time value I'm going to need a deeper measure of time, is that possible. Thanks! Cross-posting this commnt to all answers, since all pointed out the typo, but none provide code to give the answer. Again, thanks - finding the answer to this is important to me. – blunders Dec 02 '11 at 16:28
1

Ruby prof only seems to give you time in 100th of seconds. These operations are faster than that and thus both operations will give you the same result.

require 'ruby-prof'
result = RubyProf.profile do
  1 + 1
end
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT)
result = RubyProf.profile do
  1 * 2
end
printer = RubyProf::GraphPrinter.new(result)
printer.print(STDOUT)

Gives :

Thread ID: 70218521201980
Total Time: 0.01

  %total   %self     total      self      wait     child            calls   Name
--------------------------------------------------------------------------------
 100.00% 100.00%      0.00      0.00      0.00      0.00                1     Global#[No method]


Thread ID: 70218521201980
Total Time: 0.01

  %total   %self     total      self      wait     child            calls   Name
--------------------------------------------------------------------------------
 100.00% 100.00%      0.00      0.00      0.00      0.00                1     Global#[No method]

Which is the same time. Perhaps using the built in Time you could get a better result. This gives the time in milliseconds :

  start = Time.now
  1 + 1
  puts (Time.now - start) * 1000


  start = Time.now
  1 * 2
  puts (Time.now - start) * 1000

They both average out to be the same. ie 1000th of a millisecond

Kassym Dorsel
  • 4,773
  • 1
  • 25
  • 52