Rails

メモ: ActiveSupport::Notifications.instrument でメモリリークしよう!


ActiveJob と組み合わせてメモリリークしよう!

ActiveJob#perform メソッドの内部で(結果的に)大量の ActiveSupport::Notifications.instrument を呼び出す事で、メモリを大量に使うことができます。

require 'active_support'

require 'active_support/subscriber'
require 'active_job'

class Subscriber < ActiveSupport::Subscriber
def perform(event)
end

def event_name(event)
end
end
Subscriber.attach_to :active_job

class Job < ActiveJob::Base
def perform(*args)
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.active_job') }
end
end

puts `ps u #{Process.pid}`
Job.perform_now
puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 34799 91.9 0.1 4310112 24264 s004 S+ 11:28AM 0:01.29 ruby sample-memory-leak-active-job.rb
[ActiveJob] [Job] [0b113157-04d6-4992-aadb-831d3cf5f5e4] Performing Job (Job ID: 0b113157-04d6-4992-aadb-831d3cf5f5e4) from Async(default)
[ActiveJob] [Job] [0b113157-04d6-4992-aadb-831d3cf5f5e4] Performed Job (Job ID: 0b113157-04d6-4992-aadb-831d3cf5f5e4) from Async(default) in 10299.27ms
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 34799 100.0 4.0 5141724 668132 s004 S+ 11:28AM 0:11.47 ruby sample-memory-leak-active-job.rb

該当 subscriber に #perform メソッドを実装するのを忘れずに。忘れてしまうとリークできません。

require 'active_support'

require 'active_support/subscriber'
require 'active_job'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :active_job

class Job < ActiveJob::Base
def perform(*args)
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.active_job') }
end
end

puts `ps u #{Process.pid}`
Job.perform_now
puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 38718 87.3 0.1 4310112 23864 s004 S+ 11:32AM 0:01.74 ruby sample-no-memory-leak-active-job.rb
[ActiveJob] [Job] [4814923b-d79a-4faf-a14d-af7ea9fc3e5f] Performing Job (Job ID: 4814923b-d79a-4faf-a14d-af7ea9fc3e5f) from Async(default)
[ActiveJob] [Job] [4814923b-d79a-4faf-a14d-af7ea9fc3e5f] Performed Job (Job ID: 4814923b-d79a-4faf-a14d-af7ea9fc3e5f) from Async(default) in 11778.25ms
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 38718 96.9 0.2 4312160 28896 s004 S+ 11:32AM 0:11.82 ruby sample-no-memory-leak-active-job.rb

メモリリークのためにはイベントの親子関係が重要なので、subscriber が #perform を実装していないと ActiveJob によるイベントの親子関係構築が働きません。 ActiveJob による親子関係構築は、以下の様に行われています。

# https://github.com/rails/rails/blob/fc5dd0b85189811062c85520fd70de8389b55aeb/activejob/lib/active_job/logging.rb#L21-L29

around_perform do |job, block, _|
tag_logger(job.class.name, job.job_id) do
payload = { adapter: job.class.queue_adapter, job: job }
ActiveSupport::Notifications.instrument("perform_start.active_job", payload.dup)
ActiveSupport::Notifications.instrument("perform.active_job", payload) do # <- 親です
block.call # <- block 内部で instrument('*.active_job') したら子です
end
end
end


ActiveJob ぬきでメモリリークしよう!!

ActiveSupport::Notifications.instrument のブロックをネストすればイベントの親子関係を作る事ができます。

require 'active_support'

require 'active_support/subscriber'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :sample

puts `ps u #{Process.pid}`
ActiveSupport::Notifications.instrument('event_name.sample', key: :value) do
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.sample') }
end
puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 43134 76.3 0.1 4307284 21444 s004 S+ 11:36AM 0:01.40 ruby sample-memory-leak.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 43134 93.4 4.0 5140944 664404 s004 S+ 11:36AM 0:13.75 ruby sample-memory-leak.rb

ネストしなければ親子関係が作られず、メモリリークさせることができません。

require 'active_support'

require 'active_support/subscriber'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :sample

puts `ps u #{Process.pid}`
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.sample') }
puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 46108 90.2 0.1 4307284 21344 s004 S+ 11:39AM 0:01.18 ruby sample-no-memory-leak.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 46108 65.2 0.1 4307284 22096 s004 S+ 11:39AM 0:11.03 ruby sample-no-memory-leak.rb

