From 60f529f667069c15fa49296ac1f59a33d94d3f31 Mon Sep 17 00:00:00 2001 From: Azat Khuzhin Date: Thu, 25 Jul 2024 11:06:00 +0200 Subject: [PATCH] The most precise way of tracking flushing time in 01246_buffer_flush Right now there are couple of issues with the test: - it does not takes into account INSERT time - it does not takes into account SELECT time, which can be significant from time to time, for instance here [1] it takes 3.3 seconds (and due to tsan build it is not possible to find out why) 2024.07.23 20:52:18.238844 [ 13045 ] {d903650b-ab87-44f3-b7c3-4145e02f1301} executeQuery: (from [::1]:39430) (comment: 01246_buffer_flush.sh) select count() from data_01256; (stage: Complete) 2024.07.23 20:52:21.588183 [ 13045 ] {d903650b-ab87-44f3-b7c3-4145e02f1301} TCPHandler: Processed in 3.354887498 sec. [1]: https://s3.amazonaws.com/clickhouse-test-reports/66934/919005c4f70b044ecd9cc1bbce5dc5e276e11929/stateless_tests__tsan__s3_storage__[4_4].html Anyway all of this can be fixed by using QueryStart-insert into data table time. Signed-off-by: Azat Khuzhin --- .../queries/0_stateless/01246_buffer_flush.sh | 49 ++++++++++++------- 1 file changed, 31 insertions(+), 18 deletions(-) diff --git a/tests/queries/0_stateless/01246_buffer_flush.sh b/tests/queries/0_stateless/01246_buffer_flush.sh index 1ca953c80d9..27c3f01f216 100755 --- a/tests/queries/0_stateless/01246_buffer_flush.sh +++ b/tests/queries/0_stateless/01246_buffer_flush.sh @@ -5,59 +5,72 @@ CUR_DIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) # shellcheck source=../shell_config.sh . "$CUR_DIR"/../shell_config.sh -function elapsed_sec() +set -e + +function wait_until() { local expr=$1 && shift - local start end - start=$(date +%s.%N) while ! eval "$expr"; do sleep 0.5 done - end=$(date +%s.%N) - $CLICKHOUSE_LOCAL -q "select floor($end-$start)" +} +function get_buffer_delay() +{ + local buffer_insert_id=$1 && shift + $CLICKHOUSE_CLIENT -nm -q " + SYSTEM FLUSH LOGS; + WITH + (SELECT event_time_microseconds FROM system.query_log WHERE current_database = currentDatabase() AND type = 'QueryStart' AND query_id = '$buffer_insert_id') AS begin_, + (SELECT max(event_time) FROM data_01256) AS end_ + SELECT dateDiff('seconds', begin_, end_)::UInt64; + " } $CLICKHOUSE_CLIENT -nm -q " drop table if exists data_01256; drop table if exists buffer_01256; - create table data_01256 as system.numbers Engine=Memory(); + create table data_01256 (key UInt64, event_time DateTime(6) MATERIALIZED now64(6)) Engine=Memory(); " echo "min" -$CLICKHOUSE_CLIENT -nm -q " - create table buffer_01256 as system.numbers Engine=Buffer(currentDatabase(), data_01256, 1, +$CLICKHOUSE_CLIENT -q " + create table buffer_01256 (key UInt64) Engine=Buffer(currentDatabase(), data_01256, 1, 2, 100, /* time */ 4, 100, /* rows */ 1, 1e6 /* bytes */ - ); - insert into buffer_01256 select * from system.numbers limit 5; - select count() from data_01256; + ) " -sec=$(elapsed_sec '[[ $($CLICKHOUSE_CLIENT -q "select count() from data_01256") -eq 5 ]]') +min_query_id=$(random_str 10) +$CLICKHOUSE_CLIENT --query_id="$min_query_id" -q "insert into buffer_01256 select * from system.numbers limit 5" +$CLICKHOUSE_CLIENT -q "select count() from data_01256" +wait_until '[[ $($CLICKHOUSE_CLIENT -q "select count() from data_01256") -eq 5 ]]' +sec=$(get_buffer_delay "$min_query_id") [[ $sec -ge 2 ]] || echo "Buffer flushed too early, min_time=2, flushed after $sec sec" [[ $sec -lt 100 ]] || echo "Buffer flushed too late, max_time=100, flushed after $sec sec" $CLICKHOUSE_CLIENT -q "select count() from data_01256" $CLICKHOUSE_CLIENT -q "drop table buffer_01256" echo "max" -$CLICKHOUSE_CLIENT -nm -q " - create table buffer_01256 as system.numbers Engine=Buffer(currentDatabase(), data_01256, 1, +$CLICKHOUSE_CLIENT -q " + create table buffer_01256 (key UInt64) Engine=Buffer(currentDatabase(), data_01256, 1, 100, 2, /* time */ 0, 100, /* rows */ 0, 1e6 /* bytes */ ); - insert into buffer_01256 select * from system.numbers limit 5; - select count() from data_01256; " -sec=$(elapsed_sec '[[ $($CLICKHOUSE_CLIENT -q "select count() from data_01256") -eq 10 ]]') +max_query_id=$(random_str 10) +$CLICKHOUSE_CLIENT --query_id="$max_query_id" -q "insert into buffer_01256 select * from system.numbers limit 5" +$CLICKHOUSE_CLIENT -q "select count() from data_01256" +wait_until '[[ $($CLICKHOUSE_CLIENT -q "select count() from data_01256") -eq 10 ]]' +sec=$(get_buffer_delay "$max_query_id") [[ $sec -ge 2 ]] || echo "Buffer flushed too early, max_time=2, flushed after $sec sec" $CLICKHOUSE_CLIENT -q "select count() from data_01256" $CLICKHOUSE_CLIENT -q "drop table buffer_01256" echo "direct" $CLICKHOUSE_CLIENT -nm -q " - create table buffer_01256 as system.numbers Engine=Buffer(currentDatabase(), data_01256, 1, + create table buffer_01256 (key UInt64) Engine=Buffer(currentDatabase(), data_01256, 1, 100, 100, /* time */ 0, 9, /* rows */ 0, 1e6 /* bytes */