diff --git a/docs/en/operations/settings/settings.md b/docs/en/operations/settings/settings.md index 91bf0812de4..f9996cbfb0b 100644 --- a/docs/en/operations/settings/settings.md +++ b/docs/en/operations/settings/settings.md @@ -1062,6 +1062,15 @@ Result: └─────────────┴───────────┘ ``` +## log_processors_profiles {#settings-log_processors_profiles} + +Write time that processor spent during execution/waiting for data to `system.processors_profile_log` table. + +See also: + +- [`system.processors_profile_log`](../../operations/system-tables/processors_profile_log.md#system-processors_profile_log) +- [`EXPLAIN PIPELINE`](../../sql-reference/statements/explain.md#explain-pipeline) + ## max_insert_block_size {#settings-max_insert_block_size} The size of blocks (in a count of rows) to form for insertion into a table. diff --git a/docs/en/operations/system-tables/processors_profile_log.md b/docs/en/operations/system-tables/processors_profile_log.md new file mode 100644 index 00000000000..2d76edb5dd7 --- /dev/null +++ b/docs/en/operations/system-tables/processors_profile_log.md @@ -0,0 +1,75 @@ +# system.processors_profile_log {#system-processors_profile_log} + +This table contains profiling on processors level (that you can find in [`EXPLAIN PIPELINE`](../../sql-reference/statements/explain.md#explain-pipeline)). + +Columns: + +- `event_date` ([Date](../../sql-reference/data-types/date.md)) — The date when the event happened. +- `event_time` ([DateTime64](../../sql-reference/data-types/datetime64.md)) — The date and time when the event happened. +- `id` ([UInt64](../../sql-reference/data-types/int-uint.md)) — ID of processor +- `parent_ids` ([Array(UInt64)](../../sql-reference/data-types/array.md)) — Parent processors IDs +- `query_id` ([String](../../sql-reference/data-types/string.md)) — ID of the query +- `name` ([LowCardinality(String)](../../sql-reference/data-types/lowcardinality.md)) — Name of the processor. +- `elapsed_us` ([UInt64](../../sql-reference/data-types/int-uint.md)) — Number of microseconds this processor was executed. +- `input_wait_elapsed_us` ([UInt64](../../sql-reference/data-types/int-uint.md)) — Number of microseconds this processor was waiting for data (from other processor). +- `output_wait_elapsed_us` ([UInt64](../../sql-reference/data-types/int-uint.md)) — Number of microseconds this processor was waiting because output port was full. + +**Example** + +Query: + +``` sql +EXPLAIN PIPELINE +SELECT sleep(1) + +┌─explain─────────────────────────┐ +│ (Expression) │ +│ ExpressionTransform │ +│ (SettingQuotaAndLimits) │ +│ (ReadFromStorage) │ +│ SourceFromSingleChunk 0 → 1 │ +└─────────────────────────────────┘ + +SELECT sleep(1) +SETTINGS log_processors_profiles = 1 + +Query id: feb5ed16-1c24-4227-aa54-78c02b3b27d4 + +┌─sleep(1)─┐ +│ 0 │ +└──────────┘ + +1 rows in set. Elapsed: 1.018 sec. + +SELECT + name, + elapsed_us, + input_wait_elapsed_us, + output_wait_elapsed_us +FROM system.processors_profile_log +WHERE query_id = 'feb5ed16-1c24-4227-aa54-78c02b3b27d4' +ORDER BY name ASC +``` + +Result: + +``` text +┌─name────────────────────┬─elapsed_us─┬─input_wait_elapsed_us─┬─output_wait_elapsed_us─┐ +│ ExpressionTransform │ 1000497 │ 2823 │ 197 │ +│ LazyOutputFormat │ 36 │ 1002188 │ 0 │ +│ LimitsCheckingTransform │ 10 │ 1002994 │ 106 │ +│ NullSource │ 5 │ 1002074 │ 0 │ +│ NullSource │ 1 │ 1002084 │ 0 │ +│ SourceFromSingleChunk │ 45 │ 4736 │ 1000819 │ +└─────────────────────────┴────────────┴───────────────────────┴────────────────────────┘ +``` + +Here you can see: + +- `ExpressionTransform` was executing `sleep(1)` function, so it `work` will takes 1e6, and so `elapsed_us` > 1e6. +- `SourceFromSingleChunk` need to wait, because `ExpressionTransform` does not accept any data during execution of `sleep(1)`, so it will be in `PortFull` state for 1e6 us, and so `output_wait_elapsed_us` > 1e6. +- `LimitsCheckingTransform`/`NullSource`/`LazyOutputFormat` need to wait until `ExpressionTransform` will execute `sleep(1)` to process the result, so `input_wait_elapsed_us` > 1e6. + +**See Also** + +- [`EXPLAIN PIPELINE`](../../sql-reference/statements/explain.md#explain-pipeline) diff --git a/programs/server/config.xml b/programs/server/config.xml index 3b035fb39ac..3bb26a3a368 100644 --- a/programs/server/config.xml +++ b/programs/server/config.xml @@ -1042,6 +1042,15 @@ 7500 --> + + + system + processors_profile_log
+ + toYYYYMM(event_date) + 7500 +
+ diff --git a/tests/queries/0_stateless/02210_processors_profile_log.reference b/tests/queries/0_stateless/02210_processors_profile_log.reference new file mode 100644 index 00000000000..a056b445bbd --- /dev/null +++ b/tests/queries/0_stateless/02210_processors_profile_log.reference @@ -0,0 +1,38 @@ +-- { echo } +EXPLAIN PIPELINE SELECT sleep(1); +(Expression) +ExpressionTransform + (SettingQuotaAndLimits) + (ReadFromStorage) + SourceFromSingleChunk 0 → 1 +SELECT sleep(1) SETTINGS log_processors_profiles=true, log_queries=1, log_queries_min_type='QUERY_FINISH'; +0 +SYSTEM FLUSH LOGS; +WITH + ( + SELECT query_id + FROM system.query_log + WHERE current_database = currentDatabase() AND Settings['log_processors_profiles']='1' + ) AS query_id_ +SELECT + name, + multiIf( + -- ExpressionTransform executes sleep(), + -- so IProcessor::work() will spend 1 sec. + name = 'ExpressionTransform', elapsed_us>1e6, + -- SourceFromSingleChunk, that feed data to ExpressionTransform, + -- will feed first block and then wait in PortFull. + name = 'SourceFromSingleChunk', output_wait_elapsed_us>1e6, + -- NullSource/LazyOutputFormatLazyOutputFormat are the outputs + -- so they cannot starts to execute before sleep(1) will be executed. + input_wait_elapsed_us>1e6) + elapsed +FROM system.processors_profile_log +WHERE query_id = query_id_ +ORDER BY name; +ExpressionTransform 1 +LazyOutputFormat 1 +LimitsCheckingTransform 1 +NullSource 1 +NullSource 1 +SourceFromSingleChunk 1 diff --git a/tests/queries/0_stateless/02210_processors_profile_log.sql b/tests/queries/0_stateless/02210_processors_profile_log.sql new file mode 100644 index 00000000000..160f8009262 --- /dev/null +++ b/tests/queries/0_stateless/02210_processors_profile_log.sql @@ -0,0 +1,28 @@ +-- { echo } +EXPLAIN PIPELINE SELECT sleep(1); + +SELECT sleep(1) SETTINGS log_processors_profiles=true, log_queries=1, log_queries_min_type='QUERY_FINISH'; +SYSTEM FLUSH LOGS; + +WITH + ( + SELECT query_id + FROM system.query_log + WHERE current_database = currentDatabase() AND Settings['log_processors_profiles']='1' + ) AS query_id_ +SELECT + name, + multiIf( + -- ExpressionTransform executes sleep(), + -- so IProcessor::work() will spend 1 sec. + name = 'ExpressionTransform', elapsed_us>1e6, + -- SourceFromSingleChunk, that feed data to ExpressionTransform, + -- will feed first block and then wait in PortFull. + name = 'SourceFromSingleChunk', output_wait_elapsed_us>1e6, + -- NullSource/LazyOutputFormatLazyOutputFormat are the outputs + -- so they cannot starts to execute before sleep(1) will be executed. + input_wait_elapsed_us>1e6) + elapsed +FROM system.processors_profile_log +WHERE query_id = query_id_ +ORDER BY name;