🔧

いまさらのデバッグプリントによる人力デバッグ備忘録(後編)

に公開
プログラミング
デバッグ
備忘録
問題解決
tech

はじめに

本記事は "前編・中編・後編" 構成の "後編" になります。

  • デバッグプリントの概要 (前編)
  • デバッグプリントの詳細と手順 (前編)
    • デバッグプリントの具体的手順
    • より最終出力に近い値から表示していく
  • デバッグプリントのTips
    • 処理内容別、バグの位置を絞り込むための変数の表示戦略 (中編)
    • 表示内容の工夫 (後編)
    • その他の工夫 (後編)

前編はこちら
中編はこちら

デバッグプリントのTips

中編では、デバッグプリントを行う際のTipsや考え方のうち、
if文やfor文など典型的な処理において、どの変数の値を表示しどのようにバグの位置を絞り込んでいくかを、例と共に見ていきました。

後編である本記事では、残るデバッグプリントにおける工夫について簡潔に説明します。

  • 表示内容の工夫
    • 複数の値の表示
    • ターミナル等に表示した場合の見やすさ
    • 複数の値を持つオブジェクトの表示
  • その他の工夫
    • 実行範囲の制限
    • 表示のための関数の消し忘れ対策
    • エラーメッセージの活用

表示内容の工夫

ここでは、変数を表示する際の表示内容(テキスト)の工夫について、簡単なものですが書いていきたいと思います。

複数の値の表示

中編の逐次処理の例や複数の関数の例で説明したように、複数の変数を一度に全部表示したほうが分かりやすい場合もあります。

a = 1

b = test1(a)

print(b)

c = test2(b)

print(c)

d = test3(c)

print(d)

e = test4(d)

print(e)

2
3
4
5

このような複数の値を表示するときには、どれが何の変数の値なのかを分かりやすくします。
その変数の想定される値が決まっているときは、それも並べて表示するとより分かりやすくなります。

a = 1

b = test1(a)

print(f"b: {b} = {b_ex} ? ({b == b_ex})")

c = test2(b)

print(f"c: {c} = {c_ex} ? ({c == c_ex})")

d = test3(c)

print(f"d: {d} = {d_ex} ? ({d == d_ex})")

e = test4(d)

print(f"e: {e} = {e_ex} ? ({e == e_ex})")

b: 2 = 2 ? (True)
c: 3 = 3 ? (True)
d: 0 = 4 ? (False)
e: 0 = 5 ? (False)

ターミナル等に表示した場合の見やすさ

変数の値を表示するターミナル上には、デバッグプリントの出力以外の結果も表示されているかもしれません。
利用している外部ライブラリのデバッグ出力や、警告文などです。

その場合、デバッグプリントのため出力したテキストが、他の出力に紛れてしまい、見づらくなることもあります。

(VllmWorkerProcess pid=134) INFO 09-09 18:06:39 [loader.py:458] Loading weights took 171.46 seconds
INFO 09-09 18:06:39 [loader.py:458] Loading weights took 171.70 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:40 [model_runner.py:1140] Model loading took 9.0935 GiB and 172.078019 seconds
INFO 09-09 18:06:39 [model_runner.py:1140] Model loading took 9.0935 GiB and 171.838181 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] Memory profiling takes 11.33 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] the current vLLM instance can use total_gpu_memory (14.74GiB) x gpu_memory_utilization (0.90) = 13.27GiB
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] model weights take 9.09GiB; non_torch_memory takes 0.10GiB; PyTorch activation peak memory takes 0.44GiB; the rest of the memory reserved for KV Cache is 3.63GiB.
b: 2 = 2 ? (True)   # 他の長い出力文に紛れると、見つけにくくなる場合がある
INFO 09-09 18:06:51 [worker.py:287] Memory profiling takes 11.50 seconds
INFO 09-09 18:06:51 [worker.py:287] the current vLLM instance can use total_gpu_memory (14.74GiB) x gpu_memory_utilization (0.90) = 13.27GiB
INFO 09-09 18:06:51 [worker.py:287] model weights take 9.09GiB; non_torch_memory takes 0.10GiB; PyTorch activation peak memory takes 1.41GiB; the rest of the memory reserved for KV Cache is 2.66GiB.
INFO 09-09 18:06:52 [executor_base.py:112] # cuda blocks: 1363, # CPU blocks: 2048
INFO 09-09 18:06:52 [executor_base.py:117] Maximum concurrency for 2048 tokens per request: 10.65x
INFO 09-09 18:06:56 [llm_engine.py:437] init engine (profile, create kv cache, warmup model) took 15.97 seconds

ライブラリの仕様にしたがい、このような出力をOFFにするのが直接的な解決ではありますが、
デバッグを実施するにあたってサッと変数の値を確認して次に進みたい場合など、このような対応が面倒になる場合があります。

こういうときは、目立つ文字列と一緒に値を表示し、出力から見つけやすくします。

