PowerQueryのログフィルからクエリの実行時間を計算してみた

Excel上のPower Queryでの開発をしていて、実行時間を測定する方法が見当たらず、自作しました。 しかし、PowerBIをお使いの場合はクエリ診断が利用できるようです。Excelに閉じている場合でも、実行時間の測定の目的でPowerBIを利用することも考えられます。

処理は、Chris Webb's BI Blogにある構文解析¹を参考にさせていただき、次のような機能を足しました。 上記クエリ診断が提供する機能とは異なります。

• クエリの起動から終了までの時間を、ログの時刻情報から取得する
• 複数のクエリの実行を一つのログファイルに記録して、後から分離する（逐次実行のみ）

利用イメージ

結果として、次のように実行時間がリストされます。

この例では、2つのクエリ実行の開始時刻、終了時刻、所要時間が、分:秒の形式で表示されています。書式はExcelの書式設定で調整します。

RealStart	RealEnd	Duration
05:40.736	05:40.756	00:00.021
05:58.809	06:16.465	00:17.657

利用する手順は次のようになります。

クエリの実行

1. クエリのオプションで「トレースを有効にする」をチェック
2. 測定対象のクリエを実行する（複数の測定を行うときは、４秒以上の間隔を空けて実行する）
3. トレースを停止する

実行時間の計算

1. パラメータ "logfile" に生成されたトレースファイルのパスをセットする
2. このコード（クエリ）を実行する

コード実行前の準備

• logfileというテキスト型パラメータを作る。
• 測定対象のクエリを実行して生成されたログファイルのパスを値にセットする。Excelなら

「C:\Users\～\AppData\Local\Microsoft\Office\16.0\PowerQuery\Traces\EXCEL.9999.yyyy-mm-ddThh-mm-ss-999999.log」

のようになると思います。
このように、EXCEL で始まるログファイルを使用して、うまく解析できました。

コード

コードはPowerQueryで記述しています。
サブクエリと関数を使って記述しましたが、一つのクエリにまとめてあります。

let

ガード秒 = #duration(0, 0, 0, 4) meta [IsParameterQuery=true, Type="Duration", IsParameterQueryRequired=true],

QuantizedStart = let
    MinStart = List.Min(ログファイルをStartEndリスト化[Start]),
    bod = DateTime.From(DateTime.Date(MinStart)),
    Unit = ガード秒 / 2,
    result = bod + Unit * Number.RoundDown((MinStart - bod) / Unit)
in
    result,

Quantize = (dt as datetime) as number => 
    Number.RoundDown((dt - QuantizedStart) / (ガード秒 / 2)),

DeQuantize = (i as number, optional upper as nullable logical) as datetime => 
    QuantizedStart + (ガード秒 / 2) * (i + (if upper = null then 0 else 1)),

