ClickHouse Query Troubleshooting

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:

1. Initial queries were run directly by the client.
2. 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:

1. If the query execution was successful, two rows with the QueryStart and QueryFinish types are created.
2. If an error occurred during query processing, two events with the QueryStart and ExceptionWhileProcessing types are created.
3. 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:

1. Configure parameters in the query_thread_log section.
2. 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