🤖

dbt macro tips advent calendar 2022 day 6 -doとlog

2022/12/06に公開

dbt

tech

便利なデータ変換ツールである dbt の中のmacroに関するtipsを書いていく dbt macro tips Advent Calendar 2022 6日目です。

do

先日のおさらいですが、 do　というものが出てきました。
これを説明するためには、今まで暗黙的に使ってきた {{ }},{% %}とmacroの戻り値についてもう少し詳しく説明し始める必要があります。

{{ }} というのは、カッコ内に書かれた内容を展開する構文になります。
一方で、{% %} というのは制御文というもので、何かしらの制御のためのタグが一緒に使用されます。(if,else,set,...)

そして、macroには戻り値というものがあります。これは通常では、macroの描画結果がそれにあたります。
例えば、macro noop() を実行した結果の値=戻り値を描画したい場合は
{{ noop() }} とかけばよいのです。

同様のことを、変数を介して行おうとするとこうなります。

{%- set ret = noop() %}
{{ ret }}

これは、macro noop() の戻り値を一旦変数 ret に保存して、その保存した結果を参照して展開しています。

さて、ここで、「別に noop() の結果はいらないのだけど、noop() の実行だけはしておきたい」場合はどうすればいいのでしょう。
それを実現するのが do となります。

log

さて、listのappend関数についてもっと詳しく説明してもいいのですが、ここでは log というmacroを使って続きの説明をしようと思います。

さきほど、 do は macro(もしくは関数)の実行だけはしておきたいけど、その結果はいらないという場合に使うと言う話をしましたが、コレはどういうときに起きるでしょうか？
答えは、macroが副作用を持つときです。
副作用というのは、本来、macroは計算結果や描画結果を返すことが目的ですが、その過程で周囲の状態を変化させてしまうことを意味します。
例えば、 dbtの実行ログに特定の文字列を表示する ということを実現するmacroがあったとしたら、それは副作用を持つことになります。
さて、ぶっちゃけるとこの副作用を持つmacroがlog となります。

macro/noop.sql

{%- macro noop() %}
{%- set numbers = [25, 35, 22, 11] %}
{%- do log('numbers is '~numbers) %}
{%- endmacro %}

models/noop.sql

{% set ret = noop() %}
{{ ret }}
select 1

このような状態で、描画を実行してログを確認すると以下のようになります。

$ dbt compile --select noop           
02:20:06  Running with dbt=1.3.1
02:20:06  Found 3 models, 4 tests, 0 snapshots, 0 analyses, 290 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
02:20:06  
02:20:06  Concurrency: 4 threads (target='dev')
02:20:06  
02:20:06  Done.
$ cat logs/dbt.log | grep 'numbers is'
02:20:06.302402 [debug] [MainThread]: numbers is [25, 35, 22, 11]
02:20:06.502220 [debug] [Thread-1 (]: numbers is [25, 35, 22, 11]

noop()のmacroをもう少し変更します。

macro/noop.sql

{%- macro noop() %}
{%- set numbers = [25, 35, 22, 11] %}
{%- do log('numbers is '~numbers,info=True) %}
{%- endmacro %}

logの関数に対してキーワード引数 info=True を与えました。
この状態で実行すると以下のようになります。

$ dbt compile --select noop           
02:24:46  Running with dbt=1.3.1
02:24:46  numbers is [25, 35, 22, 11]
02:24:46  Found 3 models, 4 tests, 0 snapshots, 0 analyses, 290 macros, 0 operations, 0 seed files, 0 sources, 0 exposures, 0 metrics
02:24:46  
02:24:46  Concurrency: 4 threads (target='dev')
02:24:46  
02:24:46  numbers is [25, 35, 22, 11]
02:24:46  Done. 
$ cat logs/dbt.log | grep 'numbers is'
02:24:46.625232 [info ] [MainThread]: numbers is [25, 35, 22, 11]
02:24:46.843828 [info ] [Thread-1 (]: numbers is [25, 35, 22, 11]

info=Trueを与えると、dbt.log だけでなく、実行時の出力にも含まれるようになりました。
logを使用することで、dbtの実行履歴に対して介入するすべを得ることができたので、macroを作るときのデバッグ等で色々と捗ることになるでしょう。

ところで、logのところでこう思った方はいませんか。「なんで２回でてるの？」
7日目はdbt特有の話の手始めとして、dbtの動作モードについて説明します。

do

log

Discussion