Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

ActiveSupport::Notifications::Event#parent_of? is not reliable in environments with poor clock resolution. #5932

Closed
wants to merge 1 commit into
from
Jump to file or symbol
Failed to load files and symbols.
+66 −13
Split
@@ -8,20 +8,25 @@ class Instrumenter
def initialize(notifier)
@id = unique_id
@notifier = notifier
+ @entry_index = 0
+ @exit_index = 0
+ @stack_level = 0
end
# Instrument the given block by measuring the time taken to execute it
# and publish it. Notice that events get sent even if an error occurs
# in the passed-in block
def instrument(name, payload={})
started = Time.now
+ payload[:entry_index] = enter_instrumentation
begin
- yield
+ yield
rescue Exception => e
payload[:exception] = [e.class.name, e.message]
raise e
ensure
+ payload[:exit_index] = exit_instrumentation
@notifier.publish(name, started, Time.now, @id, payload)
end
end
@@ -30,6 +35,21 @@ def instrument(name, payload={})
def unique_id
SecureRandom.hex(10)
end
+
+ def enter_instrumentation
+ @stack_level += 1
+ @entry_index += 1
+ end
+
+ def exit_instrumentation
+ idx = @exit_index += 1
+ @stack_level -= 1
+ if @stack_level == 0
+ @entry_index = 0
+ @exit_index = 0
+ end
+ idx
+ end
end
class Event
@@ -46,7 +66,9 @@ def initialize(name, start, ending, transaction_id, payload)
def parent_of?(event)
start = (time - event.time) * 1000
- start <= 0 && (start + duration >= event.duration)
+ start <= 0 && (start + duration >= event.duration) &&
+ @payload[:entry_index] < event.payload[:entry_index] &&
+ @payload[:exit_index] > event.payload[:exit_index]
end
end
end
@@ -161,7 +161,7 @@ def test_instrument_yields_the_paylod_for_further_modification
assert_equal 2, instrument(:awesome) { |p| p[:result] = 1 + 1 }
assert_equal 1, @events.size
assert_equal :awesome, @events.first.name
- assert_equal Hash[:result => 2], @events.first.payload
+ assert_equal 2, @events.first.payload[:result]
end
def test_instrumenter_exposes_its_id
@@ -176,12 +176,12 @@ def test_nested_events_can_be_instrumented
assert_equal 1, @events.size
assert_equal :wot, @events.first.name
- assert_equal Hash[:payload => "child"], @events.first.payload
+ assert_equal "child", @events.first.payload[:payload]
end
assert_equal 2, @events.size
assert_equal :awesome, @events.last.name
- assert_equal Hash[:payload => "notifications"], @events.last.payload
+ assert_equal "notifications", @events.last.payload[:payload]
end
def test_instrument_publishes_when_exception_is_raised
@@ -194,15 +194,43 @@ def test_instrument_publishes_when_exception_is_raised
end
assert_equal 1, @events.size
- assert_equal Hash[:payload => "notifications",
- :exception => ["RuntimeError", "FAIL"]], @events.last.payload
+ assert_equal "notifications", @events.last.payload[:payload]
+ assert_equal ["RuntimeError", "FAIL"], @events.last.payload[:exception]
end
def test_event_is_pushed_even_without_block
instrument(:awesome, :payload => "notifications")
assert_equal 1, @events.size
assert_equal :awesome, @events.last.name
- assert_equal Hash[:payload => "notifications"], @events.last.payload
+ assert_equal "notifications", @events.last.payload[:payload]
+ end
+
+ def test_distinguish_between_siblings_and_children_with_low_clock_resolution
+ # In some virtualized non-realtime systems, clock resolution can
+ # degrade. We simulate this by returning the same time for the
+ # duration of the test.
+ Time.stubs(:now).returns(Time.utc(2009, 01, 01, 0, 0, 1))
+
+ instrument(:dad) do
+ instrument(:child) do
+ instrument(:grand_child) do
+ end
+ end
+ instrument(:sibling) do
+ end
+ end
+
+ assert_equal 4, @events.size
+ assert_equal([:grand_child, :child, :sibling, :dad],
+ @events.map(&:name))
+ assert(@events[1].parent_of?(@events[0]),
+ "#{@events[1].name} should be parent of #{@events[0].name}")
+ assert(@events[3].parent_of?(@events[1]),
+ "#{@events[3].name} should be parent of #{@events[1].name}")
+ assert(!@events[1].parent_of?(@events[2]),
+ "#{@events[1].name} should not be parent of #{@events[2].name}")
+ assert(!@events.first.parent_of?(@events.last),
+ "#{@events[0].name} should not be parent of #{@events[3].name}")
end
end
@@ -218,15 +246,18 @@ def test_events_are_initialized_with_details
def test_events_consumes_information_given_as_payload
event = event(:foo, Time.now, Time.now + 1, random_id, :payload => :bar)
- assert_equal Hash[:payload => :bar], event.payload
+ assert_equal :bar, event.payload[:payload]
end
- def test_event_is_parent_based_on_time_frame
+ def test_event_is_parent_based_on_time_frame_and_entry_index
time = Time.utc(2009, 01, 01, 0, 0, 1)
- parent = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id, {})
- child = event(:foo, time, time + 10, random_id, {})
- not_child = event(:foo, time, time + 100, random_id, {})
+ parent = event(:foo, Time.utc(2009), Time.utc(2009) + 100, random_id,
+ {:entry_index => 0, :exit_index => 2})
+ child = event(:foo, time, time + 10, random_id,
+ {:entry_index => 1, :exit_index => 0})
+ not_child = event(:foo, time, time + 100, random_id,
+ {:entry_index => 2, :exit_index => 1})
assert parent.parent_of?(child)
assert !child.parent_of?(parent)