7.3.3. Output trace log#
7.3.3.1. Summary#
New in version 13.0.9.
Note
This is an experimental feature. Currently, this feature is still not stable.
This feature requires Command version 3 or later.
Trace log is similar information to PostgreSQL’s EXPLAIN (ANALYZE, VERBOSE)
information. It includes the followings:
What was executed?
Which index was used?
How long did the operation take?
What value was used internal?
…
Trace log contents may be insufficient for now because this feature is still experimental. If you want more information, please report it to the GitHub issue with your use case.
7.3.3.2. Usage#
You can get trace log by specifying yes as output_trace_log. You
also need to specify 3 as Command version.
Command line style:
select ... --output_trace_log yes --command_version 3
URI style:
/d/select?...&output_trace_log=yes&command_version=3
7.3.3.3. Format#
Trace log is available only when you use JSON or Apache Arrow Output format. If you don’t specify output format, JSON is used by default.
7.3.3.3.1. JSON#
You can specify JSON output format explicitly like the followings:
Command line style:
select ... --output_trace_log yes --command_version 3 --output_format json
URI style:
/d/select.json?...&output_trace_log=yes&command_version=3
or
/d/select?...&output_trace_log=yes&command_version=3&output_format=json
Here is an output structure for JSON output format:
{
"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": []
}
If output_trace_log is yes, "trace_log": {...} is added. It has
2 key-value pairs:
Key |
Description |
|---|---|
|
An array of column metadata for each trace log entry |
|
An array of trace log entries |
Each columns element has the following key-value pairs:
Key |
Description |
|---|---|
|
The name of column |
Each logs element has the following elements:
Index |
Name |
Description |
|---|---|---|
0 |
|
The execution level. Multiple trace logs may be outputted for one execution level. If there are
multiple trace logs for one execution level, |
1 |
|
The sequence number in the same execution level. If this is |
2 |
|
The name of this trace log. |
3 |
|
The value of this trace log. The value type must be one of the followings:
|
4 |
|
The elapsed time since the command is started. Unit is nano second. |
logs is a flat array but it may be able to format as a tree like
PostgreSQL’s EXPLAIN (ANALYZE, VERBOSE) output based on depth and
sequence. Groonga may have an option to do it in the future or we
may provide a tool for it.
Example:
{
"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#
You can specify Apache Arrow output format explicitly like the followings:
Command line style:
select ... --output_trace_log yes --command_version 3 --output_format apache-arrow
URI style:
/d/select.arrows?...&output_trace_log=yes&command_version=3
or
/d/select?...&output_trace_log=yes&command_version=3&output_format=apache-arrow
Here is an output structure for Apache Arrow output format:
----
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
----
The second record batch is a trace log. You can check
GROONGA:data_type metadata to detect a record batch for trace log.
Here is descriptions of each column of the record batch:
Name |
Description |
|---|---|
|
The execution level. Multiple trace logs may be outputted for one execution level. If there are
multiple trace logs for one execution level, |
|
The sequence number in the same execution level. If this is |
|
The name of this trace log. |
|
The value of this trace log. The value type must be one of the followings:
|
|
The elapsed time since the command is started. Unit is nano second. |
Example:
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