Event logger#

The event logger allows query completion events and all related Starburst Enterprise platform (SEP) information to be logged into a PostgreSQL database.

Note

Event logger requires a valid Starburst Enterprise license.

Event logger data is used to provide cluster performance history, including:

  • CPU and memory usage

  • Cluster size

  • Query load

In addition to cluster performance data, the event logger also provides query history and performance data. Once the event logger is running, use the Insights user interface to view cluster and query data.

Requirements#

  • PostgreSQL database, version 9.6 or higher

  • Network connectivity between the coordinator and the PostgreSQL server

Connectivity between SEP and the PostgreSQL database can be verified on the coordinator.

You can use ping to verify the hostname:

$ ping postgresql.example.com

You can use telnet with the hostname and port of the database to confirm PostgreSQL is listening on the configured port.

$ telnet postgresql.example.com:5432

Installation and configuration#

The event logger is implemented as a event listener implementation and can be enabled by creating a configuration file called etc/event-listener.properties on the coordinator. The name needs to be set to event-logger. The configuration includes the JDBC connection URL with hostname, port and database name as well as username and password for accessing the PostgreSQL database.

event-listener.name=event-logger
jdbc.url=jdbc:postgresql://postgresql.example.com:5432/event_logger
jdbc.user=test_psql
jdbc.password=test12

You must have sufficient rights to create tables and insert data in the configured schema.

Note

It is not good practice to use the public schema. Configure the user to use a different schema by default. See the PostgreSQL documentation for details.

You must restart the cluster after creating the configuration files. At first usage, the table completed_queries is automatically created in the PostgreSQL database.

Once the table is created, logging is activated and running.

Instructions for configuring event logger for Kubernetes deployments are available in the Kubernetes documentation.

Logged information#

Information from processing queries is logged in multiple tables and the contained fields. Details are documented in the following sections.

Completed queries#

A row is created in the completed_queries table for each submitted query. It captures everything that SEP emits – query, user, metadata, stats, performance related attributes, resource consumption, start time, end time, and much more:

Columns of the completed_queries table#

Column

Description

query_id

Unique identifier of the query

catalog

Session catalog

schema

Session schema

principal

Identity used to authenticate to SEP

user_agent

User agent that submitted the query

client_info

Information about the client submitting the query

source

Client tool or driver used to execute query

environment

Name of the SEP environment name

remote_client_address

Address of the client that submitted the query

server_version

Version of SEP that executed the query

usr

Identity used for authorization and access control

usr_groups

The groups the user executing the query belongs to, as an array of strings

query_state

State of the query when logged

query

Full SQL statement of the submitted query

query_plan

Full explain plan of the submitted query, including costs for each stage. Identical to the output from EXPLAIN ANALYZE <query>.

total_rows

Sum of all rows used in the query input

total_bytes

Sum of all bytes used in the query input

output_rows

Number of filtered rows on query output

output_bytes

Number of filtered bytes on query output

written_rows

Number of inserted rows

written_bytes

Number of bytes of inserted rows

cpu_time_ms

Total accumulated CPU time across threads and workers

wall_time_ms

Elapsed time for query pressing as measured by a wall clock in ms

queued_time_ms

Time spent between query submission and the beginning of query planning in ms

peak_user_memory_bytes

Maximum amount of memory directly tied to query resources used by a query at one time

peak_total_non_revocable_memory_bytes

Maximum amount of memory used at one time which is not eligible to be spilled to disk

peak_task_user_memory

Maximum amount of user memory reserved at one time by one task

peak_task_total_memory

Maximum amount of user and system memory reserved at one time by one task, values are impacted by the memory management configurations

physical_input_bytes

Number of uncompressed bytes read from source

physical_input_rows

Number of rows read from source

internal_network_bytes

Number of bytes of data exchanged between nodes during query execution

internal_network_rows

Number of rows of data exchanged between nodes during query execution

cumulative_memory

Integral of memory reservation with respect to time, giving units of memory x time. Dividing this figure by the execution time approximates the average memory reservation during query execution.

completed_splits

Total number of splits completed by the query

plan_node_stats_and_costs

Table statistics for each source table, as well as estimates for the CPU, memory, and network I/O for each stage of the query plan and each operator in each plan node. Operator costs are denoted by their plan node ID, as indicated from the operator_summaries column. Cost values do not represent any actual unit, but are numbers that are used to compare the relative costs between plan nodes, allowing the optimizer to choose the best plan for executing a query.

stage_gc_statistics

Information about JVM garbage collection tasks and time spent in GC for each query stage

cpu_time_distribution

Min, max, average, and percentiles for reserved CPU time per task for each query stage. Can be useful for identifying skew in a query.

operator_summaries

Information about every operator, including operator type (TableScan, Aggregation, Join, etc.) and resources used (CPU time, network I/O, memory reserved, etc.) invoked at each stage of the query.

resource_waiting_time

Time spent waiting for sufficient resources before query execution in ms

analysis_time

Time spent reading the metadata and checking the query for semantic errors in ms

execution_time

Total time a query spent in the execution phase in ms

create_time

Timestamp from when query was received

end_time

Timestamp when results were finished being consumed by the client

accessed_metadata

List of catalogs, schemas, tables, and columns read. Query must be a SELECT query that returned more than 0 rows.

planning_time

