概要
原著者の許諾を得て翻訳・公開いたします。
- 英語記事: Optimize Your Debugging Process With Object-Oriented Tracing and tapping_device - DEV Community
- 原文公開日: 2020/01/22
- 著者: Stan Lo
I wrote a blog post to propose a new debugging strategy called object-oriented tracing. I've been experimenting with this concept for months and I'd love to hear any feedback about it or how you debug your Ruby program!
Please retweet for reach😊https://t.co/PP1g8XQqwE
— Stan (@_st0012) January 21, 2020
Ruby: 「オブジェクト指向トレース」とtapping_device gemで効率よくデバッグ（翻訳）
デバッグはプログラマーにとって日常的な仕事のひとつです。プログラミングのスキルのみならず、デバッグのスキルも磨き上げることが重要です。しかしリファクタリングやテストといったコーディングスキルの伸びに比べると、デバッグスキルがイマイチ伸びないと思ったことはありませんか？私も振り返ってみると、数年前のデバッグツールや手順をずっと使い続けていたことに気づきました。
私はここ数週間デバッグを効率よく行う方法を模索し続けてきました。本記事では、デバッグスキルを伸ばすのが難しい理由と、この問題に別の方面から取り組む方法について解説します。
（簡単のため、本記事では「バグ」という言葉を「以前問題なく動いていたプログラムを壊すコード片」という意味に限定して用います）
プログラムのデバッグ手順について
実際のデバッグの方法は、「比較」という極めて素朴な行為です。プログラムの「こう動くべき」動作と「実際の」動作を比較し、プログラムの実行中にそのズレがどこから始まるかを探し当てることでデバッグします。ほとんどの場合、それらがバグを見つける手がかり（バグそのものでなければですが）となります。これは以下の3つの手順で行います。
- 期待する実行パスを構築する
- 実際の実行パスを構築する
- 両者のパスを比較する
以下の図で例を示します。
実行パスを構築する
プログラムの「実行パス」とは、ある意味メソッドや関数の呼び出しのパス、あるいはもっとシンプルに「呼び出しパス」と考えることもできます。しかしプログラムのサイズによってはメソッド呼び出しが膨大になる可能性もありますので、普通は「ビジネスロジックに関連するメソッドの呼び出しパス」に限定します。たとえば、OrdersController#createリクエスト中にはArray#[]とかObject#inspectといった呼び出しが多数発生しますが、実行パスを構築するうえではOrderの作成にのみ注目し、それ以外は無視します。
実行パスを比較する
ほとんどの条件下では、プログラムのバグは振る舞いが最初に異なる場所（戻り値が異なる、違うメソッドが呼ばれるなど）で見つかります。そこで以下のケースでは、バグはおそらくbarメソッドかその依存ファイルの中に潜んでいます。
この方法の困難な点
ほとんどの開発者がこのアプローチでデバッグしていると私は信じていますが、アプローチは完全に同じではありません。理想としては実行パスをできるかぎり詳細に構築すべきであり、それによって正確な比較に必要な情報を十分に得られます。しかし現実には時間も足りませんし勤労意欲が落ちるときもありますので、そのバグに関連すると「思われる」メソッドをエイヤでいくつか選んで、後は選んだメソッドが正しいことを祈るのが関の山です。
つまり、デバッグ手法の効率性は、パスを構築するときにいかに適切なメソッドを選ぶかにかかっています。そしてこれは以下の要素に影響されます。
- その言語なりフレームワークなりにおける自分の経験
- コードベースをどれだけ理解しているか
- 運の強さ？
デバッグスキルの向上をそれほど心がけていなくても、デバッグに要する時間が時間とともに短くなっていく理由はこれです。
私見では、この現象の根本原因はデバッグ戦略とうまく調和する効率的なツールがないからだと思います。その点はputsデバッグであろうとpryデバッガーであろうと同じです。ほとんどの場合、プログラムの振る舞いを精査する作業には膨大な時間を要しますが、それにはいくつもの理由があります。
1. 引数を手動で集める必要がある。
# 超つらい
def foo(var1, var2)
puts("var1: #{var1}")
puts("var2: #{var2}")
...
end
2. 戻り値を手動で集める必要がある。
# これとか
def new_cart(attributes)
Cart.new(attributes).tap { |c| puts(c) }
end
# これとか
cart = new_cart(attributes)
puts(cart)
3. さまざまなメソッド間を行ったり来たりしながら、putsやブレークポイントを置いたりする必要がある。
情報を集める作業を手動で行う割合が増えるほど、推測やバクチに頼るようになります。この作業はつらいだけでなく、さまざまな情報をかき集めるうちに以下のような別の問題まで発生します。
- 必要な情報（正しいメソッドを正しい場所で呼んでいるかなど）を効率的に集めるには、プログラムを十分理解する必要があります。経験の浅い開発者ほど理解は困難になります。
- ブレークポイントやトレース用メソッドを追加するとコードが汚染されます。たとえば、あるメソッドがあるオブジェクトのステートを変更しているとすると、コードのトレース時に（戻り値を取りたいなどの理由で）そのメソッドを呼び出すと、プログラムの振る舞いが変わってしまうかもしれません。
- 私の経験では、コードが散らかっていると自分がそもそも何をしたかったのか（=メソッド呼び出しを調べて深掘りする）を忘れてしまいがちです。
「オブジェクト指向トレース」
ここでデバッグ時に私たちが行っていることをよく観察すると、うまく活用できそうなパターンがいくつか見えてきます。たとえば以下がそうです。
- Webアプリケーションのある機能をデバッグしているのであれば、特定のエンドポイントのロジック（特定のコントローラのアクションなど）から調査を開始する手が考えられます。これはデバッグを開始するのに最適な場所となります。
- Rubyのようなオブジェクト指向プログラミング言語では、ある機能が1つまたは複数のクラスにリンクしているのが普通です。たとえばorderにバグがあるなら
OrderCreationServiceあたりを調べるべきでしょう。つまりオブジェクトのいくつかのメソッド呼び出しを観察することで実行パスの大半を構築できるわけです。
「オブジェクト指向トレース」という概念は、以上の仮定と、Rubyの強力なTracePoint機能の上に成り立ちます。いくつか例を示して説明します。
OrdersController#createというエンドポイントがあり、ここでorderを作成するとします。
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
@order = OrderCreationService.new.perform(@cart, promotion)
......
end
このorder作成の実行パスを構築してみたいと思います。これは以下のように書けます。
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:call) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
上のコードから以下のような結果が出力されます。
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
これでOrderを1つ作成するためにOrderCreationServiceが何をしているかが判明し、かなり明確な実行パスを直ちに得られました。しかし、ここでRubyのメタプログラミング技を少々用いれば、メソッド呼び出しごとに引数を取るなどの詳細な情報を取れるのです！
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:call) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
Arg options: {}
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
めちゃクールですよね？呼び出されたメソッドや、受け取った引数がすっかり明らかになりました。それでは最後の仕上げに戻り値も情報に加えてみましょう。
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:return) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
puts(" => #{tp.return_value}")
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:4
Arg options: {}
=> {}
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:21
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=>
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:25
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> true
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:29
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> #<Order:0x00007f91455ebd10>
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:13
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> #<Order:0x00007f91455ebd10>
上の例を注意深く読んでいただければ、戻り値が加わった以外にも、コードや出力で変わった点があることに気づくでしょう。
TracePointがreturnイベントをトラッキングするようになった（その前の2つの例ではcallイベントだった）。- 出力の順序がその前の結果とどことなく異なっている
理由は、メソッド呼び出しの完了（return）を、戻り値を取り出せるようになるまで待つ必要があるからです。つまり出力は（呼び出された順ではなく）メソッドが戻った順に並びます。
def perform
# ...
create_order
end
# call order: perform -> create_order
# return order: create_order -> perform
このわずかな違いを理解しておけば、出力を読んでいてもさほど混乱はしないでしょう。実際、私はこれがいくつかの場合にさらに有用であることに気づきました。たとえば、同じ値をさまざまなメソッドが更新して戻す様子を観察したいのであれば、戻り値順に並ぶ方が自然です。
オブジェクト指向トレースを用いれば、プログラムの呼び出しパス、呼び出しごとの引数、そして戻り値も一発で得られます。オブジェクト指向トレースは実に効率的であるのみならず、前述した問題のいくつかを回避することもできます。
- 従来だと、
OrderCreationServiceのメソッド内部を把握して必要な情報を集めるために、OrderCreationServiceが何を呼び出すかを理解する必要があったが、OrderCreationService#performが呼び出される場所を把握するだけでできるようになった（これなら楽勝です😋）。 OrderCreationServiceのロジックを詳しく把握したりテストする必要がなければ、コードを一切変更する必要がない。そのおかげで、デバッグ中でもコードを汚さずに済みます。
TappingDevice
欲しい機能はTracePointに既にひととおりありますが、もっと楽にやるための改良点がいくつかあります。
- ボイラープレートコード（デバッグ用のテンプレートコード）が10行もあるので覚えるのがダルい。
TracePointに慣れないうちはいくつかエッジケースを踏んでしまうかもしれません（私もそうでした）。それを回避しようとするとボイラープレートコードが長くなりがちです。
そうした理由から、私は皆さんに代わってtapping_deviceを作って楽にやれるようにしました。さっき最後に書いたコード例を思い出せますか？私は無理です😆。では、あのボイラープレートのコード片を1個のメソッド呼び出しにしてみたらどうでしょう？
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
TracePoint.new(:return) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
puts(" => #{tp.return_value}")
end
end.enable do
@order = service.perform(@cart, promotion)
end
# ...
end
上のように書く代わりに、以下のようにたった2行追加するだけでやれます。
include TappingDevice::Trackable # includeしておく
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
print_calls_in_detail(service) # <--- この場合はこれだけあればよい
@order = service.perform(@cart, promotion)
# ...
end
これで以下のように同じ情報を得られます！
:validate_cart # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
<= {:cart=>#<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> nil
:apply_discount # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> true
:create_order # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
:perform # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:10
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
tapping_deviceは、print_calls_in_detailの他にも、print_tracesなどのさまざまな情報レベルに応じたAPIを提供しています。
さて、OrderCreationServiceには何も不審な点が見つからなかったとしましょう。次は@cartで何か問題が起きているのではないかと疑ってみることにします。print_tracesを用いれば、@cartがプログラムの他の部分とやりとりする様子を確認できます。
include TappingDevice::Trackable
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
print_traces(@cart, exclude_by_paths: [/gems/]) # /gems/を除外してActive Recordの内部メソッド呼び出しを出力しないようにする
@order = service.perform(@cart, promotion)
Passed as 'cart' in 'OrderCreationService#perform' at /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:9
Passed as 'cart' in 'OrderCreationService#validate_cart' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
Called :reserved_until from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:18
Called :errors from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:9
Passed as 'cart' in 'OrderCreationService#apply_discount' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
Called :apply_discount from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:24
Called :total from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Called :update! from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Passed as 'cart' in 'OrderCreationService#create_order' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
Called :total from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :customer from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :promotion from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
@cartを呼び出したメソッドはもちろん、@cartを引数に取ったメソッドも出力されるようになりました【要チェック】。これでデバッグ時間が少しは減ることでしょう😉。
tapping_deviceの利用法について詳しく知りたい方は、readmeでさまざまなヘルパーをご覧いただけます。私がtapping_deviceでRailsのissueを修正したときのやり方については別記事『Debug Rails issues effectively with tapping_device』をどうぞ。
まとめ
デバッグ作業のほとんどは、プログラムの動作（あるいはかつて動作していた）に関する情報収集ですが、これを手動でやっていては相当時間を吸われてしまいます。プログラムの動作について雑に当たりをつけて人間らしく乗り切ろうとすると、問題解決にさらに時間を吸われてしまいます。
しかしオブジェクト指向トレースを援用すれば、オブジェクト指向のパラダイムとRubyの超強力なTracePointの力を借りて、プログラムを効果的に精査できるようになります。私はこの方法で、駆け出し開発者がデバッグするときのつらみも軽減でき、ベテラン開発者のデバッグプロセスも大きく加速できると信じています。
本記事やtapping_deviceについてお気づきの点がありましたら、お気軽に元記事にコメントをどうぞ。皆さんからのご相談を歓迎します！他のデバッグ戦略や、もっとよいデバッグ戦略をご存知でしたら、ぜひお知らせください😉。