This is a demo of a thread-safety issue with ActiveSupport::Notifications for Rails issue https://github.com/rails/rails/issues/12069

as-note-thread-safety-demo.rb

#!/usr/bin/env ruby

#
# When run against rails/rails commit 91684fb193a91671d682701cc1357e7b4b3fbe2b,
# this code produces the following output on my machine:
#
# long start   @ 0.000
# short start  @ 0.510
# short finish @ 1.511
#   short reported 1.511186 s
# long finish  @ 2.001
#   long reported 1.490836 s
#
# That is: the reported times are incorrect. More specifically, the reported start
# times for the 'short' and 'long' blocks are swapped, leading to incorrect durations.
#

require 'active_support'

ActiveSupport::Notifications.subscribe('frobnicate') do |name, start, finish, id, payload|
  raise "uh-oh, start was nil" if start == nil
  duration = finish - start
  puts "  #{payload[:name]} reported #{duration} s"
end

t0 = Time.now

thread0 = Thread.new do
  ActiveSupport::Notifications.instrument('frobnicate', :name => 'long') do
    puts "long start   @ %.3f" % [Time.now - t0]
    sleep 2
    puts "long finish  @ %.3f" % [Time.now - t0]
  end
end

sleep 0.5

thread1 = Thread.new do
  ActiveSupport::Notifications.instrument('frobnicate', :name => 'short') do
    puts "short start  @ %.3f" % [Time.now - t0]
    sleep 1
    puts "short finish @ %.3f" % [Time.now - t0]
  end
end

[thread0, thread1].each(&:join)

nested.rb

#!/usr/bin/env ruby

#
# When run against rails/rails commit 91684fb193a91671d682701cc1357e7b4b3fbe2b,
# this code produces the following output on my machine:
#
# outer start   @ 0.000
# inner start  @ 0.501
# inner finish @ 1.502
#   inner reported 1.501953 s
# outer finish  @ 1.502
#   outer reported 1.001104 s
#

require 'active_support'

ActiveSupport::Notifications.subscribe('frobnicate') do |name, start, finish, id, payload|
  raise "uh-oh, start was nil" if start == nil
  duration = finish - start
  puts "  #{payload[:name]} reported #{duration} s"
end

t0 = Time.now

ActiveSupport::Notifications.instrument('frobnicate', :name => 'outer') do
  puts "outer start   @ %.3f" % [Time.now - t0]
  sleep 0.5
  ActiveSupport::Notifications.instrument('frobnicate', :name => 'inner') do
    puts "inner start  @ %.3f" % [Time.now - t0]
    sleep 1
    puts "inner finish @ %.3f" % [Time.now - t0]
  end
  puts "outer finish  @ %.3f" % [Time.now - t0]
end