(VllmWorkerProcess pid=134) INFO 09-09 18:06:39 [loader.py:458] Loading weights took 171.46 seconds
INFO 09-09 18:06:39 [loader.py:458] Loading weights took 171.70 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:40 [model_runner.py:1140] Model loading took 9.0935 GiB and 172.078019 seconds
INFO 09-09 18:06:39 [model_runner.py:1140] Model loading took 9.0935 GiB and 171.838181 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] Memory profiling takes 11.33 seconds
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] the current vLLM instance can use total_gpu_memory (14.74GiB) x gpu_memory_utilization (0.90) = 13.27GiB
(VllmWorkerProcess pid=134) INFO 09-09 18:06:51 [worker.py:287] model weights take 9.09GiB; non_torch_memory takes 0.10GiB; PyTorch activation peak memory takes 0.44GiB; the rest of the memory reserved for KV Cache is 3.63GiB.
==================== debug print ======================
b: 2 = 2 ? (True)
==================== debug print ======================
INFO 09-09 18:06:51 [worker.py:287] Memory profiling takes 11.50 seconds
INFO 09-09 18:06:51 [worker.py:287] the current vLLM instance can use total_gpu_memory (14.74GiB) x gpu_memory_utilization (0.90) = 13.27GiB
INFO 09-09 18:06:51 [worker.py:287] model weights take 9.09GiB; non_torch_memory takes 0.10GiB; PyTorch activation peak memory takes 1.41GiB; the rest of the memory reserved for KV Cache is 2.66GiB.
INFO 09-09 18:06:52 [executor_base.py:112] # cuda blocks: 1363, # CPU blocks: 2048
INFO 09-09 18:06:52 [executor_base.py:117] Maximum concurrency for 2048 tokens per request: 10.65x
INFO 09-09 18:06:56 [llm_engine.py:437] init engine (profile, create kv cache, warmup model) took 15.97 seconds

目立たせ方は、個人の好みでよいと思います。出力が複数行にわたるときは上記のように、
ここからここまでがデバッグプリントの出力、というような区画を作ると分かりやすいと思います。

また、複数の値を表示したり、長いテキストを表示したりするときは、
できるだけターミナル上で改行されないように、複数の表示命令に分けると見やすくなります。

input of func "double_number" = 5, output of "double_number" = 10, input of "square_number" 
= 2, output of "square_number" = 4

↓

input of func "double_number" = 5,
output of "double_number" = 10,

input of "square_number" = 2,
output of "square_number" = 4

複数の値を持つオブジェクトの表示

どんな値かを確認したい変数が、中身にさらに複数の変数を持つオブジェクトである場合もあります。
Pythonであれば、リストなどのコレクションや、クラスなどが考えられます。

このような変数の値を表示するときは、含んでいる値の数が多くないときは全ての値を表示してしまった方が無難です。
ただし、要素の多いリストやメンバの多いクラスなど、全て表示しようとすると大変な場合もあります。

これまで述べてきた通り、
デバッグプリントでは、ある処理にバグがあるかを判断するために、変数の値を表示します。

なので、その処理に関係のある要素や変数、つまりはその処理で計算に使われた・または出力先となった値にのみ表示範囲を絞ると、デバッグプリントを進めやすくなります。

各オブジェクトごとの例

例えばリストの場合は、特定のインデックスにだけアクセスする処理であれば、そのインデックスの要素だけ表示すれば十分です。

a = get_list()
b = test1(a[0])

print("a[0]: ", a[0])
print(b)

ただしリストについては基本、全要素を走査する処理を扱うケースが多いため、
繰り返し処理における例で述べたように少ない要素の配列を用意して処理の検査をしたり、
リストの中身の正しさの検証のためにファイルに出力をするなど、別途対策をとる方がよいでしょう。

**

クラスや、他のプログラミング言語における構造体などの場合は、
複数あるメンバ変数の中から選んで表示することになります。
興味のある処理が、一部のメンバしか使っていないのであれば、そのメンバを表示すれば十分です。

a = test_class()
b = test2(a.id, a.name)

print("a.id: ", a.id, "a.name: ", a.name)
print(b)

**

複数の "key" と "value" の組を持つ型である、辞書やmapの場合も考え方は同じで、
興味のある処理がアクセスしている要素に絞って表示し、確認します。

a = get_dict()
b = a["weight"] / (a["height"] ** 2)

print("a_weight: ", a["weight"], "a_height: ", a["height"])
print(b)

その他の工夫

デバッグプリントを進めるにあたって役立つ、その他の工夫についても紹介します。

実行範囲の制限

デバッグを進めて原因箇所がある程度絞れてきたら、原因箇所以外のコードが実行されないようにするとよいでしょう。

原因箇所でないと分かっているコードの影響を排除することで、さらなる絞り込みやバグ有無の判断をする場合にノイズとなる情報を排除することができますし、
処理に時間がかかるコード部分を実行せずに済めば、単純にデバッグの高速化を見込むこともできます。

また、ターミナル等に表示した場合の見やすさ でも取り上げた、外部ライブラリによる処理がログ等を自動で出力する場合についても、
その処理を実行されなくすることでターミナル等の表示をスッキリさせることもできます。

