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 "
settings = " $server_logs --log_queries=1 --log_query_threads=1 --log_profile_events=1 --log_query_settings=1 "
# Test insert logging on each block and checkPacket() method
$CLICKHOUSE_CLIENT $settings -n -q "
DROP TABLE IF EXISTS test.null;
CREATE TABLE test.null ( i UInt8) ENGINE = MergeTree PARTITION BY tuple( ) ORDER BY tuple( ) ; "
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 test.null FORMAT RowBinary"
$CLICKHOUSE_CLIENT $settings -n -q "
SELECT count( ) FROM test.null;
DROP TABLE test.null; "
( ( ` 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,
any( length( thread_numbers) ) >= 1
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 " `
threads = ` $CLICKHOUSE_CLIENT $settings -q " SELECT length(thread_numbers) FROM system.query_log WHERE event_date >= today()-1 AND type=2 AND query_id=' $query_id ' ORDER BY event_time DESC LIMIT 1 " `
$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 ,
uniqExact( thread_number) = $threads
2018-06-13 19:01:07 +00:00
FROM
(
2018-08-14 22:01:41 +00:00
SELECT
thread_number,
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
GROUP BY thread_number
2018-06-13 19:01:07 +00:00
)
"
# Check per-thread and per-query ProfileEvents consistency
$CLICKHOUSE_CLIENT $settings -q "
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 "