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

columns

An array of column metadata for each trace log entry

logs

An array of trace log entries

Each columns element has the following key-value pairs:

Key

Description

name

The name of column

Each logs element has the following elements:

Index

Name

Description

0

depth

The execution level.

Multiple trace logs may be outputted for one execution level. If there are multiple trace logs for one execution level, sequence is incremented for each trace logs in the same execution level.

1

sequence

The sequence number in the same execution level.

If this is 0, it shows that new execution level is started.

2

name

The name of this trace log.

3

value

The value of this trace log.

The value type must be one of the followings:

  • Integer

  • String

4

elapsed_time

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

depth

The execution level.

Multiple trace logs may be outputted for one execution level. If there are multiple trace logs for one execution level, sequence is incremented for each trace logs in the same execution level.

sequence

The sequence number in the same execution level.

If this is 0, it shows that new execution level is started.

name

The name of this trace log.

value

The value of this trace log.

The value type must be one of the followings:

  • Integer

  • String

elapsed_time

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
	(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