Go to Qiita Advent Calendar 2024 Top
LoginSignup
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

@koshigoein株式会社フィードフォース

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

Last updated at Posted at 2018-08-16

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
0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?