Query with sleepEachRow finished without fully sleeping #55667
Description
Comes from #53792 (comment).
The test_drop_is_lock_free set of tests use sleepEachRow to have a query running with a lock in the table and see that other queries are lock free. In at least that referenced run the "locking" query has finished in 6 seconds although it's supposed to sleep for 150s:
Checking the query log:
SELECT *
FROM system.query_log
WHERE query_id = 'select-table_test_query_is_permanent_detach_part_TxNotFinished_'
Query id: 61db6d90-c855-42c0-8766-16337562b4da
Row 1:
──────
type: QueryStart
event_date: 2023-10-09
event_time: 2023-10-09 18:25:57
event_time_microseconds: 2023-10-09 18:25:57.720389
query_start_time: 2023-10-09 18:25:57
query_start_time_microseconds: 2023-10-09 18:25:57.720389
query_duration_ms: 0
read_rows: 0
read_bytes: 0
written_rows: 0
written_bytes: 0
result_rows: 0
result_bytes: 0
memory_usage: 0
current_database: default
query: SELECT sleepEachRow(3) FROM table_test_query_is_permanent_detach_part_TxNotFinished_ SETTINGS function_sleep_max_microseconds_per_block = 0;
formatted_query:
normalized_query_hash: 6855856342005459772
query_kind: Select
databases: ['default']
tables: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_']
columns: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_.date']
partitions: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220901','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220902','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220903','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220904','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220905','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220906','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220907','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220908','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220909','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220910','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220911','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220912','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220913','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220914','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220915','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220916','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220917','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220918','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220919','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220920','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220921','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220922','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220923','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220924','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220925','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220926','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220927','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220928','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220929','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220930','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221001','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221002','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221003','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221004','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221005','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221006','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221007','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221008','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221009','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221010','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221011','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221012','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221013','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221014','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221015','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221016','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221017','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221018','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221019','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221020']
projections: []
views: []
exception_code: 0
exception:
stack_trace:
is_initial_query: 1
user: default
query_id: select-table_test_query_is_permanent_detach_part_TxNotFinished_
address: ::ffff:172.16.16.1
port: 56996
initial_user: default
initial_query_id: select-table_test_query_is_permanent_detach_part_TxNotFinished_
initial_address: ::ffff:172.16.16.1
initial_port: 56996
initial_query_start_time: 2023-10-09 18:25:57
initial_query_start_time_microseconds: 2023-10-09 18:25:57.720389
interface: 1
is_secure: 0
os_user:
client_hostname: 3bb190df1d92
client_name: ClickHouse client
client_revision: 54466
client_version_major: 23
client_version_minor: 10
client_version_patch: 1
http_method: 0
http_user_agent:
http_referer:
forwarded_for:
quota_key:
distributed_depth: 0
revision: 54479
log_comment:
thread_ids: []
peak_threads_usage: 0
ProfileEvents: {}
Settings: {'allow_experimental_analyzer':'1','function_sleep_max_microseconds_per_block':'0'}
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: []
used_row_policies: []
transaction_id: (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage: Unknown
asynchronous_read_counters: {}
Row 2:
──────
type: QueryFinish
event_date: 2023-10-09
event_time: 2023-10-09 18:26:03
event_time_microseconds: 2023-10-09 18:26:03.736292
query_start_time: 2023-10-09 18:25:57
query_start_time_microseconds: 2023-10-09 18:25:57.720389
query_duration_ms: 6015
read_rows: 50
read_bytes: 100
written_rows: 0
written_bytes: 0
result_rows: 50
result_bytes: 6400
memory_usage: 9144
current_database: default
query: SELECT sleepEachRow(3) FROM table_test_query_is_permanent_detach_part_TxNotFinished_ SETTINGS function_sleep_max_microseconds_per_block = 0;
formatted_query:
normalized_query_hash: 6855856342005459772
query_kind: Select
databases: ['default']
tables: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_']
columns: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_.date']
partitions: ['default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220901','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220902','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220903','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220904','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220905','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220906','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220907','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220908','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220909','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220910','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220911','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220912','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220913','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220914','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220915','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220916','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220917','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220918','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220919','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220920','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220921','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220922','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220923','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220924','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220925','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220926','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220927','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220928','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220929','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20220930','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221001','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221002','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221003','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221004','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221005','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221006','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221007','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221008','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221009','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221010','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221011','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221012','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221013','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221014','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221015','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221016','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221017','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221018','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221019','default.table_test_query_is_permanent_detach_part_TxNotFinished_.20221020']
projections: []
views: []
exception_code: 0
exception:
stack_trace:
is_initial_query: 1
user: default
query_id: select-table_test_query_is_permanent_detach_part_TxNotFinished_
address: ::ffff:172.16.16.1
port: 56996
initial_user: default
initial_query_id: select-table_test_query_is_permanent_detach_part_TxNotFinished_
initial_address: ::ffff:172.16.16.1
initial_port: 56996
initial_query_start_time: 2023-10-09 18:25:57
initial_query_start_time_microseconds: 2023-10-09 18:25:57.720389
interface: 1
is_secure: 0
os_user:
client_hostname: 3bb190df1d92
client_name: ClickHouse client
client_revision: 54466
client_version_major: 23
client_version_minor: 10
client_version_patch: 1
http_method: 0
http_user_agent:
http_referer:
forwarded_for:
quota_key:
distributed_depth: 0
revision: 54479
log_comment:
thread_ids: [1258,1283,1239,1240,1230,1290,1289,1242,1275,1214,1261,1268,1221,1291,1244,1267,1272,1235,1257,1280,1263,1254,1294,908,1276,1218,1227,1274,1251,1293,1246,1288,1256,1278]
peak_threads_usage: 34
ProfileEvents: {'Query':1,'SelectQuery':1,'QueriesWithSubqueries':1,'SelectQueriesWithSubqueries':1,'FileOpen':100,'ReadBufferFromFileDescriptorReadBytes':4300,'ReadCompressedBytes':4336,'CompressedReadBufferBlocks':101,'CompressedReadBufferBytes':4110,'OpenedFileCacheMisses':100,'OpenedFileCacheMicroseconds':986,'IOBufferAllocs':202,'IOBufferAllocBytes':1072976,'FunctionExecute':50,'MarkCacheMisses':50,'CreatedReadBufferOrdinary':100,'DiskReadElapsedMicroseconds':1218,'NetworkReceiveElapsedMicroseconds':420,'NetworkSendElapsedMicroseconds':3578,'NetworkSendBytes':31060,'SelectedParts':50,'SelectedRanges':50,'SelectedMarks':50,'SelectedRows':50,'SelectedBytes':100,'WaitMarksLoadMicroseconds':11373,'LoadedMarksCount':200,'LoadedMarksMemoryBytes':5200,'ContextLock':20,'RWLockAcquiredReadLocks':1,'PartsLockHoldMicroseconds':40,'RealTimeMicroseconds':204179530,'UserTimeMicroseconds':42154,'SystemTimeMicroseconds':37838,'SoftPageFaults':9685,'OSCPUWaitMicroseconds':615,'OSCPUVirtualTimeMicroseconds':79885,'OSWriteBytes':28672,'OSReadChars':2048,'OSWriteChars':29696,'SleepFunctionCalls':50,'SleepFunctionMicroseconds':150000000,'ThreadPoolReaderPageCacheHit':100,'ThreadPoolReaderPageCacheHitBytes':4300,'ThreadPoolReaderPageCacheHitElapsedMicroseconds':1218,'SynchronousReadWaitMicroseconds':2404,'LogTest':100,'LogTrace':4,'LogDebug':6}
Settings: {'allow_experimental_analyzer':'1','function_sleep_max_microseconds_per_block':'0'}
used_aggregate_functions: []
used_aggregate_function_combinators: []
used_database_engines: []
used_data_type_families: []
used_dictionaries: []
used_formats: []
used_functions: ['multiMatchAny','multiIf','if','sleepEachRow','or']
used_storages: []
used_table_functions: []
used_row_policies: []
transaction_id: (0,0,'00000000-0000-0000-0000-000000000000')
query_cache_usage: None
asynchronous_read_counters: {}
2 rows in set. Elapsed: 0.007 sec.
query_duration_ms: 6015
'SleepFunctionCalls':50,'SleepFunctionMicroseconds':150000000,
Something doesn't add up. The run is https://s3.amazonaws.com/clickhouse-test-reports/53792/0b4d76780f79613fa51e725e0142663d2807f04a/integration_tests__asan__analyzer__[4_6].html but the logs of this test have been rotated, only the system tables remain.