Examining Errors Generated By ClickHouse

Log of query execution

Controlled by session level setting send_logs_level Possible values: ‘trace’, ‘debug’, ‘information’, ‘warning’, ‘error’, ‘fatal’, ‘none’ Can be used with clickhouse-client in both interactive and non-interactive mode.

clickhouse-client -mn --send_logs_level='trace' --query "SELECT sum(number) FROM numbers(1000)"

Result;

[instance-1] 2022.07.31 20:19:48.661800 [ 5723 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Debug> executeQuery: (from 127.0.0.1:50556) SELECT sum(number) FROM numbers(1000) (stage: Complete)
[instance-1] 2022.07.31 20:19:48.663376 [ 5723 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> ContextAccess (default): Access granted: CREATE TEMPORARY TABLE ON *.*
[instance-1] 2022.07.31 20:19:48.666041 [ 5723 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
[instance-1] 2022.07.31 20:19:48.666795 [ 5940 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> AggregatingTransform: Aggregating
[instance-1] 2022.07.31 20:19:48.667071 [ 5940 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> Aggregator: Aggregation method: without_key
[instance-1] 2022.07.31 20:19:48.667240 [ 5940 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Debug> AggregatingTransform: Aggregated. 1000 to 1 rows (from 7.81 KiB) in 0.000833972 sec. (1199081.024 rows/sec., 9.15 MiB/sec.)
[instance-1] 2022.07.31 20:19:48.667318 [ 5940 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> Aggregator: Merging aggregated data
[instance-1] 2022.07.31 20:19:48.667388 [ 5940 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Trace> Aggregator: Statistics updated for key=2571081918823209039: new sum_of_sizes=1, median_size=1
[instance-1] 2022.07.31 20:19:48.668838 [ 5723 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Information> executeQuery: Read 1000 rows, 7.81 KiB in 0.006944513 sec., 143998 rows/sec., 1.10 MiB/sec.
[instance-1] 2022.07.31 20:19:48.668988 [ 5723 ] {76d80ca3-4f77-4fac-8ef8-e8e2b92156f7} <Debug> MemoryTracker: Peak memory usage (for query): 189.52 KiB.
499500

To write logs into a log file ;

clickhouse-client -mn --send_logs_level='trace' --query "SELECT sum(number) FROM numbers(1000)"2>./query.log

Monitoring logs via clickhouse-client. Set log level first;

SET send_logs_level='trace';

SET send_logs_level = 'trace'

Query id: 2d72c0a7-bdfd-47cc-be23-7031a419cf38

Ok.

0 rows in set. Elapsed: 0.001 sec.

Run the sql to monitor logs

SELECT sum(number) FROM numbers(1000);

SELECT sum(number)
FROM numbers(1000)

Query id: bc4a813a-a0e3-4518-84fd-09c0eca2bf92

[instance-1] 2022.07.31 20:21:26.109043 [ 5723 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Debug> executeQuery: (from 127.0.0.1:50558) SELECT sum(number) FROM numbers(1000); (stage: Complete)
[instance-1] 2022.07.31 20:21:26.109645 [ 5723 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> ContextAccess (default): Access granted: CREATE TEMPORARY TABLE ON *.*
[instance-1] 2022.07.31 20:21:26.109895 [ 5723 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
[instance-1] 2022.07.31 20:21:26.110505 [ 5933 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> AggregatingTransform: Aggregating
[instance-1] 2022.07.31 20:21:26.110539 [ 5933 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> Aggregator: An entry for key=2571081918823209039 found in cache: sum_of_sizes=1, median_size=1
[instance-1] 2022.07.31 20:21:26.110561 [ 5933 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> Aggregator: Aggregation method: without_key
[instance-1] 2022.07.31 20:21:26.110604 [ 5933 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Debug> AggregatingTransform: Aggregated. 1000 to 1 rows (from 7.81 KiB) in 0.000582967 sec. (1715362.962 rows/sec., 13.09 MiB/sec.)
[instance-1] 2022.07.31 20:21:26.110621 [ 5933 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Trace> Aggregator: Merging aggregated data
┌─sum(number)─┐
│      499500 │
└─────────────┘
[instance-1] 2022.07.31 20:21:26.111577 [ 5723 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Information> executeQuery: Read 1000 rows, 7.81 KiB in 0.002415719 sec., 413955 rows/sec., 3.16 MiB/sec.
[instance-1] 2022.07.31 20:21:26.111733 [ 5723 ] {bc4a813a-a0e3-4518-84fd-09c0eca2bf92} <Debug> MemoryTracker: Peak memory usage (for query): 189.14 KiB.

1 row in set. Elapsed: 0.005 sec. Processed 1.00 thousand rows, 8.00 KB (187.23 thousand rows/s., 1.50 MB/s.)

System Errors

To find out errors generated by ClickHouse is also stores in the system.errors table.

Run the query below to examine errors.

SELECT *
FROM system.errors
WHERE value > 0
ORDER BY code ASC

Result;

Row 1:
──────
name:               BAD_ARGUMENTS
code:               36
value:              8
last_error_time:    2022-07-24 22:16:52
last_error_message: Invalid date part  for function dateName
last_error_trace:   [188179706,224048537,298054854,228426570,228422158,349871205,349872808,349877167,356681089,381324419,363530860,363486982,363478832,363820099,363824744,366194351,366207242,375718151,375736498,378388347,431577039,431586337,433409001,433397568,139775186957833,139775186059571]
remote:             0