GetDuration = let
    ソース = (文字列 as text) => let
        Source = 文字列,
        #"Split Text" = Text.Split(Source, ","),
        selection = List.Select(#"Split Text", each Text.StartsWith(_, "Duration:")),
        #"Split Column by Delimiter" = Text.AfterDelimiter(List.First(selection), ":"),
        #"Parsed Time" = Duration.FromText(#"Split Column by Delimiter")
    in
        #"Parsed Time"
in
    ソース,

ログファイルをStartEndリスト化 = let
    Source = File.Contents(logfile),
    ソース = Table.FromColumns({Lines.FromBinary(Source,null,null,932)}),
    #"Extracted Text After Delimiter1" = Table.TransformColumns(ソース, {{"Column1", each Text.AfterDelimiter(_, ":", 1), type text}}),
    #"Parsed JSON" = Table.TransformColumns(#"Extracted Text After Delimiter1",{},Json.Document),
    #"Expanded {0}" = Table.ExpandRecordColumn(#"Parsed JSON", "Column1", {"Start", "Duration", "Action"}),
    #"Changed Type" = Table.TransformColumnTypes(#"Expanded {0}",{{"Start", type datetime}, {"Duration", type duration}}),
    End算出 = Table.AddColumn(#"Changed Type", "End", each [Start] + [Duration], type datetime),
    #"Reordered Columns" = Table.ReorderColumns(End算出,{"Start", "End", "Duration", "Action"})
in
    #"Reordered Columns",

    StartEndTable = Table.Buffer(ログファイルをStartEndリスト化),
    quantized = Table.TransformColumns(StartEndTable, {}, Quantize),
    #"Group by End" = Table.Group(quantized, {"End"}, {{"Start", each List.Min([Start]), type number}}),
    #"Group by Start" = Table.Group(#"Group by End", {"Start"}, {{"End", each List.Max([End]), type number}}),
    Separators = List.Numbers(-1, Quantize(List.Max(StartEndTable[End])) + 3),
    Seps = List.Buffer(Separators),
    res = Table.AddColumn(#"Group by Start", "Ranges", each List.Range(Seps, [Start] + 1, [End] - [Start] + 1), type list),
    #"Existing Ranges" = List.Union(res[Ranges]),
    exists = List.Buffer(#"Existing Ranges"),
    #"Converted to Table" = Table.FromList(Seps, Splitter.SplitByNothing(), type table [range = number]),
    #"Marked Running Range" = Table.AddColumn(#"Converted to Table", "running", each List.Contains(exists, [range]), type logical),
    #"Added Index" = Table.AddIndexColumn(#"Marked Running Range", "index", 0, 1, Int64.Type),
    Start認定 = Table.AddColumn(#"Added Index", "Start", each [running] and not #"Added Index"{[index=[index]-1]}?[running]?, type logical),
    End認定 = Table.AddColumn(Start認定, "End", each [running] and not Start認定{[index=[index]+1]}?[running]?, type logical),
    #"Removed Columns" = Table.RemoveColumns(End認定,{"running", "index"}),
    境界値のみ = Table.SelectRows(#"Removed Columns", each [Start] or [End]),
    #"Added Custom1" = Table.AddColumn(境界値のみ, "EndIndex", each if [End] then [range] else null, type nullable number),
    #"Filled Up" = Table.FillUp(#"Added Custom1",{"EndIndex"}),
    #"Filtered End Rows" = Table.SelectRows(#"Filled Up", each ([Start] = true)),
    #"Removed Columns3" = Table.RemoveColumns(#"Filtered End Rows",{"Start", "End"}),
    #"Renamed Columns" = Table.RenameColumns(#"Removed Columns3",{{"range", "StartIndex"}}),
    #"Added Custom" = Table.AddColumn(#"Renamed Columns", "RealData", each let EndRange = DeQuantize([EndIndex], true), StartRange = DeQuantize([StartIndex]) in Table.SelectRows(StartEndTable, each [Start] >= StartRange and [End] < EndRange), type table),
    #"Added RealStart" = Table.AddColumn(#"Added Custom", "RealStart", each List.Min([RealData][Start]), type datetime),
    #"Added RealEnd" = Table.AddColumn(#"Added RealStart", "RealEnd", each List.Max([RealData][End]), type datetime),
    #"Removed Other Columns" = Table.SelectColumns(#"Added RealEnd",{"RealStart", "RealEnd"}),
    #"Inserted Time Subtraction" = Table.AddColumn(#"Removed Other Columns", "Duration", each [RealEnd] - [RealStart], type duration)
in
    #"Inserted Time Subtraction"

カスタマイズ

測定対象のクエリを実行する際の最小時間間隔は、コード内の「ガード秒」に設定されています（4秒）。時間間隔をより長く取れるならば、この値を大きくすることで、解析時の計算量を低減することができます。

試した環境

Windows 10 Pro 22H2 64bit
EXCEL Microsoft 365 バージョン 2301 64bit
Power Query 2.112.523.0 64 ビット

1. 当初は@tanuki_phoenix さんの記事の手順を参考にさせていただいていました。 ↩