From d8bb5e73c7060a2c520be1d6df77a7cbfe8648e6 Mon Sep 17 00:00:00 2001 From: Mike Blumtritt Date: Wed, 29 May 2024 19:19:10 +0000 Subject: [PATCH] Next Version: v1.1.0 (#5) - add timer support - tidy-up - bump version to v1.1.0 --- README.md | 4 +- Rakefile | 4 +- examples/foo.rb | 2 +- examples/timer.rb | 29 ++++++ lib/im-lost.rb | 199 ++++++++++++++++++++++++++++++----- lib/im-lost/version.rb | 2 +- spec/helper.rb | 10 +- spec/lib/im-lost_spec.rb | 218 ++++++++++++++++++++++----------------- 8 files changed, 338 insertions(+), 130 deletions(-) create mode 100644 examples/timer.rb diff --git a/README.md b/README.md index b03b051..e344541 100644 --- a/README.md +++ b/README.md @@ -19,6 +19,7 @@ File.open('test.txt', 'w') do |file| file.puts(:world!) end end + # output will look like # > IO#<<(?) # /projects/test.rb:1 @@ -38,6 +39,7 @@ ImLost.trace_exceptions do rescue SystemCallError raise('something went wrong!') end + # output will look like # x Errno::EEXIST: File exists @ rb_sysopen - / # /projects/test.rb:2 @@ -47,7 +49,7 @@ end # /projects/test.rb:4 ``` -When you like to know if and when a code point is reached, `ImLost.here` will help: +When you like to know if a code point is reached, `ImLost.here` will help: ```ruby ImLost.here diff --git a/Rakefile b/Rakefile index 0fe247e..5edd7d2 100644 --- a/Rakefile +++ b/Rakefile @@ -15,6 +15,6 @@ CLOBBER << 'doc' YARD::Rake::YardocTask.new(:doc) { _1.stats_options = %w[--list-undoc] } desc 'Run YARD development server' -task('doc:dev' => :clobber) { exec('yard server --reload') } +task('doc:dev' => :clobber) { exec 'yard server --reload' } -task(:default) { exec('rake --tasks') } +task(:default) { exec 'rake --tasks' } diff --git a/examples/foo.rb b/examples/foo.rb index 27009aa..ac21211 100644 --- a/examples/foo.rb +++ b/examples/foo.rb @@ -1,6 +1,6 @@ # frozen_string_literal: true -require_relative '../lib/im-lost' +require 'im-lost' class Foo def self.create(value:) = new(value) diff --git a/examples/timer.rb b/examples/timer.rb new file mode 100644 index 0000000..f18fa9f --- /dev/null +++ b/examples/timer.rb @@ -0,0 +1,29 @@ +# frozen_string_literal: true + +puts <<~INFO + + This is an example how to use named and anonymous timers. + +INFO + +require_relative '../lib/im-lost' + +puts 'Create a named timer:' +ImLost.timer.create(:first) + +puts 'Create an anonymous timer:' +second = ImLost.timer.create + +sleep(0.5) # or whatever + +puts 'print runtime for named timer:' +ImLost.timer[:first] + +puts 'print runtime for anonymous timer:' +ImLost.timer[second] + +puts 'delete a named timer' +ImLost.timer.delete(:first) + +puts 'delete an anonymous timer' +ImLost.timer.delete(second) diff --git a/lib/im-lost.rb b/lib/im-lost.rb index 0db728e..3806d2c 100644 --- a/lib/im-lost.rb +++ b/lib/im-lost.rb @@ -1,5 +1,6 @@ # frozen_string_literal: true +# # If you have overlooked something again and don't really understand what your # code is doing. If you have to maintain this application but can't really find # your way around and certainly can't track down that stupid error. If you feel @@ -53,6 +54,12 @@ def output=(value) raise(ArgumentError, "invalid output device - #{value.inspect}") end + # + # @return [TimerStore] the timer store used to estimate the runtime of + # your code + # + attr_reader :timer + # # Enables/disables tracing of method calls. # This is enabled by default. @@ -79,6 +86,7 @@ def trace_calls=(value) # rescue SystemCallError # raise('something went wrong!') # end + # # # output will look like # # x Errno::EEXIST: File exists @ rb_sysopen - / # # /projects/test.rb:2 @@ -170,15 +178,16 @@ def here(test = true) # file.puts(:world!) # end # end - # output will look like - # > IO#<<(?) - # /projects/test.rb:1 - # > IO#write(*) - # /projects/test.rb:1 - # > IO#puts(*) - # /projects/test.rb:2 - # > IO#write(*) - # /projects/test.rb:2 + # + # # output will look like + # # > IO#<<(?) + # # /projects/test.rb:1 + # # > IO#write(*) + # # /projects/test.rb:1 + # # > IO#puts(*) + # # /projects/test.rb:2 + # # > IO#write(*) + # # /projects/test.rb:2 # # @overload trace(*args) # @param args [[Object]] one or more objects to be traced @@ -187,7 +196,6 @@ def here(test = true) # @see untrace # @see untrace_all! # - # # @overload trace(*args) # @param args [[Object]] one or more objects to be traced # @yieldparam args [Object] the traced object(s) @@ -257,7 +265,7 @@ def vars(object) @trace[traced] = traced if traced end - protected + private def as_sig(prefix, info, args) args = args.join(', ') @@ -269,8 +277,6 @@ def as_sig(prefix, info, args) end end - private - def _trace(arg) id = arg.__id__ @trace[id] = id if __id__ != id && @output.__id__ != id @@ -312,11 +318,11 @@ def _vars(obj, location) vars = obj.instance_variables if vars.empty? @output.puts(' ') - else - @output.puts(' instance variables:') - vars.sort!.each do |name| - @output.puts(" #{name}: #{obj.instance_variable_get(name).inspect}") - end + return obj + end + @output.puts(' instance variables:') + vars.sort!.each do |name| + @output.puts(" #{name}: #{obj.instance_variable_get(name).inspect}") end obj end @@ -326,16 +332,150 @@ def _local_vars(binding) vars = binding.local_variables if vars.empty? @output.puts(' ') - else - @output.puts(' local variables:') - vars.sort!.each do |name| - @output.puts(" #{name}: #{binding.local_variable_get(name).inspect}") - end + return self + end + @output.puts(' local variables:') + vars.sort!.each do |name| + @output.puts(" #{name}: #{binding.local_variable_get(name).inspect}") end self end end + # + # A store to create and register timers you can use to estimate the runtime of + # some code. + # + # All timers are identified by an unique ID or a name. + # + # @example Use a named timer + # ImLost.timer.create('my_test') + # + # # ...your code here... + # + # ImLost.timer['my_test'] + # # => prints the timer name, this location and runtime so far + # + # # ...more code here... + # + # ImLost.timer['my_test'] + # # => prints the timer name, this location and runtime since the timer was created + # + # ImLost.timer.delete('my_test') + # # the timer with name 'my_test' is not longer valid now + # + # + # @example Use an anonymous timer (identified by ID) + # tmr = ImLost.timer.create + # + # # ...your code here... + # + # ImLost.timer[tmr] + # # => prints the timer ID, this location and runtime so far + # + # # ...more code here... + # + # ImLost.timer[tmr] + # # => prints the timer ID, this location and runtime since the timer was created + # + # ImLost.timer.delete(tmr) + # # the timer with the ID `tmr` is not longer valid now + # + # @see ImLost.timer + # + class TimerStore + if defined?(Process::CLOCK_MONOTONIC) + # @return [Float] current time + def self.now = Process.clock_gettime(Process::CLOCK_MONOTONIC) + else + # @return [Float] current time + def self.now = ::Time.now + end + + # @attribute [r] count + # @return [Integer] the number of registered timers + def count = ids.size + + # @attribute [r] empty? + # @return [Boolean] wheter the timer store is empty or not + def empty? = ids.empty? + + # @attribute [r] ids + # @return [Array] IDs of all registered timers + def ids = (@ll.keys.keep_if { _1.is_a?(Integer) }) + + # + # Create and register a new named or anonymous timer. + # It print the ID or name of the created timer and includes the location. + # + # @param name [#to_s] optional timer name + # @return [Integer] timer ID + # + def create(name = nil) + timer = [] + @ll[id = timer.__id__] = timer + name ? @ll[name = name.to_s] = timer : name = id + @cb[name, Kernel.caller_locations(1, 1)[0]] + timer << name << self.class.now + id + end + + # + # Delete and unregister timers. + # + # @param id_or_names [Array] the IDs or the names + # @return [nil] + # + def delete(*id_or_names) + id_or_names.flatten.each do |id| + if id.is_a?(Integer) + del = @ll.delete(id) + @ll.delete(del[0]) if del + else + del = @ll.delete(id.to_s) + @ll.delete(del.__id__) if del + end + end + nil + end + + # + # Print the ID or name and the runtime since timer was created. + # It includes the location. + # + # @param id_or_name [Integer, #to_s] the identifier or the name of the timer + # @return [Integer] timer ID + # @raise [ArgumentError] when the given id or name is not a registered timer + # identifier or name + # + def [](id_or_name) + time = self.class.now + timer = @ll[id_or_name.is_a?(Integer) ? id_or_name : id_or_name.to_s] + raise(ArgumentError, "not a timer - #{id_or_name.inspect}") unless timer + @cb[timer[0], Kernel.caller_locations(1, 1)[0], time - timer[1]] + timer.__id__ + end + + # + # Print the ID or name and the runtime of all active timers. + # It includes the location. + # + # @return [nil] + # + def all + now = self.class.now + loc = Kernel.caller_locations(1, 1)[0] + @ll.values.uniq.reverse_each { |name, start| @cb[name, loc, now - start] } + nil + end + + # @!visibility private + def initialize(&block) + @cb = block + @ll = {} + end + end + ARG_SIG = { rest: '*', keyrest: '**', block: '&' }.compare_by_identity.freeze NO_NAME = { :* => 1, :** => 1, :& => 1 }.compare_by_identity.freeze private_constant :ARG_SIG, :NO_NAME @@ -344,6 +484,15 @@ def _local_vars(binding) @caller_locations = true @output = $stderr.respond_to?(:puts) ? $stderr : STDERR + @timer = + TimerStore.new do |title, location, time| + @output.puts( + "T #{title}: #{time ? "#{time} sec." : 'created'}", + " #{location.path}:#{location.lineno}" + ) + end + TimerStore.private_class_method(:new) + @trace_calls = [ TracePoint.new(:c_call) do |tp| next if !@trace.key?(tp.self.__id__) || tp.path == __FILE__ @@ -383,7 +532,7 @@ def _local_vars(binding) '<', tp, tp.parameters.map do |kind, name| - next name if %i[* ** &].include?(name) + next name if NO_NAME.key?(name) "#{ARG_SIG[kind]}#{ctx.local_variable_get(name).inspect}" end ) @@ -392,7 +541,7 @@ def _local_vars(binding) end ] - supported = RUBY_VERSION >= '3.3.0' ? %i[raise rescue] : %i[raise] + supported = RUBY_VERSION.to_f < 3.3 ? %i[raise] : %i[raise rescue] @trace_exceptions = TracePoint.new(*supported) do |tp| ex = tp.raised_exception.inspect diff --git a/lib/im-lost/version.rb b/lib/im-lost/version.rb index 7a01a3e..a472847 100644 --- a/lib/im-lost/version.rb +++ b/lib/im-lost/version.rb @@ -2,5 +2,5 @@ module ImLost # The version number of the gem. - VERSION = '1.0.2' + VERSION = '1.1.0' end diff --git a/spec/helper.rb b/spec/helper.rb index ce1d2fe..5d85f55 100644 --- a/spec/helper.rb +++ b/spec/helper.rb @@ -1,7 +1,11 @@ # frozen_string_literal: true -require 'stringio' -require_relative '../lib/im-lost' - $stdout.sync = $stderr.sync = $VERBOSE = true + RSpec.configure(&:disable_monkey_patching!) + +require 'stringio' + +RE_FLOAT = '[-+]?[0-9]*\.?[0-9]+([eE][-+]?[0-9]+)?' + +require_relative '../lib/im-lost' diff --git a/spec/lib/im-lost_spec.rb b/spec/lib/im-lost_spec.rb index 26ae900..9f7583a 100644 --- a/spec/lib/im-lost_spec.rb +++ b/spec/lib/im-lost_spec.rb @@ -25,10 +25,8 @@ def bar = :bar let(:sample) { TestSample.new } let(:output) { ImLost.output.string } - before do - ImLost.output = StringIO.new - ImLost.untrace_all! - end + before { ImLost.output = StringIO.new } + after { ImLost.untrace_all! } it 'has defined default attributes' do is_expected.to have_attributes( @@ -99,19 +97,15 @@ def bar = :bar expect(output).to eq "> TestSample#insp(**{})\n" end - if RUBY_VERSION < '3.1.0' - it 'handles argument forwarding' do - sample.fwd(40, 2) + it 'handles argument forwarding' do + sample.fwd(40, 2) + if RUBY_VERSION.to_f < 3.1 expect(output).to eq <<~OUTPUT > TestSample#fwd(*, &) > TestSample#add(40, 2) OUTPUT - end - else - it 'handles argument forwarding' do - sample.fwd(40, 2) - + else expect(output).to eq <<~OUTPUT > TestSample#fwd(*, **, &) > TestSample#add(40, 2) @@ -206,21 +200,17 @@ def bar = :bar expect(output).to eq "< TestSample#insp(**{})\n = \"{}\"\n" end - if RUBY_VERSION < '3.1.0' - it 'handles argument forwarding' do - sample.fwd(40, 2) + it 'handles argument forwarding' do + sample.fwd(40, 2) + if RUBY_VERSION.to_f < 3.1 expect(output).to eq <<~OUTPUT < TestSample#add(40, 2) = 42 < TestSample#fwd(*, &) = 42 OUTPUT - end - else - it 'handles argument forwarding' do - sample.fwd(40, 2) - + else expect(output).to eq <<~OUTPUT < TestSample#add(40, 2) = 42 @@ -240,111 +230,83 @@ def bar = :bar end end - if RUBY_VERSION >= '3.3.0' - context '.trace_exceptions' do - it 'traces exceptions and rescue blocks' do - ImLost.trace_exceptions do - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end + context '.trace_exceptions' do + it 'traces exceptions and rescue blocks' do + raise_location = "#{__FILE__}:#{__LINE__ + 4}" + rescue_location = "#{__FILE__}:#{__LINE__ + 4}" + + ImLost.trace_exceptions do + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + if RUBY_VERSION.to_f < 3.3 expect(output).to eq <<~OUTPUT x ArgumentError: not the answer - 21 - #{__FILE__}:#{__LINE__ - 7} - ! ArgumentError: not the answer - 21 - #{__FILE__}:#{__LINE__ - 8} + #{raise_location} OUTPUT - end - - it 'allows to disable location information' do - ImLost.trace_exceptions(with_locations: false) do - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - + else expect(output).to eq <<~OUTPUT x ArgumentError: not the answer - 21 + #{raise_location} ! ArgumentError: not the answer - 21 + #{rescue_location} OUTPUT end + end - it 'allows to be stacked' do - ImLost.trace_exceptions(with_locations: false) do - ImLost.trace_exceptions(with_locations: true) do - raise(ArgumentError, 'not the answer - 42') - rescue ArgumentError - # nop - end - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - begin - raise(NotImplementedError) - rescue NotImplementedError - # nop - end + it 'allows to disable location information' do + ImLost.trace_exceptions(with_locations: false) do + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + if RUBY_VERSION.to_f < 3.3 + expect(output).to eq "x ArgumentError: not the answer - 21\n" + else expect(output).to eq <<~OUTPUT - x ArgumentError: not the answer - 42 - #{__FILE__}:#{__LINE__ - 16} - ! ArgumentError: not the answer - 42 - #{__FILE__}:#{__LINE__ - 17} x ArgumentError: not the answer - 21 ! ArgumentError: not the answer - 21 OUTPUT end end - end - if RUBY_VERSION < '3.3.0' - context '.trace_exceptions' do - it 'traces exceptions and rescue blocks' do - ImLost.trace_exceptions do - raise(ArgumentError, 'not the answer - 21') + it 'allows to be stacked' do + raise_location = "#{__FILE__}:#{__LINE__ + 5}" + rescue_location = "#{__FILE__}:#{__LINE__ + 5}" + + ImLost.trace_exceptions(with_locations: false) do + ImLost.trace_exceptions(with_locations: true) do + raise(ArgumentError, 'not the answer - 42') rescue ArgumentError # nop end + raise(ArgumentError, 'not the answer - 21') + rescue ArgumentError + # nop + end + begin + raise(NotImplementedError) + rescue NotImplementedError + # nop + end + if RUBY_VERSION.to_f < 3.3 expect(output).to eq <<~OUTPUT + x ArgumentError: not the answer - 42 + #{raise_location} x ArgumentError: not the answer - 21 - #{__FILE__}:#{__LINE__ - 7} OUTPUT - end - - it 'allows to disable location information' do - ImLost.trace_exceptions(with_locations: false) do - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - - expect(output).to eq "x ArgumentError: not the answer - 21\n" - end - - it 'allows to be stacked' do - ImLost.trace_exceptions(with_locations: false) do - ImLost.trace_exceptions(with_locations: true) do - raise(ArgumentError, 'not the answer - 42') - rescue ArgumentError - # nop - end - raise(ArgumentError, 'not the answer - 21') - rescue ArgumentError - # nop - end - begin - raise(NotImplementedError) - rescue NotImplementedError - # nop - end - + else expect(output).to eq <<~OUTPUT x ArgumentError: not the answer - 42 - #{__FILE__}:#{__LINE__ - 16} + #{raise_location} + ! ArgumentError: not the answer - 42 + #{rescue_location} x ArgumentError: not the answer - 21 + ! ArgumentError: not the answer - 21 OUTPUT end end @@ -419,4 +381,66 @@ def bar = :bar end end end + + context '.timer' do + after { ImLost.timer.delete(ImLost.timer.ids) } + + it 'supports attributes #count, #empty?, #ids' do + expect(ImLost.timer).to have_attributes(count: 0, empty?: true, ids: []) + + ids = 5.times.map { ImLost.timer.create } + + expect(ImLost.timer).to have_attributes( + count: ids.size, + empty?: false, + ids: ids + ) + end + + it 'prints information when an anonymous timer is created' do + id = ImLost.timer.create + + expect(output).to eq "T #{id}: created\n #{__FILE__}:#{__LINE__ - 2}\n" + end + + it 'prints information when a named timer is created' do + ImLost.timer.create(:tt1) + + expect(output).to eq "T tt1: created\n #{__FILE__}:#{__LINE__ - 2}\n" + end + + it 'prints runtime information for an anonymous timer' do + id = ImLost.timer.create + ImLost.output = StringIO.new # reset output + ImLost.timer[id] + location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") + + expect(output).to match(/\AT #{id}: #{RE_FLOAT} sec.\n #{location}\n\z/) + end + + it 'prints runtime information for a named timer' do + ImLost.timer.create(:tt2) + ImLost.output = StringIO.new # reset output + ImLost.timer[:tt2] + location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") + + expect(output).to match(/\AT tt2: #{RE_FLOAT} sec.\n #{location}\n\z/) + end + + context '.timer#all' do + it 'prints the runtime of all timers' do + ImLost.timer.create(:first) + second = ImLost.timer.create + ImLost.output = StringIO.new # reset output + + ImLost.timer.all + location = Regexp.escape("#{__FILE__}:#{__LINE__ - 1}") + + expect(output).to match( + /\AT #{second}: #{RE_FLOAT} sec.\n #{location}\n(?# + )T first: #{RE_FLOAT} sec.\n #{location}\n\z/ + ) + end + end + end end