7.3.3. トレースログの出力#

7.3.3.1. 概要#

バージョン 13.0.9 で追加.

注釈

この機能は実験的な機能です。現状、この機能はまだ安定していません。

コマンドバージョン 3 以降を指定する必要があります。

トレースログはPostgreSQLのEXPLAIN (ANALYZE, VERBOSE)と似た情報です。これは次のような情報を含みます。

  • 何が実行されたか

  • どのインデックスが使われたか

  • 各操作にどのくらい時間がかかったか

  • 内部的にどんな値が使われたか

  • ...

現時点ではトレースログに十分な情報が含まれていないかもしれません。なぜならこの機能はまだ実験的だからです。もしより詳細な情報が欲しい場合は、あなたのユースケースと一緒にGitHubのissueで報告してください。

7.3.3.2. 使い方#

output_trace_logとしてyesを指定するとトレースログを取得できます。コマンドバージョン3を指定する必要もあります。

コマンドラインスタイル:

select ... --output_trace_log yes --command_version 3

URIスタイル:

/d/select?...&output_trace_log=yes&command_version=3

7.3.3.3. フォーマット#

トレースログは出力形式にJSONあるいはApache Arrowを使っているときだけ有効になります。もし、出力形式を指定していない場合は、デフォルトでJSONが使われます。

7.3.3.3.1. JSON#

次のようにして明示的に出力形式としてJSONを指定できます。

コマンドラインスタイル:

select ... --output_trace_log yes --command_version 3 --output_format json

URIスタイル:

/d/select.json?...&output_trace_log=yes&command_version=3

あるいは

/d/select?...&output_trace_log=yes&command_version=3&output_format=json

出力形式としてJSONを指定したときに出力構造は次の通りです。

{
  "header": {},
  "trace_log": {
    "columns": [
      {"name": "depth"},
      {"name": "sequence"},
      {"name": "name"},
      {"name": "value"},
      {"name": "elapsed_time"}
    ],
    "logs": [
      [1, 0, "ii.select.input", "Hello", 100],
      [2, 0, "ii.select.exact.n_hits", 2, 200],
      [1, 1, "ii.select.n_hits", 2, 210]
    ],
  ],
  "body": []
}

output_trace_logyesなら、"trace_log": {...}が増えます。ここにはキー・バリューのペアが2つあります。

キー

説明

columns

トレースログエントリーの各カラムのメタデータの配列

logs

トレースログエントリーの配列

columnsの各要素は以下のキー・バリューのペアを持っています。

キー

説明

name

カラム名

logsの各要素は次の要素を持っています。

インデックス

名前

説明

0

depth

実行レベル。

1つの実行レベルで複数のトレースログが出力されることがあります。1つの実行レベルに複数のトレースログがある場合、同じ実行レベル内のトレースログではsequenceの値が順に1ずつ増えます。

1

sequence

同一実行レベル中でのシーケンス番号。

この値が0の場合は新しい実行レベルが始まったことを示しています。

2

name

このトレースログの名前。

3

value

このトレースログの値。

この値の型は次のどれか1つです。

  • 整数

  • 文字列

4

elapsed_time

対象コマンドが実行されてからの実行時間。単位はナノ秒。

logsはフラット配列ですが、depthsequenceを使うとPostgreSQLのEXPLAIN (ANALYZE, VERBOSE)のようにツリーとしてフォーマットできるかもしれません。今後、Groongaにそのようにするオプションを追加したり、そのようなことをするツールを提供するかもしれません。

例:

{
  "header": {
    "return_code": 0,
    "start_time": 0.0,
    "elapsed_time": 0.0
  },
  "trace_log": {
    "columns": [
      {
        "name": "depth"
      },
      {
        "name": "sequence"
      },
      {
        "name": "name"
      },
      {
        "name": "value"
      },
      {
        "name": "elapsed_time"
      }
    ],
    "logs": [
      [
        1,
        0,
        "ii.select.input",
        "Thas",
        0
      ],
      [
        1,
        1,
        "ii.select.operator",
        "or",
        1
      ],
      [
        2,
        0,
        "ii.select.exact.n_hits",
        0,
        2
      ],
      [
        2,
        0,
        "ii.select.fuzzy.input",
        "Thas",
        3
      ],
      [
        2,
        1,
        "ii.select.fuzzy.input.actual",
        "that",
        4
      ],
      [
        2,
        2,
        "ii.select.fuzzy.input.actual",
        "this",
        5
      ],
      [
        2,
        3,
        "ii.select.fuzzy.n_hits",
        2,
        6
      ],
      [
        1,
        2,
        "ii.select.n_hits",
        2,
        7
      ],
      [
        1,
        0,
        "ii.select.input",
        "ere",
        8
      ],
      [
        1,
        1,
        "ii.select.operator",
        "or",
        9
      ],
      [
        2,
        0,
        "ii.select.exact.n_hits",
        2,
        10
      ],
      [
        1,
        2,
        "ii.select.n_hits",
        2,
        11
      ]
    ]
  },
  "body": {
    "n_hits": 2,
    "columns": [
      {
        "name": "content",
        "type": "ShortText"
      },
      {
        "name": "_score",
        "type": "Float"
      }
    ],
    "records": [
      [
        "This is a pen",
        1.0
      ],
      [
        "That is a pen",
        1.0
      ]
    ]
  }
}

7.3.3.3.2. Apache Arrow#

次のようにすると明示的に出力形式としてApache Arrowを指定できます。

コマンドラインスタイル:

select ... --output_trace_log yes --command_version 3 --output_format apache-arrow

URIスタイル:

/d/select.arrows?...&output_trace_log=yes&command_version=3

あるいは

/d/select?...&output_trace_log=yes&command_version=3&output_format=apache-arrow

出力形式がApache Arrowのときの出力構造は次の通りです。

----
Apache Arrow record batch (stream format)
Metadata:
  GROONGA:data_type: metadata
----
----
Apache Arrow record batch (stream format)
Metadata:
  GROONGA:data_type: trace_log
Schema:
  depth: uint16
  sequence: uint16
  name: string
  value: dense_union<0: uint32=0, 1: string=1>
  elapsed_time: uint64
----
Apache Arrow record batch (stream format)
Metadata:
  GROONGA:n_hits: N
----

2番目のレコードバッチがトレースログです。GROONGA:data_typeメタデータをチェックするトレースログ用のレコードバッチを検出できます。

レコードバッチ中の各カラムの説明は次の通りです。

名前

説明

depth

実行レベル。

1つの実行レベルで複数のトレースログが出力されることがあります。1つの実行レベルに複数のトレースログがある場合、同じ実行レベル内のトレースログではsequenceの値が順に1ずつ増えます。

sequence

同一実行レベル中でのシーケンス番号。

この値が0の場合は新しい実行レベルが始まったことを示しています。

name

このトレースログの名前。

value

このトレースログの値。

この値の型は次のどれか1つです。

  • 整数

  • 文字列

elapsed_time

対象コマンドが実行されてからの実行時間。単位はナノ秒。

例:

depth: uint16
sequence: uint16
name: dictionary<values=string, indices=int16, ordered=0>
value: dense_union<0: uint32=0, 1: string=1>
elapsed_time: uint64
-- metadata --
GROONGA:data_type: trace_log
	   depth	sequence	        name	        value	elapsed_time
	(uint16)	(uint16)	(dictionary)	(dense_union)	    (uint64)
 0	       1	       0	ii.select.input	Thas         	           0
 1	       1	       1	ii.select.operator	or           	           1
 2	       2	       0	ii.select.exact.n_hits	            0	           2
 3	       2	       0	ii.select.fuzzy.input	Thas         	           3
 4	       2	       1	ii.select.fuzzy.input.actual	that         	           4
 5	       2	       2	ii.select.fuzzy.input.actual	this         	           5
 6	       2	       3	ii.select.fuzzy.n_hits	            2	           6
 7	       1	       2	ii.select.n_hits	            2	           7
 8	       1	       0	ii.select.input	ere          	           8
 9	       1	       1	ii.select.operator	or           	           9
10	       2	       0	ii.select.exact.n_hits	            2	          10
11	       1	       2	ii.select.n_hits	            2	          11