Time spent creating and optimizing the query plan in ms

scheduled_time

Total time a query’s tasks were scheduled on a thread to run in ms

failure_info

Information about a query’s failure reason (if applicable), as a JSON formatted string.

query_type

The type of query. Possible values are the ones enumerated for the queryType selector rule for Resource groups.

update_type

The type of update the query performed (e.g. CREATE TABLE); this column is null for SELECT queries.

Query tables#

For every table referenced by a query, zero, one or more rows with information about the accessed table is created in the query_tables table. The query_id defines the relationship to the query in the completed_queries table.

Columns of the query_tables table#

Column

Description

query_id

Unique identifier of the query

catalog_name

Name of the catalog containing the queried table

schema_name

Name of the schema containing the queried table

table_name

Name of the queried table

physical_bytes

Number of bytes read or written

physical_rows

Number of rows read or written

is_output

Boolean flag indicating whether the table was written to (true) or read from (false)

Analyzing the event log#

To analyze and query the event log, you can create a catalog with the PostgreSQL connector using the same JDBC connection parameters. This allows you to use the Trino CLI, or any other application connected to the catalog to create queries, dashboards, perform ad hoc analysis and more.

Example use cases:

  • measure query performance numbers and trends

  • understand impact of different cluster configurations

  • enable cluster workload management and resource consumption

Example#

Generate event logger data by running a query.

presto> CREATE TABLE memory.default.country AS
        SELECT n.name nation_name, r.name region_name
        FROM delta.sf1.nation n JOIN delta.sf1.region r ON n.regionkey = r.regionkey;
CREATE TABLE: 25 rows

Query 20201209_021306_00003_qsyab, FINISHED, 1 node
Splits: 68 total, 68 done (100.00%)
3.34 [35 rows, 5.35KB] [10 rows/s, 1.6KB/s]

Event logger data is written to the completed_queries table in the PostgreSQL database.

In the following example, the catalog file is named event_logger.properties and the public schema contains the completed_queries table. The query_id from the execution is used to locate the correct record. The output in the following example has been trimmed.

presto> SELECT *
        FROM event_logger.public.completed_queries
        WHERE query_id = '20201209_021306_00003_qsyab';
-[ RECORD 1 ]-------------------------+---------------------------------------
query_id                              | 20201209_021306_00003_qsyab
catalog                               | NULL
schema                                | NULL
principal                             | demo
user_agent                            | StatementClientV1/345
client_info                           | NULL
source                                | presto-cli
environment                           | demo
remote_client_address                 | 127.0.0.1
server_version                        | 350-e
usr                                   | demo
query_state                           | FINISHED
query                                 | CREATE TABLE memory.default.country AS SELECT n.name nation_name, r.name region_name FROM delta.sf1.nation n JOIN delta.sf1.region r ON n.regionkey = r.regionkey
query_plan                            | Fragment 0 [COORDINATOR_ONLY]
                                      |     CPU: 43.24ms, Scheduled: 60.81ms, Input: 2 rows (81B); per task: avg.: 2.00 std.dev.: 0.00, Output: 1 row (9B)
                                      |     Output layout: [rows]
                                      | ...
total_rows                            | 35
total_bytes                           | 5477
output_rows                           | 1
output_bytes                          | 9
written_rows                          | 25
written_bytes                         | 597
cpu_time_ms                           | 392
wall_time_ms                          | 3342
queued_time_ms                        | 10
peak_user_memory_bytes                | 387318
peak_total_non_revocable_memory_bytes | 387318
peak_task_user_memory                 | 387318
peak_task_total_memory                | 387318
physical_input_bytes                  | 5274
physical_input_rows                   | 30
internal_network_bytes                | 933
internal_network_rows                 | 32
cumulative_memory                     | 7.7086698E7
completed_splits                      | 68
plan_node_stats_and_costs             | {"stats":{},"costs":{}}
stage_gc_statistics                   | [{"stageId":0,"tasks":1,"fullGcTasks":0,...
cpu_time_distribution                 | [{"stageId":0,"tasks":1,"p25":25,"p50":25,...
operator_summaries                    | [{"stageId":0,"pipelineId":0,"operatorId":0,..
resource_waiting_time                 | 783
analysis_time                         | 783
execution_time                        | 2559
create_time                           | 2020-12-09 02:13:06.140000 UTC
end_time                              | 2020-12-09 02:13:09.482000 UTC
accessed_metadata                     | [{"catalogName":"delta","schema":"sf1","table":"nation","columns":["name","regionkey"],...
failure_info                          | NULL
update_type                           | CREATE TABLE
planning_time                         | 1711
scheduled_time                        | 1263

The tables accessed by the query are recorded in the query_tables table and can be identified using the same query_id.

presto> SELECT *
        FROM event_logger.public.query_tables
        WHERE query_id = '20201209_021306_00003_qsyab';
          query_id           | catalog_name | schema_name | table_name | physical_bytes | physical_rows | is_output
-----------------------------+--------------+-------------+------------+----------------+---------------+-----------
 20201209_021306_00003_qsyab | memory       | default     | country    |            597 |            25 | true
 20201209_021306_00003_qsyab | delta        | sf1         | region     |           1691 |             5 | false
 20201209_021306_00003_qsyab | delta        | sf1         | nation     |           3583 |            25 | false
(3 rows)