7.3.3. トレースログの出力#
7.3.3.1. 概要#
バージョン 13.0.9 で追加.
トレースログは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_logがyesなら、"trace_log": {...}が増えます。ここにはキー・バリューのペアが2つあります。
キー |
説明 |
|---|---|
|
トレースログエントリーの各カラムのメタデータの配列 |
|
トレースログエントリーの配列 |
columnsの各要素は以下のキー・バリューのペアを持っています。
キー |
説明 |
|---|---|
|
カラム名 |
logsの各要素は次の要素を持っています。
インデックス |
名前 |
説明 |
|---|---|---|
0 |
|
実行レベル。 1つの実行レベルで複数のトレースログが出力されることがあります。1つの実行レベルに複数のトレースログがある場合、同じ実行レベル内のトレースログでは |
1 |
|
同一実行レベル中でのシーケンス番号。 この値が |
2 |
|
このトレースログの名前。 |
3 |
|
このトレースログの値。 この値の型は次のどれか1つです。
|
4 |
|
対象コマンドが実行されてからの実行時間。単位はナノ秒。 |
logsはフラット配列ですが、depthとsequenceを使うと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メタデータをチェックするトレースログ用のレコードバッチを検出できます。
レコードバッチ中の各カラムの説明は次の通りです。
名前 |
説明 |
|---|---|
|
実行レベル。 1つの実行レベルで複数のトレースログが出力されることがあります。1つの実行レベルに複数のトレースログがある場合、同じ実行レベル内のトレースログでは |
|
同一実行レベル中でのシーケンス番号。 この値が |
|
このトレースログの名前。 |
|
このトレースログの値。 この値の型は次のどれか1つです。
|
|
対象コマンドが実行されてからの実行時間。単位はナノ秒。 |
例：
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
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