2018-06-13 19:01:07 +00:00
#!/usr/bin/env bash
set -e
# Get all server logs
export CLICKHOUSE_CLIENT_SERVER_LOGS_LEVEL = "trace"
CURDIR = $( cd " $( dirname " ${ BASH_SOURCE [0] } " ) " && pwd )
. $CURDIR /../shell_config.sh
2019-03-20 20:04:49 +00:00
cur_name = $( basename " ${ BASH_SOURCE [0] } " )
server_logs_file = ${ CLICKHOUSE_TMP } /$cur_name "_server.logs"
2019-02-21 09:21:20 +00:00
2018-06-13 19:01:07 +00:00
server_logs = " --server_logs_file= $server_logs_file "
rm -f " $server_logs_file "
2019-05-14 13:37:24 +00:00
settings = " $server_logs --log_queries=1 --log_query_threads=1 --log_profile_events=1 --log_query_settings=1 --experimental_use_processors=0 "
2018-06-13 19:01:07 +00:00
# Test insert logging on each block and checkPacket() method
$CLICKHOUSE_CLIENT $settings -n -q "
2019-06-03 17:36:27 +00:00
DROP TABLE IF EXISTS null_00634;
CREATE TABLE null_00634 ( i UInt8) ENGINE = MergeTree PARTITION BY tuple( ) ORDER BY tuple( ) ; "
2018-06-13 19:01:07 +00:00
2019-06-03 17:36:27 +00:00
head -c 1000 /dev/zero | $CLICKHOUSE_CLIENT $settings --max_insert_block_size= 10 --min_insert_block_size_rows= 1 --min_insert_block_size_bytes= 1 -q "INSERT INTO null_00634 FORMAT RowBinary"
2018-06-13 19:01:07 +00:00
$CLICKHOUSE_CLIENT $settings -n -q "
2019-06-03 17:36:27 +00:00
SELECT count( ) FROM null_00634;
DROP TABLE null_00634; "
2018-06-13 19:01:07 +00:00
( ( ` cat " $server_logs_file " | wc -l` >= 110 ) ) || echo Fail
# Check ProfileEvents in query_log
heavy_cpu_query = "SELECT ignore(sum(sipHash64(hex(sipHash64(hex(sipHash64(hex(number)))))))) FROM (SELECT * FROM system.numbers_mt LIMIT 1000000)"
$CLICKHOUSE_CLIENT $settings --max_threads= 1 -q " $heavy_cpu_query "
2018-10-09 10:05:27 +00:00
$CLICKHOUSE_CLIENT $settings -q "SYSTEM FLUSH LOGS"
2018-06-13 19:01:07 +00:00
$CLICKHOUSE_CLIENT $settings -q "
WITH
2018-08-14 22:01:41 +00:00
any( query_duration_ms*1000) AS duration,
sumIf( PV, PN = 'RealTimeMicroseconds' ) AS threads_realtime,
sumIf( PV, PN IN ( 'UserTimeMicroseconds' , 'SystemTimeMicroseconds' , 'OSIOWaitMicroseconds' , 'OSCPUWaitMicroseconds' ) ) AS threads_time_user_system_io
2018-06-13 19:01:07 +00:00
SELECT
2018-08-19 04:25:53 +00:00
-- duration, threads_realtime, threads_time_user_system_io,
2018-08-14 22:01:41 +00:00
threads_realtime >= 0.99 * duration,
threads_realtime >= threads_time_user_system_io,
2020-02-02 19:49:53 +00:00
any( length( thread_ids) ) >= 1
2018-08-14 22:01:41 +00:00
FROM
( SELECT * FROM system.query_log PREWHERE query = '$heavy_cpu_query' WHERE event_date >= today( ) -1 AND type = 2 ORDER BY event_time DESC LIMIT 1)
ARRAY JOIN ProfileEvents.Names AS PN, ProfileEvents.Values AS PV"
2018-06-13 19:01:07 +00:00
# Check ProfileEvents in query_thread_log
$CLICKHOUSE_CLIENT $settings --max_threads= 3 -q " $heavy_cpu_query "
2018-10-09 10:05:27 +00:00
$CLICKHOUSE_CLIENT $settings -q "SYSTEM FLUSH LOGS"
2018-06-13 19:01:07 +00:00
query_id = ` $CLICKHOUSE_CLIENT $settings -q " SELECT query_id FROM system.query_log WHERE event_date >= today()-1 AND type=2 AND query=' $heavy_cpu_query ' ORDER BY event_time DESC LIMIT 1 " `
query_elapsed = ` $CLICKHOUSE_CLIENT $settings -q " SELECT query_duration_ms*1000 FROM system.query_log WHERE event_date >= today()-1 AND type=2 AND query_id=' $query_id ' ORDER BY event_time DESC LIMIT 1 " `
2020-02-02 19:49:53 +00:00
threads = ` $CLICKHOUSE_CLIENT $settings -q " SELECT length(thread_ids) FROM system.query_log WHERE event_date >= today()-1 AND type=2 AND query_id=' $query_id ' ORDER BY event_time DESC LIMIT 1 " `
2018-06-13 19:01:07 +00:00
$CLICKHOUSE_CLIENT $settings -q "
SELECT
2018-08-14 22:01:41 +00:00
-- max( thread_realtime) , $query_elapsed , max( thread_time_user_system_io) ,
0.9 * $query_elapsed <= max( thread_realtime) AND max( thread_realtime) <= 1.1 * $query_elapsed ,
0.7 * $query_elapsed <= max( thread_time_user_system_io) AND max( thread_time_user_system_io) <= 1.3 * $query_elapsed ,
2020-02-02 19:49:53 +00:00
uniqExact( thread_id) = $threads
2018-06-13 19:01:07 +00:00
FROM
(
2018-08-14 22:01:41 +00:00
SELECT
2020-02-02 19:49:53 +00:00
thread_id,
2018-08-14 22:01:41 +00:00
sumIf( PV, PN = 'RealTimeMicroseconds' ) AS thread_realtime,
sumIf( PV, PN IN ( 'UserTimeMicroseconds' , 'SystemTimeMicroseconds' , 'OSIOWaitMicroseconds' , 'OSCPUWaitMicroseconds' ) ) AS thread_time_user_system_io
FROM
( SELECT * FROM system.query_thread_log PREWHERE query_id = '$query_id' WHERE event_date >= today( ) -1)
ARRAY JOIN ProfileEvents.Names AS PN, ProfileEvents.Values AS PV
2020-02-02 19:49:53 +00:00
GROUP BY thread_id
2018-06-13 19:01:07 +00:00
)
"
# Check per-thread and per-query ProfileEvents consistency
2019-08-08 19:42:34 +00:00
$CLICKHOUSE_CLIENT $settings --any_join_distinct_right_table_keys= 1 -q "
2018-06-13 19:01:07 +00:00
SELECT PN, PVq, PVt FROM
(
2018-08-14 22:01:41 +00:00
SELECT PN, sum( PV) AS PVt
FROM system.query_thread_log
ARRAY JOIN ProfileEvents.Names AS PN, ProfileEvents.Values AS PV
WHERE event_date >= today( ) -1 AND query_id = '$query_id'
GROUP BY PN
2018-06-13 19:01:07 +00:00
)
ANY INNER JOIN
(
2018-08-14 22:01:41 +00:00
SELECT PN, PV AS PVq
FROM system.query_log
ARRAY JOIN ProfileEvents.Names AS PN, ProfileEvents.Values AS PV
WHERE event_date >= today( ) -1 AND query_id = '$query_id'
2018-06-13 19:01:07 +00:00
)
USING PN
2018-08-19 04:25:53 +00:00
WHERE
2018-08-14 22:01:41 +00:00
NOT PN IN ( 'ContextLock' ) AND
NOT ( PVq <= PVt AND PVt <= 1.1 * PVq)
2018-06-13 19:01:07 +00:00
"
2018-08-19 04:25:53 +00:00
# Clean
2018-06-15 17:32:35 +00:00
rm " $server_logs_file "