diff --git a/src/Common/ProfileEvents.cpp b/src/Common/ProfileEvents.cpp index 475e073d253..908adbe1d12 100644 --- a/src/Common/ProfileEvents.cpp +++ b/src/Common/ProfileEvents.cpp @@ -11,9 +11,6 @@ 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 1ce41204718..87b5da991a9 100644 --- a/src/Interpreters/executeQuery.cpp +++ b/src/Interpreters/executeQuery.cpp @@ -51,9 +51,6 @@ 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 @@ -483,34 +480,8 @@ static std::tuple executeQueryImpl( query_log->add(elem); } - /// Coomon 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.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, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, - status_info_to_query_log] + auto finish_callback = [elem, &context, log_queries, log_queries_min_type = settings.log_queries_min_type] (IBlockInputStream * stream_in, IBlockOutputStream * stream_out, QueryPipeline * query_pipeline) mutable { QueryStatus * process_list_elem = context.getProcessListElement(); @@ -528,14 +499,21 @@ static std::tuple executeQueryImpl( elem.type = QueryLogElementType::QUERY_FINISH; elem.event_time = time(nullptr); + elem.query_duration_ms = elapsed_seconds * 1000; - status_info_to_query_log(elem, info); + elem.read_rows = info.read_rows; + elem.read_bytes = info.read_bytes; + + elem.written_rows = info.written_rows; + elem.written_bytes = info.written_bytes; 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(); @@ -580,8 +558,7 @@ static std::tuple executeQueryImpl( } }; - 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 + auto exception_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, quota(quota)] () mutable { if (quota) quota->used(Quota::ERRORS, 1, /* check_exceeded = */ false); @@ -602,7 +579,16 @@ static std::tuple executeQueryImpl( if (process_list_elem) { QueryStatusInfo info = process_list_elem->getInfo(true, current_settings.log_profile_events, false); - status_info_to_query_log(elem, info); + + 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); } 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 deleted file mode 100644 index 14ec14dbf6d..00000000000 --- a/tests/queries/0_stateless/01417_query_time_in_system_events.reference +++ /dev/null @@ -1,3 +0,0 @@ -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 deleted file mode 100755 index ff6d11befb0..00000000000 --- a/tests/queries/0_stateless/01417_query_time_in_system_events.sh +++ /dev/null @@ -1,51 +0,0 @@ -#!/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 -