dbt-coreにおけるOSS活動ことはじめその7 ~ デバッグの話 ~

本記事が目指すこと

• dbt-coreにおけるOSS活動を始めるにあたってやるべきこと、学びになったことを紹介する
  • 複数回に渡り連載する予定
    • これまでの投稿記事
      • dbt-coreにおけるOSS活動ことはじめ ~投稿記事まとめ~

注意

• 本記事は筆者が所属する会社と関係なく、個人の記事であることをご了承ください

背景

• 筆者は、ちゅらデータ株式会社に務める会社員であるが、就業時間中に職務としてのdbt-coreのOSS活動を始めた（OSS活動自体が初めての経験）
• CONTRIBUTING.mdには明示的に記載されてない部分があったため、それらの解説を含む

本編

これまでの記事では、dbt-coreにおけるOSS活動において、PRを出すまでに必要な手順を紹介した。
本記事では、開発時につまづいた際のデバッグの方法について、ドキュメントをベースにいくつか補足を加えて解説する。
CONTRIBUTING.mdのDebuggingには以下のように説明されている

1. The logs for a dbt run have stack traces and other information for debugging errors (in logs/dbt.log in your project directory).
2. Try using a debugger, like ipdb. For pytest: --pdb --pdbcls=IPython.terminal.debugger:pdb
3. Sometimes, it’s easier to debug on a single thread: dbt --single-threaded run
4. To make print statements from Jinja macros: {{ log(msg, info=true) }}
5. You can also add {{ debug() }} statements, which will drop you into some auto-generated code that the macro wrote.
6. The dbt “artifacts” are written out to the ‘target’ directory of your dbt project. They are in unformatted json, which can be hard to read. Format them with:

python -m json.tool target/run_results.json > run_results.json

上から順に解説する。

1.では、プロジェクトフォルダのlogs/dbt.logにdbt runの実行ログが記録されていることを説明している。ちなみに、正式名称はデバッグログファイル。デフォルトでは、すべてのDEBUGレベルのイベントに加えて、ログレベルやスレッド名などのコンテキスト情報が含まれる。これはdbt runだけでなく、dbt testやdbt seedといった別のdbtのコマンドでも同じファイルに実行ログが記録される。また、1回目実行時は新規で作成され、2回目以降は、ファイルの末尾にログが追加される。

• ログレベルの種類と変更方法（参考：Events and logs）
  • ログレベルは、全部で4種類(noneを除く)
    • debug, info, warn, error
  • デバッグログファイルと、コンソールに出力されるログ(stdout)のログレベルは異なる
    • デフォルトでは、前者はdebugレベル。後者はinfoレベル
  • ログレベルの変更方法（参考：log-level）
    • 両方のログレベルを変更する場合は、CLIのflagとして--log-levelで指定する
      • 例
        • dbt --log-level debug runで実行すると、デバッグログファイル、コンソール両方ともにdebugレベルで表示される
          • dbt --debug runやdbt -d runでも可能
    • デバッグログファイルのログレベルのみを変更する場合は、CLIのflagとして--log-level-fileで指定する
      • 例
        • dbt --log-level-file error runで実行すると、デバッグログファイルのみ'error'レベルで表示される
• デバッグログファイルのパスは以下の3つのいずれかの方法で変更できる(参考：log-path)
  1. CLIのflagとして--log-pathで指定する
     • 推奨(dbt1.5以降)
     • 例
       • dbt --log-path test_logs runを実行するとtest_logs/dbt.logにdbt runの実行ログが記録される
  2. 環境変数DBT_LOG_PATHで指定する
     • 推奨(dbt1.5以降)
     • 例
       • export DBT_LOG_PATH=test_logsを実行した後、dbt runを実行するとtest_logs/dbt.logにdbt runの実行ログが記録される
  3. dbt_project.ymlのlog-pathで指定する
     • 非推奨(dbt1.5以降。今後廃止予定)
     • 例
       • dbt_project.ymlにて以下のように記述した後、dbt runを実行するとtest_logs/dbt.logにdbt runの実行ログが記録される
         dbt_project.yml

         log-path: test_logs
         

2.では、ipdbを用いたデバッグについて説明している。ipdbとは、pdbというPython標準のデバッガを改良したもので、タブ補完、構文の強調表示、より優れたトレースバック、pdbモジュールと同じインターフェイスによるより優れたイントロスペクションなどの機能が備わっている。自身が改修したファイルやpytest実行時にブレークポイントを設けて一行ずつ実行したり、オブジェクトの中身を確認したりするときに用いると良い

• pdb,ipdbの違いや使い方について知りたい方は以下の記事を参考にすると良い

3.では、単一スレッドでデバッグする方法を述べている。dbtでは、同時に構築するモデルの数をマルチスレッドとして設定することができる。例えば、threads: 1では、dbt は 1 つのモデルのみの構築を開始し、それを終了してから次のモデルに進む。もしthreads: 8とすると、dbtは依存関係に違反することなく一度に最大8つのモデルを処理できることを意味する。設定方法は、dbtコマンド実行時に--threadsで指定するか、profiles.ymlで指定するかのいずれかである。一方、マルチスレッドを利用する際の考慮すべき点としては、BIツールがdbtと同じコンピューティングリソースを使用する場合、スレッド数を増やすとウェアハウスの負荷が増加ためクエリはdbtの実行中にキューに入れられる可能性がある。また、データベースで実行できる同時クエリの数によって構築できるモデルの数が制限される可能性がある。マルチスレッドにより発生するエラーか、それ以外かの原因を切り分けるためにも、デバッグの際には、シングルスレッドで実行する方法を提示しているようである（参考：Using threads）

4.では、Jinjaマクロから任意の変数を出力する方法を示している。{{ log(msg, info=true) }}を対象のマクロに記載する。第一引数のmsgには、ログに記録するメッセージ(変数など)を入れる。第二引数のinfoは、Trueだとログファイルと標準出力に吐き出され、Falseだとログファイルにのみ吐き出される。マクロから任意の変数を確認する際に用いる（参考：log）

5.では、マクロが作成した自動作成コードをデバッグする方法を紹介している。{{ debug() }}を利用することにより、コンパイルされたdbtマクロのコンテキストでiPythonデバッガーが開かれる。ただ、ここで利用しているデバッガーは、上記の2.で説明したipdbである。そのため詳細は割愛する（参考：About debug macro）

6.では、dbtの"artifacts"を読みやすい形でフォーマットする方法を紹介している。artifactsは、dbtコマンド実行時に自動作成されるもので、プロジェクトのリソース、構成、実行に関する詳細が記載される。具体的には、log_pathやprofiles_dirやproject_dirなどが記載されているため、意図した構成になっているかをデバッグの際に確認するときに用いれば良い（参考：dbt-artifacts）

他にも、mypyやflake8の無効化やCProfileに関するデバッグのTipsがAssorted development tipsには記載されている。

デバッグの際には、ぜひご活用いただきたい。

その他のデバッグTips

• 統合テストに関して
  • Makefileには、integrationの他にintegration-fail-fastのコマンドが用意されている。こちらの中身を確認すると、pytestのオプションとして-xを引き渡しているだけである。これは、最初に失敗したテストで終了するコマンドである。（参考資料：How to handle test failures）
  • 失敗したテストを明らかにし、その後失敗した特定のテストファイルごとに--pdbコマンドをつけてデバッグする方法がオススメ。

終わりに

ちゅらデータでは、クレイジーな仲間を募集しているでござる
データエンジニア、もしくはSE系からデータエンジニアになりたい方がいればぜひ、御仁の力量に応じたグレード（ジュニア/ミドル/シニア）にて、応募するでござる