FireDucksのトレースのとりかた

FireDucksには,read_csv や groupby, sort などのそれぞれの処理がどれくらいの時間がかかったかを記録するトレース機能があります. この記事ではトレース機能の使い方を紹介します.

トレースファイルの出力と表示

トレース機能を使うには,特にプログラムを修正する必要はありません. 以下のように環境変数を設定して実行するだけでトレース機能を利用することができます.

$ FIREDUCKS_FLAGS="--trace=3" python -mfireducks.pandas your_program.py

環境変数を設定してプログラムを実行すると,プログラムを実行したディレクトリに trace.json というファイルが出来上がります. このファイルがトレースファイルです.

トレースファイルを表示するためには,トレースビューアー機能を有するウェブブラウザである Microsoft Edge もしくは Google Chrome どちらかを用います.Microsoft Edge であれば edge://tracing,Google Chrome であれば chrome://tracing とアドレスバーに入力するとトレースビューアーを起動することができます.

以下の画像は,Microsoft Edge でトレースビューアーを起動した様子です.

Edge TraceViewer

Load ボタンをクリックして,トレースファイルを開くと,プログラムの実行トレースがグラフィカルに表示されます. 以下の画像は,こちらの記事で紹介した polars-tpch benchmark の1クエリの実行トレースです.

TPCH Q01 Trace

top と表示されているのが,プログラム全体(正しくは import fireducks.pandas をしてからプログラムが終了するまで)の時間です.その下では fireducks.core.evaluate と大きく2つのブロックにわかれています.これは,fireducks の遅延評価が2回発生していることを意味しています.polars-tpch benchmark の実行では,parquetファイルの読み込みとクエリの実行とを明示的に分けて計測しています.そのため,遅延評価が2つにわかれています.

前半の評価では fireducks.read_parquet_with_metadata という parquet の読み込み処理だけが実行時間を占めていることがわかります.また,マウス操作でズームインすることで,以下のように後半のクエリの実行時間の内訳を詳しくみることもできます.

TPCH Q01 Trace Query Detail

トレースファイル名の変更

デフォルトのトレースファイル名は trace.json でしたが,以下のように --trace-file=foo.json といったように任意のファイル名を設定することが可能です.

$ FIREDUCKS_FLAGS="--trace=3 --trace-file=foo.json" python -mfireducks.pandas your_program.py

標準エラーへのトレースサマリの出力

トレースファイルを出力してウェブブラウザで表示する方法を紹介しましたが,各処理の時間の内訳だけを表示するのであれば,標準エラーにサマリ情報を表示することもできます.

サマリの表示方法は,先述のトレースファイル名の変更と同じオプションを用います.ファイル名ではなく --trace-file=- と指定します.

$ FIREDUCKS_FLAGS="--trace=3 --trace-file=-" python -mfireducks.pandas your_program.py

先の例で用いた polars-tpch benchmark のクエリでの実行例です. 各処理の実行順などの詳細はわかりませんが,実行時間のサマリを確認することができます.

elapsed            6.071 sec
kernels            5.963 sec  98.22%      101
fallbacks          0.000 sec   0.00%        0
                                        duration sec ratio     count
== kernel ==
fireducks.read_parquet_with_metadata       5.453   89.83%          1
fireducks.filter                           0.293    4.83%          1
fireducks.groupby_agg                      0.089    1.46%          1
fireducks.le.vector.scalar                 0.051    0.83%          1
fireducks.mul.vector.vector                0.042    0.69%          2
fireducks.rsub.vector.scalar               0.023    0.38%          1
fireducks.radd.vector.scalar               0.009    0.15%          1
fireducks.sort_values                      0.002    0.03%          1
fireducks.read_parquet_metadata            0.001    0.02%          1
fireducks.project                          0.000    0.00%          8
== fallback ==
== other ==
top                                        6.071  100.00%          1
create_mlir_func                           0.001    0.02%          3
import pandas                              0.000    0.00%          2
fire.get_string                            0.000    0.00%         22

おわりに

FireDucks でのトレース機能の使い方を紹介しました.

FireDucks を利用していると,なぜか遅くなったということがあるかもしれません. その場合は,この記事を参考にトレースをとってみると,遅くなった原因の処理を見つけられるかもしれません.

トレース機能も使って FireDucks を使いこなしていただけると幸いです.