diff --git a/src/Common/ProfileEvents.cpp b/src/Common/ProfileEvents.cpp index 908adbe1d1..475e073d25 100644 --- a/src/Common/ProfileEvents.cpp +++ b/src/Common/ProfileEvents.cpp @@ -11,6 +11,9 @@ M(FailedQuery, "Number of failed queries.") \ M(FailedSelectQuery, "Same as FailedQuery, but only for SELECT queries.") \ M(FailedInsertQuery, "Same as FailedQuery, but only for INSERT queries.") \ + M(QueryTimeMicroseconds, "Total time of all queries.") \ + M(SelectQueryTimeMicroseconds, "Total time of SELECT queries.") \ + M(InsertQueryTimeMicroseconds, "Total time of INSERT queries.") \ M(FileOpen, "Number of files opened.") \ M(Seek, "Number of times the 'lseek' function was called.") \ M(ReadBufferFromFileDescriptorRead, "Number of reads (read/pread) from a file descriptor. Does not include sockets.") \ diff --git a/src/Interpreters/executeQuery.cpp b/src/Interpreters/executeQuery.cpp index 46237bd6ef..78e9f4bba3 100644 --- a/src/Interpreters/executeQuery.cpp +++ b/src/Interpreters/executeQuery.cpp @@ -51,6 +51,9 @@ namespace ProfileEvents extern const Event FailedQuery; extern const Event FailedInsertQuery; extern const Event FailedSelectQuery; + extern const Event QueryTimeMicroseconds; + extern const Event SelectQueryTimeMicroseconds; + extern const Event InsertQueryTimeMicroseconds; } namespace DB @@ -480,8 +483,37 @@ static std::tuple executeQueryImpl( query_log->add(elem); } + /// Common code for finish and exception callbacks + auto status_info_to_query_log = [ast](QueryLogElement &element, const QueryStatusInfo &info) mutable + { + DB::UInt64 query_time = info.elapsed_seconds * 1000000; + ProfileEvents::increment(ProfileEvents::QueryTimeMicroseconds, query_time); + if (ast->as() || ast->as()) + { + ProfileEvents::increment(ProfileEvents::SelectQueryTimeMicroseconds, query_time); + } + else if (ast->as()) + { + ProfileEvents::increment(ProfileEvents::InsertQueryTimeMicroseconds, query_time); + } + + element.query_duration_ms = info.elapsed_seconds * 1000; + + element.read_rows = info.read_rows; + element.read_bytes = info.read_bytes; + + element.written_rows = info.written_rows; + element.written_bytes = info.written_bytes; + + element.memory_usage = info.peak_memory_usage > 0 ? info.peak_memory_usage : 0; + + element.thread_ids = std::move(info.thread_ids); + element.profile_counters = std::move(info.profile_counters); + }; + /// Also make possible for caller to log successful query finish and exception during execution. - auto finish_callback = [elem, &context, log_queries, log_queries_min_type = settings.log_queries_min_type] + auto finish_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, + status_info_to_query_log] (IBlockInputStream * stream_in, IBlockOutputStream * stream_out, QueryPipeline * query_pipeline) mutable { QueryStatus * process_list_elem = context.getProcessListElement(); @@ -499,21 +531,14 @@ static std::tuple executeQueryImpl( elem.type = QueryLogElementType::QUERY_FINISH; elem.event_time = time(nullptr); - elem.query_duration_ms = elapsed_seconds * 1000; - elem.read_rows = info.read_rows; - elem.read_bytes = info.read_bytes; - - elem.written_rows = info.written_rows; - elem.written_bytes = info.written_bytes; + status_info_to_query_log(elem, info); auto progress_callback = context.getProgressCallback(); if (progress_callback) progress_callback(Progress(WriteProgress(info.written_rows, info.written_bytes))); - elem.memory_usage = info.peak_memory_usage > 0 ? info.peak_memory_usage : 0; - if (stream_in) { const BlockStreamProfileInfo & stream_in_info = stream_in->getProfileInfo(); @@ -558,7 +583,8 @@ static std::tuple executeQueryImpl( } }; - auto exception_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, quota(quota)] () mutable + auto exception_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, quota(quota), + status_info_to_query_log] () mutable { if (quota) quota->used(Quota::ERRORS, 1, /* check_exceeded = */ false); @@ -579,16 +605,7 @@ static std::tuple executeQueryImpl( if (process_list_elem) { QueryStatusInfo info = process_list_elem->getInfo(true, current_settings.log_profile_events, false); - - elem.query_duration_ms = info.elapsed_seconds * 1000; - - elem.read_rows = info.read_rows; - elem.read_bytes = info.read_bytes; - - elem.memory_usage = info.peak_memory_usage > 0 ? info.peak_memory_usage : 0; - - elem.thread_ids = std::move(info.thread_ids); - elem.profile_counters = std::move(info.profile_counters); + status_info_to_query_log(elem, info); } if (current_settings.calculate_text_stack_trace) diff --git a/tests/queries/0_stateless/01417_query_time_in_system_events.reference b/tests/queries/0_stateless/01417_query_time_in_system_events.reference new file mode 100644 index 0000000000..14ec14dbf6 --- /dev/null +++ b/tests/queries/0_stateless/01417_query_time_in_system_events.reference @@ -0,0 +1,3 @@ +QueryTimeMicroseconds: Ok +SelectQueryTimeMicroseconds: Ok +InsertQueryTimeMicroseconds: Ok diff --git a/tests/queries/0_stateless/01417_query_time_in_system_events.sh b/tests/queries/0_stateless/01417_query_time_in_system_events.sh new file mode 100755 index 0000000000..ff6d11befb --- /dev/null +++ b/tests/queries/0_stateless/01417_query_time_in_system_events.sh @@ -0,0 +1,51 @@ +#!/usr/bin/env bash + +CURDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) +. $CURDIR/../shell_config.sh + +DATA_BEFORE=`${CLICKHOUSE_CLIENT} --query="SELECT event,value FROM system.events WHERE event IN ('QueryTimeMicroseconds','SelectQueryTimeMicroseconds','InsertQueryTimeMicroseconds') FORMAT CSV"` + +${CLICKHOUSE_CLIENT} --query="DROP TABLE IF EXISTS test" +${CLICKHOUSE_CLIENT} --query="CREATE TABLE test (k UInt32) ENGINE=MergeTree ORDER BY k" +${CLICKHOUSE_CLIENT} --query="INSERT INTO test (k) SELECT sleep(1)" +${CLICKHOUSE_CLIENT} --query="SELECT sleep(1)" > /dev/null +${CLICKHOUSE_CLIENT} --query="DROP TABLE IF EXISTS test" + +DATA_AFTER=`${CLICKHOUSE_CLIENT} --query="SELECT event,value FROM system.events WHERE event IN ('QueryTimeMicroseconds','SelectQueryTimeMicroseconds','InsertQueryTimeMicroseconds') FORMAT CSV"` + +declare -A VALUES_BEFORE +VALUES_BEFORE=(["\"QueryTimeMicroseconds\""]="0" ["\"SelectQueryTimeMicroseconds\""]="0" ["\"InsertQueryTimeMicroseconds\""]="0") +declare -A VALUES_AFTER +VALUES_AFTER=(["\"QueryTimeMicroseconds\""]="0" ["\"SelectQueryTimeMicroseconds\""]="0" ["\"InsertQueryTimeMicroseconds\""]="0") + +for RES in ${DATA_BEFORE} +do + IFS=',' read -ra FIELDS <<< ${RES} + VALUES_BEFORE[${FIELDS[0]}]=${FIELDS[1]} +done + +for RES in ${DATA_AFTER} +do + IFS=',' read -ra FIELDS <<< ${RES} + VALUES_AFTER[${FIELDS[0]}]=${FIELDS[1]} +done + +let QUERY_TIME=${VALUES_AFTER[\"QueryTimeMicroseconds\"]}-${VALUES_BEFORE[\"QueryTimeMicroseconds\"]} +let SELECT_QUERY_TIME=${VALUES_AFTER[\"SelectQueryTimeMicroseconds\"]}-${VALUES_BEFORE[\"SelectQueryTimeMicroseconds\"]} +let INSERT_QUERY_TIME=${VALUES_AFTER[\"InsertQueryTimeMicroseconds\"]}-${VALUES_BEFORE[\"InsertQueryTimeMicroseconds\"]} +if [[ "${QUERY_TIME}" -lt "2000000" ]]; then + echo "QueryTimeMicroseconds: Fail (${QUERY_TIME})" +else + echo "QueryTimeMicroseconds: Ok" +fi +if [[ "${SELECT_QUERY_TIME}" -lt "1000000" ]]; then + echo "SelectQueryTimeMicroseconds: Fail (${SELECT_QUERY_TIME})" +else + echo "SelectQueryTimeMicroseconds: Ok" +fi +if [[ "${INSERT_QUERY_TIME}" -lt "1000000" ]]; then + echo "InsertQueryTimeMicroseconds: Fail (${INSERT_QUERY_TIME})" +else + echo "InsertQueryTimeMicroseconds: Ok" +fi +