興味のないコードが実行されないようにする場合は、

  • 興味のあるコードが関数に閉じているなら、その関数だけを実行するコードを書く
  • 興味のないコード部分をコメントアウトする

のどちらかを行えばよいでしょう。

興味のあるコード部分が短くまとまっている場合(関数に切り出している場合も含む)は前者を、
逆に興味のないコード部分の方が短いようであれば前者を選ぶとよいと思います。

表示のための関数の消し忘れ対策

デバッグプリントをしていると、デバッグプリントのための表示処理 (Python なら print文の呼び出し) を消し忘れてしまうことがあります。
著者もデバッグ用の出力文が残ったまま commit してしまい、レビュー時に指摘されるミスを何度もしてきました。

対策として著者がやっていたことを紹介したいと思います。

  • 出力文字列に "debugprint: " のような決まり文句を必ず入れるようにしておく。

デバッグ完了後や、commit する直前などに、エディタ等の検索機能で "debugprint:" を検索し、消し忘れを消して回ることができます。

a = 1

print("Process Start ...")  # デバッグプリント用ではない、常に表示したいような出力には何もつけない

b = test1(a)

c = test2(b)

print("debugprint: ", c)    # デバッグプリント用の表示分には決まり文句をつける

d = test3(c)

e = test4(d)

print("debugprint: ", e)
  • gitを利用する場合であれば、デバッグプリント始める直前のコード commit または git add しておく

デバッグプリントによって追加した出力命令が、git diff (--cached) などで差分として出るようになるため、消し忘れに気付くことができます。

## この状態で commit または git add しておく
a = 1

b = test1(a)

c = test2(b)

d = test3(c)

e = test4(d)

## この状態で git diff (--cached) すると、print文が差分として表れる
a = 1

b = test1(a)

c = test2(b)

print("debugprint: ", c)

d = test3(c)

e = test4(d)

print("debugprint: ", e)
  • ログレベルを使い分ける

これができる環境や言語は限られていますが、仕組みづくりとしての対策ができます。
デバッグプリントによる出力を、いわゆるdebugレベルのログで実施していれば、消し忘れによる問題を軽減できます。

ログレベルについての解説は以下の記事が参考になりました。

エラーメッセージの活用

これも当たり前のことと言われてしまいそうですが、一応触れておきます。

デバッグプリントは手順通り地道に行えば時間はかかりますが、エラーメッセージを見ずともそのエラーの原因であるバグの特定まで至ることは基本的に可能です。

ただ、もしエラーメッセージが出ていて閲覧できるのであれば、それをデバッグプリントにおいても有効に活用することはできます。
具体的には、エラーの内容からバグの原因となっている処理内容をある程度推測することで、そのような処理を実施している部分までバグの範囲を絞り込むことができます。

Traceback (most recent call last):
  File "/tmp/main.py", line 2, in <module>
    import user_code
  File "/tmp/user_code.py", line 2, in <module>
    a["key"]
    ~^^^^^^^
KeyError: 'key'

[Execution complete with exit code 1]

上記はシンプルなPythonにおける例外が発生した例ですが、エラーの内容から辞書型の存在しないキーを参照したことが分かります。
すると、辞書型のキーを参照しているコード付近に、バグの原因がある可能性が高いと分かります。

その付近に対してデバッグプリントを始めれば、何も情報がない状態から始めるよりも、かなり手数を節約できます。

終わりに

ここまで長々と書いて感じたのが、
やはりテストをしっかり書いていれば後々楽できるんだなということと、
あとデバッガ使えたほうがいいんだろうなということです。

～終～

ともかく、今はかなり高度になったAIがコードを書いたりデバッグをしてくれる時代になりました。

そんな中こうしてデバッグプリントのやり方をまとめてみて、

  • 原因・要因になりうる候補の範囲を絞り込むこと
  • ある結論を出すために何を確認すべきで、それがどういう状態ならどういう結論になるか。を整理しておくこと
  • 同じ目標に至るとしても、より効率的・楽な方法を模索すること

このような、デバッグ以外の作業でも役立ちそうな考え方の重要性を、改めて認識することができました。
デバッグプリントやデバッガを使った人力デバッグをすることで、これらの考え方を実践して鍛えることができるのではないかと思っています。

そのためにわざわざ人力デバッグを実施すべきとは言いませんが、少なくとも著者は人力デバッグを経験してきて良かったと思っています。

とはいえAIが高性能になってきた今の時代、過去の常識や経験・実績に囚われすぎず、
何をAIに任せ、一方で何に人力で取り組んで時間を費やすか、を見極めてやり方を変えていく柔軟性が、AIと共存するうえで大事だと考えています。

今回デバッグプリントという、いまさらな題材で書かせていただきましたが、

  • 特殊な環境下で人力デバッグをしないといけない場合に向けて、
  • AIの時代だからこそデバッグプリントによる人力デバッグから何かしらの学びを得るために、

この記事が少しでも役に立てば幸いです。

よろしければ、前編と中編もご覧いただければと思います。
前編はこちら
中編はこちら

Discussion