イベントの親子関係はこんな感じで作られてます。

# https://github.com/rails/rails/blob/fc5dd0b85189811062c85520fd70de8389b55aeb/activesupport/lib/active_support/subscriber.rb#L86-L102

def start(name, id, payload)
e = ActiveSupport::Notifications::Event.new(name, Time.now, nil, id, payload)
parent = event_stack.last
parent << e if parent

event_stack.push e
end

def finish(name, id, payload)
finished = Time.now
event = event_stack.pop
event.end = finished
event.payload.merge!(payload)

method = name.split(".".freeze).first
send(method, event)
end

ActiveSupport::Notifications.instrument を呼ぶ度に子供イベントがスタックされている事が分かります。

require 'active_support'

require 'active_support/subscriber'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :sample

subscriber = ActiveSupport::Subscriber.subscribers.last

ActiveSupport::Notifications.instrument('event_name.sample', key: :value) do
10.times do
ActiveSupport::Notifications.instrument('event_name.sample')
p subscriber.send(:event_stack).last&.children&.size
end
end
p subscriber.send(:event_stack).last&.children&.size

10.times { ActiveSupport::Notifications.instrument('event_name.sample') }
p subscriber.send(:event_stack).last&.children&.size

__END__

1
2
3
4
5
6
7
8
9
10
nil
nil


おまけ!!!


GC

require 'active_support'

require 'active_support/subscriber'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :sample

puts `ps u #{Process.pid}`
ActiveSupport::Notifications.instrument('event_name.sample', key: :value) do
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.sample') }
end
puts `ps u #{Process.pid}`

GC.start

puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 86655 90.6 0.1 4308308 21096 s004 S+ 12:10PM 0:01.27 ruby sample-memory-leak-with-gc.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 86655 100.0 4.0 5138896 667436 s004 S+ 12:10PM 0:13.37 ruby sample-memory-leak-with-gc.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 86655 91.3 3.7 5094764 626864 s004 S+ 12:10PM 0:14.66 ruby sample-memory-leak-with-gc.rb

※ 『リーク(解放漏れ)』というよりも、(ライブラリ的には)意図的な使用に見える一方、相変わらず GC では解放されないプロセスのメモリ領域はリークと言ってしまって間違いでもない、かな?


memprof2

require 'active_support'

require 'active_support/subscriber'
require 'memprof2'

class Subscriber < ActiveSupport::Subscriber
def event_name(event)
end
end
Subscriber.attach_to :sample

Memprof2.start

puts `ps u #{Process.pid}`
ActiveSupport::Notifications.instrument('event_name.sample', key: :value) do
1_000_000.times { ActiveSupport::Notifications.instrument('event_name.sample') }
end
puts `ps u #{Process.pid}`

Memprof2.report(out: 'tmp/before-gc.txt')

GC.start
Memprof2.report(out: 'tmp/after-gc.txt')

Memprof2.stop

puts `ps u #{Process.pid}`

__END__

USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 88487 93.1 0.1 4307336 21360 s004 S+ 12:11PM 0:01.06 ruby sample-memory-leak-with-profile.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 88487 100.0 9.2 6016432 1536304 s004 S+ 12:11PM 0:25.96 ruby sample-memory-leak-with-profile.rb
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
koshigoe 88487 100.0 9.2 6024628 1541536 s004 S+ 12:11PM 0:53.97 ruby sample-memory-leak-with-profile.rb

$ sort -n -k1 -r tmp/before-gc.txt | head -n 10

192000192 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:60:Hash
192000192 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:60:Hash
96000096 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:87:ActiveSupport::Notifications::Event
96000096 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:87:ActiveSupport::Notifications::Event
86000086 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:95:Time
86000086 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:95:Time
86000086 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:87:Time
86000086 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:87:Time
51636312 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:64:Array
51636312 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:64:Array

$ sort -n -k1 -r tmp/after-gc.txt | head -n 10

3177552 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:87:String
1603169 sample-memory-leak-with-profile.rb:15:String
1601463 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:64:String
1599935 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:60:String
1599396 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:95:String
8424 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/subscriber.rb:100:File
8424 /app/vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:64:File
192 sample-memory-leak-with-profile.rb:22:Hash
192 sample-memory-leak-with-profile.rb:22:Hash
192 sample-memory-leak-with-profile.rb:22:Hash