ClickHouse has tables called ‘system.query_log’ and ‘system_query_thread_log’ that are used for storing statistics of each executed query like duration, memory usage, peak memory usage, etc.
There is also a table called ‘system.processes’ that has information about current queries.
In this article, we will explain these tables and give examples.
system.query_log
query_log table is located in the system database and contains information about executed queries, for example, start time, duration of the processing, and error messages.
♣ Note: This table does not contain the ingested data for INSERT queries. |
The system.query_log
table registers two kinds of queries:
- Initial queries were run directly by the client.
- Child queries that were initiated by other queries (for distributed query execution). For these types of queries, information about the parent queries is shown in the
initial_*
columns.
Each query creates one or two rows in the query_log
table, depending on the status (see the type
column) of the query:
- If the query execution was successful, two rows with the
QueryStart
andQueryFinish
types are created. - If an error occurred during query processing, two events with the
QueryStart
andExceptionWhileProcessing
types are created. - If an error occurred before launching the query, a single event with the
ExceptionBeforeStart
type is created.
Example
Query;
SELECT * FROM system.query_log order by event_date desc limit 1 format Vertical
Output;
Row 1: ────── type: QueryFinish event_date: 2021-11-03 event_time: 2021-11-03 16:13:54 event_time_microseconds: 2021-11-03 16:13:54.953024 query_start_time: 2021-11-03 16:13:54 query_start_time_microseconds: 2021-11-03 16:13:54.952325 query_duration_ms: 0 read_rows: 69 read_bytes: 6187 written_rows: 0 written_bytes: 0 result_rows: 69 result_bytes: 48256 memory_usage: 0 current_database: default query: DESCRIBE TABLE system.query_log formatted_query: normalized_query_hash: 8274064835331539124 query_kind: databases: [] tables: [] columns: [] projections: [] views: [] exception_code: 0 exception: stack_trace: is_initial_query: 1 user: default query_id: 7c28bbbb-753b-4eba-98b1-efcbe2b9bdf6 address: ::ffff:127.0.0.1 port: 40452 initial_user: default initial_query_id: 7c28bbbb-753b-4eba-98b1-efcbe2b9bdf6 initial_address: ::ffff:127.0.0.1 initial_port: 40452 initial_query_start_time: 2021-11-03 16:13:54 initial_query_start_time_microseconds: 2021-11-03 16:13:54.952325 interface: 1 os_user: sevirov client_hostname: clickhouse.ru-central1.internal client_name: cansayin47 client_revision: 54449 client_version_major: 21 client_version_minor: 10 client_version_patch: 1 http_method: 0 http_user_agent: http_referer: forwarded_for: quota_key: revision: 54456 log_comment: thread_ids: [30776,31174] ProfileEvents: {'Query':1,'NetworkSendElapsedMicroseconds':59,'NetworkSendBytes':2643,'SelectedRows':69,'SelectedBytes':6187,'ContextLock':9,'RWLockAcquiredReadLocks':1,'RealTimeMicroseconds':817,'UserTimeMicroseconds':427,'SystemTimeMicroseconds':212,'OSCPUVirtualTimeMicroseconds':639,'OSReadChars':894,'OSWriteChars':319} Settings: {'load_balancing':'random','max_memory_usage':'10000000000'} used_aggregate_functions: [] used_aggregate_function_combinators: [] used_database_engines: [] used_data_type_families: [] used_dictionaries: [] used_formats: [] used_functions: [] used_storages: [] used_table_functions: []
system.query_thread_log
query_thread_log table is located in the system database and contains information about threads that execute queries, for example, thread name, thread start time, and duration of query processing.
To start logging in:
- Configure parameters in the query_thread_log section.
- Set log_query_threads to 1.
Setting for logging threads of queries received with the log_query_threads=1 setting.
Queries are logged in the system.query_thread_log table, not in a separate file. You can change the name of the table in the table
parameter (see below).
If the table does not exist, ClickHouse will create it. If the structure of the query thread log changed when the ClickHouse server was updated, the table with the old structure is renamed, and a new table is created automatically.
Example
Query;
SELECT * FROM system.query_thread_log LIMIT 1
Output;
Row 1: ────── event_date: 2020-09-11 event_time: 2020-09-11 10:08:17 event_time_microseconds: 2020-09-11 10:08:17.134042 query_start_time: 2020-09-11 10:08:17 query_start_time_microseconds: 2020-09-11 10:08:17.063150 query_duration_ms: 70 read_rows: 0 read_bytes: 0 written_rows: 1 written_bytes: 12 memory_usage: 4300844 peak_memory_usage: 4300844 thread_name: TCPHandler thread_id: 638133 master_thread_id: 638133 query: INSERT INTO test1 VALUES is_initial_query: 1 user: default query_id: 50a320fd-85a8-49b8-8761-98a86bcbacef address: ::ffff:127.0.0.1 port: 33452 initial_user: default initial_query_id: 50a320fd-85a8-49b8-8761-98a86bcbacef initial_address: ::ffff:127.0.0.1 initial_port: 33452 interface: 1 os_user: bharatnc client_hostname: tower client_name: ClickHouse client_revision: 54437 client_version_major: 20 client_version_minor: 7 client_version_patch: 2 http_method: 0 http_user_agent: quota_key: revision: 54440 ProfileEvents: {'Query':1,'SelectQuery':1,'ReadCompressedBytes':36,'CompressedReadBufferBlocks':1,'CompressedReadBufferBytes':10,'IOBufferAllocs':1,'IOBufferAllocBytes':89,'ContextLock':15,'RWLockAcquiredReadLocks':1}
system.processes
system.processes table contains data about all the current queries.
Example
Query;
SELECT * FROM system.processes format Vertical
Output;
Row 1: ────── is_initial_query: 1 user: demo query_id: c0b4f5df-d311-4e37-a727-2ef0f9211f0d address: ::ffff:10.129.56.59 port: 46692 initial_user: demo initial_query_id: c0b4f5df-d311-4e37-a727-2ef0f9211f0d initial_address: ::ffff:10.129.56.59 initial_port: 46692 interface: 2 os_user: client_hostname: client_name: client_revision: 0 client_version_major: 0 client_version_minor: 0 client_version_patch: 0 http_method: 2 http_user_agent: DBeaver 22.1.1 - SQLEditor <Script.sql> http_referer: forwarded_for: quota_key: distributed_depth: 0 elapsed: 0.000989364 is_cancelled: 0 read_rows: 0 read_bytes: 0 total_rows_approx: 0 written_rows: 0 written_bytes: 0 memory_usage: 0 peak_memory_usage: 0 query: SELECT * FROM system.processes format Vertical thread_ids: [13231] ProfileEvents: {'Query':1,'SelectQuery':1,'ContextLock':13,'RWLockAcquiredReadLocks':1} Settings: {'max_insert_threads':'8','max_threads':'32','connect_timeout_with_failover_ms':'1000','optimize_move_to_prewhere':'1','load_balancing':'random','distributed_aggregation_memory_efficient':'1','log_queries':'1','max_bytes_before_external_group_by':'64424509440','max_bytes_before_external_sort':'64424509440','max_result_rows':'200','max_result_bytes':'10485760','result_overflow_mode':'break','max_execution_time':'120','readonly':'2','max_memory_usage':'115964116992','max_memory_usage_for_user':'115964116992','allow_ddl':'0','parallel_view_processing':'1','default_database_engine':'Ordinary','max_memory_usage_for_all_queries':'115964116992','allow_experimental_window_functions':'1'} current_database: default
Long Running Queries
To find long running queries we have to check system.processes table which is include current processes.
Example;
SELECT query, query_id, elapsed, memory_usage, peak_memory_usage, read_rows,read_bytes, written_rows,written_bytes FROM system.processes
Find queries running longer than 1 second.
SELECT query, query_id, elapsed, memory_usage, peak_memory_usage, read_rows,read_bytes, written_rows,written_bytes FROM system.processes WHERE elapsed > 1
Kill Query
To kill a process, run the following command.
KILL QUERY WHERE query_id = 'd02f4bdb-8928-4347-8641-4da4b9c0f486'
If your kill query returns ‘waiting’ status, please read the information below;
ClickHouse queries can’t be killed during the sleep.
If you are using a recent CH release (21.12+), then the KILL flag will be checked after each block is processed (on older releases it might never be checked). Since the default block is 65536, the query will be slept for 65536 * 3 seconds ~= 54 hours before checking anything.
In future releases of CH it will be impossible to sleep for more than 3 seconds (which right now is a limit of sleep but not for sleepEachRow). In the meantime you can either wait or restart the server.
Most Current Reading Queries
You can use the below command to find the most read queries
SELECT query, query_id, elapsed, read_rows,read_bytes, memory_usage, peak_memory_usage, written_rows,written_bytes FROM system.processes ORDER BY read_bytes DESC
Most Current Writing Queries
You can use the below command to find the most writing queries
SELECT query, query_id, elapsed, written_rows,written_bytes , memory_usage, peak_memory_usage, read_rows,read_bytes FROM system.processes ORDER BY written_rows DESC
Current Queries Using Huge Amount of Memory
Following query shows you queries which are using huge amount of memory.
SELECT query, query_id, elapsed, memory_usage, peak_memory_usage, written_rows,written_bytes , read_rows,read_bytes FROM system.processes order by memory_usage desc
Most Read Queries
SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log ORDER BY read_rows DESC
Most Wrote Queries
SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log ORDER BY written_rows DESC
Most Run Queries
SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log ORDER BY query_duration_ms DESC
Most Memory Used Queries
SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log ORDERY BY memory_usage DESC
Queries Return Error
In the where clause there is type information which is given 3 and 4.
Type 3 is ExceptionBeforeStart
Type 4 is ExceptionWhileProcessing
Now, you can get both error type queries.
SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log WHERE type = 3 or type = 4 ORDER BY event_time DESC
Get By Count
SELECT count() FROM ( SELECT type, query, query_id, event_time,query_duration_ms,read_rows,read_bytes,written_rows,written_bytes,memory_usage FROM system.query_log WHERE type = 3 or type = 4 ORDER BY event_time desc )
Debug Hunging
If ClickHouse is busy and you don’t know why, you can check the stacktraces of all the thread which are working.
SELECT arrayStringConcat(arrayMap(x -> demangle(addressToSymbol(x)), trace), '\n') AS trace_functions, count() FROM system.stack_trace GROUP BY trace_functions ORDER BY count() DESC SETTINGS allow_introspection_functions=1