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

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

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

```ruby
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` メソッドを実装するのを忘れずに。忘れてしまうとリークできません。

```ruby
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` による親子関係構築は、以下の様に行われています。

```ruby
# 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` のブロックをネストすればイベントの親子関係を作る事ができます。

```ruby
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
```

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

```ruby
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
```

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

```ruby
# 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` を呼ぶ度に子供イベントがスタックされている事が分かります。

```ruby
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

```ruby
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

```ruby
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
```