GemのソースをTracePointを使って効率的に読む

Rubyには様々な便利なGemがあるので有効活用しない手はないですよね。
ただ使っているGemが予期せぬ挙動をした時やドキュメントに載ってないような詳細仕様を知りたい時などにソースを読みたくなることがあります。

Gemのソースを読みたい場合、GithubなどWeb上に公開されていることが多いのでブラウザでソースを見たり、ローカルにソースを落としてきて見たりすると思います。

ただ愚直にソースを読み始めるとソース量が膨大だったり、メタプロが多用されていたりなどで読解がかなり大変です。
そこでこの記事ではTracePointを使って効率的にソースを読む方法を紹介します。

# ソースを読んでみよう
具体例があった方が良いので、今回はrailsの`find_or_create_by`を使った場合に呼ばれるソースを探すことにしましょう。
https://github.com/rails/rails

今回はローカルマシンにチェックアウトして読むことにします。
この記事では6-0-stableブランチ(2020/01/14時点)を使っています。

## 愚直にやってみよう
該当箇所の探し方は人それぞれだと思いますが、私は最初はメソッド名でgrepすることが多いです。
今回はactiverecord配下にあることが明白なのでactiverecord/配下で`git grep find_or_create_by`しました。

```ruby
activerecord % git grep find_or_create_by
CHANGELOG.md:    `ActiveRecord::Base.find_or_create_by`/`!` by leaning on unique constraints in the database.
lib/active_record/associations.rb:      #       def find_or_create_by_name(name)
lib/active_record/associations.rb:      #         find_or_create_by(first_name: first_name, last_name: last_name)
lib/active_record/associations.rb:      #   person = Account.first.people.find_or_create_by_name("David Heinemeier Hansson")
lib/active_record/associations.rb:      #     def find_or_create_by_name(name)
lib/active_record/associations.rb:      #       find_or_create_by(first_name: first_name, last_name: last_name)
lib/active_record/associations.rb:        #     def find_or_create_by_name(name)
lib/active_record/associations.rb:        #       find_or_create_by(first_name: first_name, last_name: last_name)
lib/active_record/associations.rb:        #     def find_or_create_by_name(name)
lib/active_record/associations.rb:        #       find_or_create_by(first_name: first_name, last_name: last_name)
lib/active_record/querying.rb:      :find_or_create_by, :find_or_create_by!, :find_or_initialize_by,
lib/active_record/relation.rb:    #   User.find_or_create_by(first_name: 'Penélope')
lib/active_record/relation.rb:    #   User.find_or_create_by(first_name: 'Penélope')
lib/active_record/relation.rb:    #   User.create_with(last_name: 'Johansson').find_or_create_by(first_name: 'Scarlett')
lib/active_record/relation.rb:    #   User.find_or_create_by(first_name: 'Scarlett') do |user|
lib/active_record/relation.rb:    def find_or_create_by(attributes, &block)
lib/active_record/relation.rb:    # Like #find_or_create_by, but calls
lib/active_record/relation.rb:    def find_or_create_by!(attributes, &block)
lib/active_record/relation.rb:    # This is similar to #find_or_create_by, but avoids the problem of stale reads between the SELECT
lib/active_record/relation.rb:    # * While we avoid the race condition between SELECT -> INSERT from #find_or_create_by,
lib/active_record/relation.rb:    # Like #find_or_create_by, but calls {new}[rdoc-ref:Core#new]
lib/active_record/relation/finder_methods.rb:    #   Person.find_or_create_by(name: 'Spartacus', rating: 4)
test/cases/finder_respond_to_test.rb:    assert_not_respond_to Topic, :fail_to_find_or_create_by_title
test/cases/finder_respond_to_test.rb:    assert_not_respond_to Topic, :find_or_create_by_title?
test/cases/finder_test.rb:    assert_raise(NoMethodError) { Topic.fail_to_find_or_create_by_title("Nonexistent Title") }
test/cases/finder_test.rb:    assert_raise(NoMethodError) { Topic.find_or_create_by_title?("Nonexistent Title") }
test/cases/nested_attributes_test.rb:      ).find_or_create_by!(
test/cases/relation/delegation_test.rb:        :find_or_create_by, :find_or_create_by!, :find_or_initialize_by,
test/cases/relations_test.rb:  def test_find_or_create_by
test/cases/relations_test.rb:    bird = Bird.find_or_create_by(name: "bob")
test/cases/relations_test.rb:    assert_equal bird, Bird.find_or_create_by(name: "bob")
test/cases/relations_test.rb:  def test_find_or_create_by_with_create_with
test/cases/relations_test.rb:    bird = Bird.create_with(color: "green").find_or_create_by(name: "bob")
test/cases/relations_test.rb:    assert_equal bird, Bird.create_with(color: "blue").find_or_create_by(name: "bob")
test/cases/relations_test.rb:  def test_find_or_create_by!
test/cases/relations_test.rb:    assert_raises(ActiveRecord::RecordInvalid) { Bird.find_or_create_by!(color: "green") }
test/cases/statement_cache_test.rb:    def test_find_or_create_by
test/cases/statement_cache_test.rb:      a = Book.find_or_create_by(name: "my book")
test/cases/statement_cache_test.rb:      b = Book.find_or_create_by(name: "my other book")
```

