Skip to content

Query with sleepEachRow finished without fully sleeping #55667

@Algunenano

Description

@Algunenano

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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    analyzerIssues and pull-requests related to new analyzerbugConfirmed user-visible misbehaviour in official releaseminorPriority: minor

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions