Add profile events to sleep function calls

This commit is contained in:
Raúl Marín 2021-07-14 18:44:09 +02:00
parent 9070cb53dd
commit 901e251d53
4 changed files with 82 additions and 1 deletions

View File

@ -248,6 +248,9 @@
M(S3WriteRequestsThrottling, "Number of 429 and 503 errors in POST, DELETE, PUT and PATCH requests to S3 storage.") \
M(S3WriteRequestsRedirects, "Number of redirects in POST, DELETE, PUT and PATCH requests to S3 storage.") \
M(QueryMemoryLimitExceeded, "Number of times when memory limit exceeded for query.") \
\
M(SleepFunctionCalls, "Number of times a sleep function (sleep, sleepEachRow) has been called.") \
M(SleepFunctionMicroseconds, "Time spent sleeping due to a sleep function call.") \
namespace ProfileEvents

View File

@ -5,11 +5,17 @@
#include <Columns/ColumnConst.h>
#include <DataTypes/DataTypesNumber.h>
#include <Common/FieldVisitorConvertToNumber.h>
#include <Common/ProfileEvents.h>
#include <Common/assert_cast.h>
#include <common/sleep.h>
#include <IO/WriteHelpers.h>
#include <Interpreters/Context_fwd.h>
namespace ProfileEvents
{
extern const Event SleepFunctionCalls;
extern const Event SleepFunctionMicroseconds;
}
namespace DB
{
@ -91,8 +97,11 @@ public:
if (seconds > 3.0) /// The choice is arbitrary
throw Exception("The maximum sleep time is 3 seconds. Requested: " + toString(seconds), ErrorCodes::TOO_SLOW);
UInt64 microseconds = seconds * (variant == FunctionSleepVariant::PerBlock ? 1 : size) * 1e6;
UInt64 count = (variant == FunctionSleepVariant::PerBlock ? 1 : size);
UInt64 microseconds = seconds * count * 1e6;
sleepForMicroseconds(microseconds);
ProfileEvents::increment(ProfileEvents::SleepFunctionCalls, count);
ProfileEvents::increment(ProfileEvents::SleepFunctionMicroseconds, microseconds);
}
/// convertToFullColumn needed, because otherwise (constant expression case) function will not get called on each columns.

View File

@ -0,0 +1,6 @@
{"'SLEEP #1 CHECK'":"SLEEP #1 CHECK","calls":"1","microseconds":"1000"}
{"'SLEEP #2 CHECK'":"SLEEP #2 CHECK","calls":"1","microseconds":"1000"}
{"'SLEEP #3 CHECK'":"SLEEP #3 CHECK","calls":"1","microseconds":"1000"}
{"'SLEEP #4 CHECK'":"SLEEP #4 CHECK","calls":"2","microseconds":"2000"}
{"'SLEEP #5 CHECK'":"SLEEP #5 CHECK","calls":"0","microseconds":"0"}
{"'SLEEP #6 CHECK'":"SLEEP #6 CHECK","calls":"10","microseconds":"10000"}

View File

@ -0,0 +1,63 @@
SET log_queries=1;
SET log_profile_events=true;
SELECT 'SLEEP #1 TEST', sleep(0.001) FORMAT Null;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #1 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%SELECT ''SLEEP #1 TEST''%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;
SELECT 'SLEEP #2 TEST', sleep(0.001) FROM numbers(2) FORMAT Null;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #2 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%SELECT ''SLEEP #2 TEST''%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;
SELECT 'SLEEP #3 TEST', sleepEachRow(0.001) FORMAT Null;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #3 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%SELECT ''SLEEP #3 TEST''%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;
SELECT 'SLEEP #4 TEST', sleepEachRow(0.001) FROM numbers(2) FORMAT Null;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #4 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%SELECT ''SLEEP #4 TEST''%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;
CREATE VIEW sleep_view AS SELECT sleepEachRow(0.001) FROM system.numbers;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #5 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%CREATE VIEW sleep_view AS%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;
SELECT 'SLEEP #6 TEST', sleepEachRow(0.001) FROM sleep_view LIMIT 10 FORMAT Null;
SYSTEM FLUSH LOGS;
SELECT 'SLEEP #6 CHECK', ProfileEvents['SleepFunctionCalls'] as calls, ProfileEvents['SleepFunctionMicroseconds'] as microseconds
FROM system.query_log
WHERE query like '%SELECT ''SLEEP #6 TEST''%'
AND type > 1
AND current_database = currentDatabase()
AND event_date >= yesterday()
FORMAT JSONEachRow;