ClickHouse/docs/en/operations/system-tables/processors_profile_log.md
Azat Khuzhin 14538f6456 Add system.processors_profile_log
This is the system table that will contain Processors level profiling.

v2: one entry per Processor, not 3 (PortFull/NeedData/work())
v3: us over ms
v4: Enable processors_profile_log table by default

Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-04 13:19:41 +03:00

3.6 KiB

system.processors_profile_log

This table contains profiling on processors level (that you can find in EXPLAIN PIPELINE).

Columns:

  • event_date (Date) — The date when the event happened.
  • event_time (DateTime64) — The date and time when the event happened.
  • query_id (String) — ID of the query
  • name (LowCardinality(String)) — Name of the processor.
  • elapsed_us (UInt64) — Number of microseconds this processor was executed.
  • need_data_elapsed_us (UInt64) — Number of microseconds this processor was waiting for data (from other processor).
  • port_full_elapsed_us (UInt64) — Number of microseconds this processor was waiting because output port was full.

Example

Query:

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,
    need_data_elapsed_us,
    port_full_elapsed_us
FROM system.processors_profile_log
WHERE query_id = 'feb5ed16-1c24-4227-aa54-78c02b3b27d4'
ORDER BY name ASC

Result:

┌─name────────────────────┬─elapsed_us─┬─need_data_elapsed_us─┬─port_full_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 port_full_elapsed_us > 1e6.
  • LimitsCheckingTransform/NullSource/LazyOutputFormat need to wait until ExpressionTransform will execute sleep(1) to process the result, so need_data_elapsed_us > 1e6.

See Also