@@ -62,6 +62,24 @@ def hitimes_duration_t3 end # +# Check out the speed of the TimedValueMetric too +# +def hitimes_duration_tv1 + Hitimes::TimedValueMetric.now( 'duration_tv1' ).stop( 42 ) +end + +HTV2 = Hitimes::TimedValueMetric.new( 'duration_tv2' ) +def hitimes_duration_tv2 + HTV2.start + HTV2.stop( 42 ) +end + +HTV3 = Hitimes::TimedValueMetric.new( 'duration_tv3' ) +def hitimes_duration_tv3 + HTV3.measure( 42 ) { nil } +end + +# # use the Struct::Tms values and return the difference in User time between 2 # successive calls # @@ -82,11 +100,14 @@ end puts "Testing time sampling 100,000 times" bm(30) do |x| - x.report("Process") { 100_000.times { process_duration } } - x.report("Time") { 100_000.times { time_duration } } - x.report("Hitimes::TimedMetric 1") { 100_000.times { hitimes_duration_t1 } } - x.report("Hitimes::TimedMetric 2") { 100_000.times { hitimes_duration_t2 } } - x.report("Hitimes::TimedMetric 3") { 100_000.times { hitimes_duration_t3 } } - x.report("Hitimes::Interval 1") { 100_000.times { hitimes_duration_i1 } } - x.report("Hitimes::Interval 2") { 100_000.times { hitimes_duration_i2 } } + x.report("Process") { 100_000.times { process_duration } } + x.report("Time") { 100_000.times { time_duration } } + x.report("Hitimes::TimedMetric 1") { 100_000.times { hitimes_duration_t1 } } + x.report("Hitimes::TimedMetric 2") { 100_000.times { hitimes_duration_t2 } } + x.report("Hitimes::TimedMetric 3") { 100_000.times { hitimes_duration_t3 } } + x.report("Hitimes::Interval 1") { 100_000.times { hitimes_duration_i1 } } + x.report("Hitimes::Interval 2") { 100_000.times { hitimes_duration_i2 } } + x.report("Hitimes::TimedValueMetric 1") { 100_000.times { hitimes_duration_tv1 } } + x.report("Hitimes::TimedValueMetric 2") { 100_000.times { hitimes_duration_tv2 } } + x.report("Hitimes::TimedValueMetric 3") { 100_000.times { hitimes_duration_tv3 } } end examples/benchmarks.rb @@ -16,13 +16,8 @@ module Hitimes # class Metric - # the time at which the first sample was taken - # This is the number of microseconds since UNIX epoch UTC as a Float - attr_accessor :sampling_start_time - - # the time at which the last sample was taken. - # This is the number of microseconds since UNIX epoch UTC as a Float - attr_accessor :sampling_stop_time + # the number of seconds as a float since the sampling_start_time + attr_reader :sampling_delta # An additional hash of data to associate with the metric attr_reader :additional_data @@ -41,13 +36,56 @@ module Hitimes # +name+ may be anything that follows the +to_s+ protocol. # def initialize( name, additional_data = {} ) - @sampling_start_time = nil - @sampling_stop_time = nil + @sampling_start_time = nil + @sampling_start_interval = nil + @sampling_delta = 0 + @name = name.to_s @additional_data = additional_data.to_hash end # + # :call-seq: + # metric.sampling_start_time -> Float or nil + # + # The time at which the first sample was taken. + # This is the number of microseconds since UNIX epoch UTC as a Float + # + # If the metric has not started measuring then the start time is nil. + # + def sampling_start_time + if @sampling_start_interval then + @sampling_start_time ||= self.utc_microseconds() + else + nil + end + end + + # + # :call-seq: + # metric.sampling_stop_time -> Float or nil + # + # The time at which the last sample was taken + # This is the number of microseconds since UNIX epoch UTC as a Float + # + # If the metric has not completely measured at least one thing then + # stop time is nil. + # + # Because accessing the actual 'time of day' is an expesive operation, we + # only get the time of day at the beginning of the first measurement and we + # keep track of the offset from that point in @sampling_delta. + # + # When sampling_stop_time is called, the actual time of day is caculated. + # + def sampling_stop_time + if @sampling_delta > 0 then + (self.sampling_start_time + (@sampling_delta * 1_000_000)) + else + nil + end + end + + # # :call-seq: # metric.to_hash -> Hash # metric.to_hash lib/hitimes/metric.rb @@ -60,17 +60,7 @@ module Hitimes def initialize( name, additional_data = {} ) super( name, additional_data ) @stats = Stats.new - @current_interval = nil - end - - # - # :call-seq: - # timed_metric.current_interval -> Interval - # - # Return the current interval, if one doesn't exist create one. - # - def current_interval - @current_interval ||= Interval.new + @current_interval = Interval.new end # @@ -80,7 +70,7 @@ module Hitimes # return whether or not the timer is currently running. # def running? - current_interval.running? + @current_interval.running? end # @@ -91,8 +81,11 @@ module Hitimes # this is a noop. # def start - current_interval.start unless running? - @sampling_start_time ||= self.utc_microseconds() + if not @current_interval.running? then + @current_interval.start + @sampling_start_time ||= self.utc_microseconds() + @sampling_start_interval ||= Interval.now + end nil end @@ -106,11 +99,14 @@ module Hitimes # no stats are updated. # def stop - if running? then - d = current_interval.stop - @current_interval = nil - @sampling_stop_time = self.utc_microseconds() + if @current_interval.running? then + d = @current_interval.stop @stats.update( d ) + @current_interval = Interval.new + + # update the length of time we have been sampling + @sampling_delta = @sampling_start_interval.duration_so_far + return d end return false @@ -148,9 +144,9 @@ module Hitimes # happens and false is returned. # def split - if running? then - next_interval = current_interval.split - d = current_interval.duration + if @current_interval.running? then + next_interval = @current_interval.split + d = @current_interval.duration @stats.update( d ) @current_interval = next_interval return d lib/hitimes/timed_metric.rb @@ -59,30 +59,19 @@ module Hitimes # def initialize( name, additional_data = {} ) super( name, additional_data ) - @current_interval = nil @timed_stats = Stats.new @value_stats = Stats.new + @current_interval = Interval.new end # # :call-seq: - # timed_value_metric.current_interval -> Interval - # - # Return the current interval, if one doesn't exist create one. - # - def current_interval - @current_interval ||= Interval.new - end - - - # - # :call-seq: # timed_value_metric.running? -> true or false # # return whether or not the metric is currently timing something. # def running? - current_interval.running? + @current_interval.running? end # @@ -93,8 +82,11 @@ module Hitimes # this is a noop. # def start - current_interval.start unless running? - @sampling_start_time ||= self.utc_microseconds() + if not @current_interval.running? then + @current_interval.start + @sampling_start_time ||= self.utc_microseconds() + @sampling_start_interval ||= Interval.now + end nil end @@ -114,12 +106,15 @@ module Hitimes # # def stop( value ) - if running? then - d = current_interval.stop - @current_interval = nil - @sampling_stop_time = self.utc_microseconds() + if @current_interval.running? then + d = @current_interval.stop @timed_stats.update( d ) + @current_interval = Interval.new @value_stats.update( value ) + + # update the lenght of time we have been sampling + @sampling_delta = @sampling_start_interval.duration_so_far + return d end return false @@ -159,9 +154,9 @@ module Hitimes # # def split( value ) - if running? then - next_interval = current_interval.split - d = current_interval.duration + if @current_interval.running? then + next_interval = @current_interval.split + d = @current_interval.duration @timed_stats.update( d ) @value_stats.update( value ) @current_interval = next_interval lib/hitimes/timed_value_metric.rb @@ -42,10 +42,13 @@ module Hitimes # Give the +value+ as the measurement to the metric. The value is returned # def measure( value ) - now = self.utc_microseconds() - @sampling_start_time ||= now - @sampling_stop_time = now + @sampling_start_time ||= self.utc_microseconds() + @sampling_start_interval ||= Interval.now + @stats.update( value ) + + # update the length of time we have been sampling + @sampling_delta = @sampling_start_interval.duration_so_far end # lib/hitimes/value_metric.rb @@ -95,9 +95,9 @@ describe Hitimes::TimedMetric do end it "keeps track of the last stop time of all the intervals" do - f1 = Time.now.gmtime.to_f * 1000000 + f1 = Time.now.gmtime.to_f * 1_000_000 5.times { @tm.start ; sleep 0.05 ; @tm.stop } - f2 = Time.now.gmtime.to_f * 1000000 + f2 = Time.now.gmtime.to_f * 1_000_000 @tm.sampling_stop_time.should > f1 @tm.sampling_stop_time.should < f2 # distance from now to max stop time time should be less than the distance @@ -131,7 +131,7 @@ describe Hitimes::TimedMetric do h['name'].should == "test-timed-metric" end - it "has an empty has for additional_data" do + it "has an empty hash for additional_data" do h = @tm.to_hash h['additional_data'].should == Hash.new h['additional_data'].size.should == 0 spec/timed_metric_spec.rb d05db04138bf95ed926d21b841545e4149f8dbf5 Jeremy Hinegardner jeremy@hinegardner.org http://github.com/copiousfreetime/hitimes/commit/cab640b8147797889e99ea6ed044b9a351e3b616 cab640b8147797889e99ea6ed044b9a351e3b616 2009-06-12T23:01:59-07:00 2009-06-12T23:01:59-07:00 Performance pass - remove unnecessary method calls - refactor getting the stop time into a start + delta 30c84f1ee5cb84d79f50950b2c7fe48bf38cc147 Jeremy Hinegardner jeremy@hinegardner.org