Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Print stats for each individual operator in EXPLAIN ANALYZE VERBOSE #14405

Conversation

sopel39
Copy link
Member

@sopel39 sopel39 commented Sep 30, 2022

Example
 Fragment 2 [HASH]
     CPU: 41.22s, Scheduled: 1.08m, Blocked 2.61m (Input: 48.15s, Output: 0.00ns), Input: 119972104 rows (2.01GB); per task: avg.: 119972104.00 std.dev.: 0.00, Output: 8 rows (
     Output layout: [count_19]
     Output partitioning: SINGLE []
     Aggregate[type = PARTIAL]
     │   Layout: [count_19:bigint]
     │   CPU: 1.30s (1.92%), Scheduled: 2.00s (1.20%), Blocked: 0.00ns (0.00%), Output: 8 rows (72B)
     │   AggregationOperator metrics:
     │     'CPU time distribution (s)' = {count=8.00, p01=0.15, p05=0.15, p10=0.15, p25=0.15, p50=0.17, p75=0.18, p90=0.18, p95=0.18, p99=0.18, min=0.15, max=0.18}
     │     'Input rows distribution' = {count=8.00, p01=36809359.00, p05=36809359.00, p10=36809359.00, p25=37080874.00, p50=37387039.00, p75=38224448.00, p90=38731833.00, p95=3
     │     'Wall time distribution (s)' = {count=8.00, p01=0.20, p05=0.20, p10=0.20, p25=0.23, p50=0.27, p75=0.27, p90=0.32, p95=0.32, p99=0.32, min=0.20, max=0.32}
     │   TaskOutputOperator metrics:
     │     'CPU time distribution (s)' = {count=8.00, p01=0.00, p05=0.00, p10=0.00, p25=0.00, p50=0.00, p75=0.00, p90=0.00, p95=0.00, p99=0.00, min=0.00, max=0.00}
     │     'Input rows distribution' = {count=8.00, p01=1.00, p05=1.00, p10=1.00, p25=1.00, p50=1.00, p75=1.00, p90=1.00, p95=1.00, p99=1.00, min=1.00, max=1.00}
     │     'Wall time distribution (s)' = {count=8.00, p01=0.00, p05=0.00, p10=0.00, p25=0.00, p50=0.00, p75=0.00, p90=0.00, p95=0.00, p99=0.00, min=0.00, max=0.00}
     │   Input avg.: 37485342.50 rows, Input std.dev.: 1.71%
     │   count_19 := count("orderkey")
     └─ InnerJoin[criteria = ("orderkey" = "orderkey_0"), hash = [$hashvalue, $hashvalue_21], distribution = PARTITIONED]
        │   Layout: [orderkey:bigint]
        │   Reorder joins cost : {rows: 239034200 (2.00GB), cpu: 5.52G, memory: 514.86MB, network: 1.01GB}
        │   Estimates: {rows: 239034200 (2.00GB), cpu: 4.01G, memory: 1.01GB, network: 0B}
        │   CPU: 29.98s (44.16%), Scheduled: 43.86s (26.35%), Blocked: 1.20m (14.13%), Output: 299882740 rows (1.62GB)
        │   LookupJoinOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=2.38, p05=2.38, p10=2.38, p25=2.42, p50=2.44, p75=2.50, p90=2.51, p95=2.51, p99=2.51, min=2.38, max=2.51}
        │     'Input rows distribution' = {count=8.00, p01=7363095.00, p05=7363095.00, p10=7363095.00, p25=7416595.00, p50=7479924.00, p75=7646558.00, p90=7746970.00, p95=77469
        │     'Wall time distribution (s)' = {count=8.00, p01=3.14, p05=3.14, p10=3.14, p25=3.19, p50=3.20, p75=3.26, p90=3.27, p95=3.27, p99=3.27, min=3.14, max=3.27}
        │   DynamicFilterSourceOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=0.04, p05=0.04, p10=0.04, p25=0.04, p50=0.04, p75=0.04, p90=0.05, p95=0.05, p99=0.05, min=0.04, max=0.05}
        │     'Input rows distribution' = {count=8.00, p01=7489515.00, p05=7489515.00, p10=7489515.00, p25=7495257.00, p50=7496362.00, p75=7506635.00, p90=7510105.00, p95=75101
        │     'Wall time distribution (s)' = {count=8.00, p01=0.12, p05=0.12, p10=0.12, p25=0.14, p50=0.16, p75=0.19, p90=0.21, p95=0.21, p99=0.21, min=0.12, max=0.21}
        │   HashBuilderOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=1.21, p05=1.21, p10=1.21, p25=1.23, p50=1.24, p75=1.32, p90=1.40, p95=1.40, p99=1.40, min=1.21, max=1.40}
        │     'Input rows distribution' = {count=8.00, p01=7489515.00, p05=7489515.00, p10=7489515.00, p25=7495257.00, p50=7496362.00, p75=7506635.00, p90=7510105.00, p95=75101
        │     'Wall time distribution (s)' = {count=8.00, p01=2.00, p05=2.00, p10=2.00, p25=2.04, p50=2.14, p75=2.21, p90=2.28, p95=2.28, p99=2.28, min=2.00, max=2.28}
        │   Left (probe) Input avg.: 7498256.50 rows, Input std.dev.: 1.72%
        │   Right (build) Input avg.: 7498256.50 rows, Input std.dev.: 0.09%
        │   Collisions avg.: 472153.48 (15.58% est.), Collisions std.dev.: 0.33%
        │   Distribution: PARTITIONED
        │   dynamicFilterAssignments = {orderkey_0 -> #df_401}

Example
 Fragment 2 [HASH]
     CPU: 41.22s, Scheduled: 1.08m, Blocked 2.61m (Input: 48.15s, Output: 0.00ns), Input: 119972104 rows (2.01GB); per task: avg.: 119972104.00 std.dev.: 0.00, Output: 8 rows (
     Output layout: [count_19]
     Output partitioning: SINGLE []
     Aggregate[type = PARTIAL]
     │   Layout: [count_19:bigint]
     │   CPU: 1.30s (1.92%), Scheduled: 2.00s (1.20%), Blocked: 0.00ns (0.00%), Output: 8 rows (72B)
     │   AggregationOperator metrics:
     │     'CPU time distribution (s)' = {count=8.00, p01=0.15, p05=0.15, p10=0.15, p25=0.15, p50=0.17, p75=0.18, p90=0.18, p95=0.18, p99=0.18, min=0.15, max=0.18}
     │     'Input rows distribution' = {count=8.00, p01=36809359.00, p05=36809359.00, p10=36809359.00, p25=37080874.00, p50=37387039.00, p75=38224448.00, p90=38731833.00, p95=3
     │     'Wall time distribution (s)' = {count=8.00, p01=0.20, p05=0.20, p10=0.20, p25=0.23, p50=0.27, p75=0.27, p90=0.32, p95=0.32, p99=0.32, min=0.20, max=0.32}
     │   TaskOutputOperator metrics:
     │     'CPU time distribution (s)' = {count=8.00, p01=0.00, p05=0.00, p10=0.00, p25=0.00, p50=0.00, p75=0.00, p90=0.00, p95=0.00, p99=0.00, min=0.00, max=0.00}
     │     'Input rows distribution' = {count=8.00, p01=1.00, p05=1.00, p10=1.00, p25=1.00, p50=1.00, p75=1.00, p90=1.00, p95=1.00, p99=1.00, min=1.00, max=1.00}
     │     'Wall time distribution (s)' = {count=8.00, p01=0.00, p05=0.00, p10=0.00, p25=0.00, p50=0.00, p75=0.00, p90=0.00, p95=0.00, p99=0.00, min=0.00, max=0.00}
     │   Input avg.: 37485342.50 rows, Input std.dev.: 1.71%
     │   count_19 := count("orderkey")
     └─ InnerJoin[criteria = ("orderkey" = "orderkey_0"), hash = [$hashvalue, $hashvalue_21], distribution = PARTITIONED]
        │   Layout: [orderkey:bigint]
        │   Reorder joins cost : {rows: 239034200 (2.00GB), cpu: 5.52G, memory: 514.86MB, network: 1.01GB}
        │   Estimates: {rows: 239034200 (2.00GB), cpu: 4.01G, memory: 1.01GB, network: 0B}
        │   CPU: 29.98s (44.16%), Scheduled: 43.86s (26.35%), Blocked: 1.20m (14.13%), Output: 299882740 rows (1.62GB)
        │   LookupJoinOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=2.38, p05=2.38, p10=2.38, p25=2.42, p50=2.44, p75=2.50, p90=2.51, p95=2.51, p99=2.51, min=2.38, max=2.51}
        │     'Input rows distribution' = {count=8.00, p01=7363095.00, p05=7363095.00, p10=7363095.00, p25=7416595.00, p50=7479924.00, p75=7646558.00, p90=7746970.00, p95=77469
        │     'Wall time distribution (s)' = {count=8.00, p01=3.14, p05=3.14, p10=3.14, p25=3.19, p50=3.20, p75=3.26, p90=3.27, p95=3.27, p99=3.27, min=3.14, max=3.27}
        │   DynamicFilterSourceOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=0.04, p05=0.04, p10=0.04, p25=0.04, p50=0.04, p75=0.04, p90=0.05, p95=0.05, p99=0.05, min=0.04, max=0.05}
        │     'Input rows distribution' = {count=8.00, p01=7489515.00, p05=7489515.00, p10=7489515.00, p25=7495257.00, p50=7496362.00, p75=7506635.00, p90=7510105.00, p95=75101
        │     'Wall time distribution (s)' = {count=8.00, p01=0.12, p05=0.12, p10=0.12, p25=0.14, p50=0.16, p75=0.19, p90=0.21, p95=0.21, p99=0.21, min=0.12, max=0.21}
        │   HashBuilderOperator metrics:
        │     'CPU time distribution (s)' = {count=8.00, p01=1.21, p05=1.21, p10=1.21, p25=1.23, p50=1.24, p75=1.32, p90=1.40, p95=1.40, p99=1.40, min=1.21, max=1.40}
        │     'Input rows distribution' = {count=8.00, p01=7489515.00, p05=7489515.00, p10=7489515.00, p25=7495257.00, p50=7496362.00, p75=7506635.00, p90=7510105.00, p95=75101
        │     'Wall time distribution (s)' = {count=8.00, p01=2.00, p05=2.00, p10=2.00, p25=2.04, p50=2.14, p75=2.21, p90=2.28, p95=2.28, p99=2.28, min=2.00, max=2.28}
        │   Left (probe) Input avg.: 7498256.50 rows, Input std.dev.: 1.72%
        │   Right (build) Input avg.: 7498256.50 rows, Input std.dev.: 0.09%
        │   Collisions avg.: 472153.48 (15.58% est.), Collisions std.dev.: 0.33%
        │   Distribution: PARTITIONED
        │   dynamicFilterAssignments = {orderkey_0 -> #df_401}
Copy link
Member

@raunaqmorarka raunaqmorarka left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks like it's increasing the verbosity of VERBOSE significantly.
If wonder if operator level details like this are too low level to be part of plan output even in verbose. Ideally even in verbose mode most of the things should be understandable and useful to end-users.
It would be great to at least provide an example or explanation of how to use this in explain-analyze.rst
Maybe this info belongs in web ui and event listener.

@sopel39
Copy link
Member Author

sopel39 commented Oct 11, 2022

Supreceded by #14572

@sopel39 sopel39 closed this Oct 11, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

Successfully merging this pull request may close these issues.

2 participants