たくさんヒットしましたが、テストコードやコメントアウトされている行は無視すると下記の２行になります。

```ruby
lib/active_record/querying.rb:      :find_or_create_by, :find_or_create_by!, :find_or_initialize_by,
lib/active_record/relation.rb:    def find_or_create_by(attributes, &block)
```

どちらが呼ばれているのでしょうか？
これだけの情報ではわからないのでさらにソースを読む必要がありそうです。

## TracePointを使ってみよう

机上でソースを辿るのがツラくなってきたのでTracePointを使って呼び出されたメソッドをトレースしてみます。
動作環境は下記の通り

* Ruby: 2.6.5
* Rails: 6.0.2.1

Rails consleで下記を実行しました。

```ruby
# TracePointのトレース開始
# :callを指定することでメソッド呼び出しをトレースします
trace = TracePoint.trace(:call)  do |tp|
  # 何も指定しないと全Gemがトレースされるのでactiverecordのみ出力するようにしました
  p tp.inspect if tp.path.include?('activerecord-6')
end

# トレースされるようになったのでfind_or_created_byを実行
User.find_or_create_by(name: 'hoge')
# trace情報が大量に出力されます
"#<TracePoint:call `find_or_create_by'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/querying.rb:21>"
"#<TracePoint:call `all'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping/named.rb:26>"
"#<TracePoint:call `current_scope'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping.rb:26>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping.rb:74>"
"#<TracePoint:call `value_for'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping.rb:79>"
"#<TracePoint:call `raise_invalid_scope_type!'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping.rb:99>"
"#<TracePoint:call `base_class'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:99>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `relation'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:295>"
"#<TracePoint:call `create'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/delegation.rb:114>"
"#<TracePoint:call `relation_class_for'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/delegation.rb:120>"
"#<TracePoint:call `relation_delegate_class'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/delegation.rb:8>"
"#<TracePoint:call `arel_table'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:266>"
"#<TracePoint:call `table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:195>"
"#<TracePoint:call `reset_table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:226>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:195>"
"#<TracePoint:call `reset_table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:226>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `table_name='@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:205>"
"#<TracePoint:call `compute_table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:528>"
"#<TracePoint:call `base_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:113>"
"#<TracePoint:call `base_class'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:99>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `full_table_name_prefix'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:236>"
"#<TracePoint:call `undecorated_table_name'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:522>"
"#<TracePoint:call `full_table_name_suffix'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:240>"
"#<TracePoint:call `table_name='@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/model_schema.rb:205>"
"#<TracePoint:call `type_caster'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:280>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/type_caster/map.rb:6>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/arel/table.rb:16>"
"#<TracePoint:call `predicate_builder'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:276>"
"#<TracePoint:call `table_metadata'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:306>"
"#<TracePoint:call `arel_table'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/core.rb:266>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/table_metadata.rb:7>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:7>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder/basic_object_handler.rb:6>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder/base_handler.rb:6>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder/range_handler.rb:8>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder/array_handler.rb:8>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder/array_handler.rb:8>"
"#<TracePoint:call `register_handler'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation/predicate_builder.rb:46>"
"#<TracePoint:call `initialize'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:27>"
"#<TracePoint:call `finder_needs_type_condition?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:86>"
"#<TracePoint:call `descends_from_active_record?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:76>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `descends_from_active_record?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:76>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `default_scoped'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping/named.rb:57>"
"#<TracePoint:call `build_default_scope'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/scoping/default.rb:103>"
"#<TracePoint:call `abstract_class?'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/inheritance.rb:161>"
"#<TracePoint:call `find_or_create_by'@/rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:168>"
・・・（省略)
```

これで最初に呼ばれているのは`lib/active_record/querying.rb#find_or_create_by`ということがサクッと分かりました。
ちなみに候補に上がっていた`lib/active_record/relation.rb#find_or_create_by`も５８個目に呼ばれていました。

TracePointを使うとこのように速く、そして正確にメソッド呼び出しの順を知ることができます。
この情報をインプットとしてソースを読むとスムーズに処理の流れが読めます。

ちなみに今回は`:call`を指定して呼び出されたメソッドだけを抽出しましたが、パラメーターや戻り値もトレースできるので、障害の原因調査などでも活躍すると思います。
詳細は"参照"に載せているリンクなどをご覧ください。

# 参照
以下、TracePointの仕様を知る上でとても参考になったリンクです。

すごく参考になった記事
https://qiita.com/siman/items/9426ff6c113247088f7e

Rubyリファレンス
https://docs.ruby-lang.org/ja/latest/class/TracePoint.html