Simplifying SQL query analysis with EXPLAIN (ANALYZE)

Introduction

The EXPLAIN (ANALYZE) function in SQL offers a powerful method for dissecting and diagnosing the performance of your queries. By prefixing this command to your SELECT statement, it provides a comprehensive execution plan detailing the engine’s processing steps. When paired with ANALYZE, it also executes the query, delivering real-time performance metrics like execution time and resource consumption. This dual functionality helps identify inefficiencies, offering a pathway to query and performance optimization.

Understanding the Execution Plan

An execution plan from EXPLAIN (ANALYZE) is read from bottom to top, detailing steps including data access, filtering, and final output preparation. Key components include:

  • StoredTable: Indicates tables or Aggregating indexes used, showing how many columns are involved and identifying the table type (e.g., FACT or DIMENSION).

  • Predicate: Shows how the query filters data, detailing the conditions applied.

  • Projection: Represents the output, which could be either a query result or an intermediate state in complex queries.

  • Aggregate: Details grouping operations, crucial for queries involving aggregate functions like SUM, AVG, etc.

  • Join: Displays information about how tables are merged based on join conditions.

  • Sort: Lists sorting operations, essential for ordered outputs.
    These steps contain sub-components like:

  • RowType: Provides specifics on the data types involved.

  • Execution Metrics: Offers critical insights into the number of rows processed and the time taken, valuable for pinpointing performance bottlenecks.

    • Output cardinality: Indicates how many rows from the table were read during this step.

    • Thread time: Represents the time this query part ran, including CPU wait time.

    • CPU time: Illustrates the time this part of the query ran on the CPU.

Practical Examples

All the example SQL code uses the Ultra Fast Gaming data set. To familiarize yourself with this data set, visit this link: Ultra Fast Gaming Firebolt Sample Dataset.

Example 1: Basic Filtering

Example SQL code:

EXPLAIN (ANALYZE)
SELECT * FROM players 
WHERE registeredon = '2022-07-22';

EXPLAIN Output:

[0] [Projection] ref_0, ref_1, ref_2, ref_3, ref_4, DATE '2022-07-22', ref_6, ref_7, ref_8, ref_9
|   [RowType]: integer null, text null, text null, text null, array(text null) null, date not null, boolean null, double precision null, text null, timestamp null
|   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
 \_[1] [Filter] (ref_5 = DATE '2022-07-22')
   |   [RowType]: integer null, text null, text null, text null, array(text null) null, date null, boolean null, double precision null, text null, timestamp null
   |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
    \_[2] [StoredTable] Name: "players", used 10/10 column(s) FACT, ref_0: "playerid" ref_1: "nickname" ref_2: "email" ref_3: "agecategory" ref_4: "platforms" ref_5: "registeredon" ref_6: "issubscribedtonewsletter" ref_7: "internalprobabilitytowin" ref_8: "source_file_name" ref_9: "source_file_timestamp"
          [RowType]: integer null, text null, text null, text null, array(text null) null, date null, boolean null, double precision null, text null, timestamp null
          [Execution Metrics]: output cardinality = 11, thread time = 2ms, cpu time = 2ms

Output analysis:

  • [StoredTable] Step: Identifies the players table with all 10 columns read. Processes 11 rows in 2ms CPU time (and Thread time), illustrating efficient data access.
    • Note: Due to filtering on a primary index column (registeredon), Firebolt reads only the relevant rows, relying on the primary index. Consequently, on [StoredTable] step, the output_cardinality is significantly less than the total number of rows in the table, which is 5420 rows.

    • Note: thread_time is the sum of the wall-clock time that threads spent working on this operator across all nodes. cpu_time is the sum of the time these threads where scheduled on a CPU core. If cpu_time is considerably smaller than thread_time, this indicates that the operator is waiting a lot on IO or the engine is under multiple queries at once. Throughout this article, we usually see CPU time = Thread time.

  • [Filter] Step: Applies a filter on registeredon column matching 2022-07-22. Keeps cardinality consistent, demonstrating focused data retrieval from the very first step.
  • Note: On the [Filter] step, the number of rows (output_cardinality) can be pruned even further to most accurately represent the rows in the primary index.
  • [Projection] Step: Outputs all fields with the same cardinality, confirming direct data fetch based on the date filter.

Example 2: Limiting Results

Example SQL code:

EXPLAIN (ANALYZE)
SELECT * 
FROM players 
WHERE registeredon = '2022-07-22' 
LIMIT 100;

EXPLAIN Output:

[0] [Projection] ref_0, ref_1, ref_2, ref_3, ref_4, DATE '2022-07-22', ref_5, ref_6, ref_7, ref_8
|   [RowType]: integer null, text null, text null, text null, array(text null) null, date not null, boolean null, double precision null, text null, timestamp null
|   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
 \_[1] [Sort] OrderBy: [] Limit: [100]
   |   [RowType]: integer null, text null, text null, text null, array(text null) null, boolean null, double precision null, text null, timestamp null
   |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
    \_[2] [Projection] ref_0, ref_1, ref_2, ref_3, ref_4, ref_6, ref_7, ref_8, ref_9
      |   [RowType]: integer null, text null, text null, text null, array(text null) null, boolean null, double precision null, text null, timestamp null
      |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
       \_[3] [Filter] (ref_5 = DATE '2022-07-22')
         |   [RowType]: integer null, text null, text null, text null, array(text null) null, date null, boolean null, double precision null, text null, timestamp null
         |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
          \_[4] [StoredTable] Name: "players", used 10/10 column(s) FACT, ref_0: "playerid" ref_1: "nickname" ref_2: "email" ref_3: "agecategory" ref_4: "platforms" ref_5: "registeredon" ref_6: "issubscribedtonewsletter" ref_7: "internalprobabilitytowin" ref_8: "source_file_name" ref_9: "source_file_timestamp"
                [RowType]: integer null, text null, text null, text null, array(text null) null, date null, boolean null, double precision null, text null, timestamp null
                [Execution Metrics]: output cardinality = 11, thread time = 2ms, cpu time = 2ms

Output analysis:

  • [StoredTable] to [Filter] Steps: Similar to Example 1, processing 11 rows reflecting a direct data fetch without additional computational overhead.

  • [Sort] and an additional [Projection] Step: Incorporates a LIMIT clause, however, as the data volume is already minimal, no additional cost or time is incurred.

Example 3: Complex Query with Joins and Aggregations

Example SQL code:

EXPLAIN (ANALYZE)
SELECT players.agecategory, AVG(playstats.currentscore)
FROM players
LEFT JOIN playstats ON playstats.playerid = players.playerid
WHERE registeredon = '2022-07-22'
GROUP BY all;

EXPLAIN Output:

[0] [Projection] ref_0, ref_1
|   [RowType]: text null, double precision null
|   [Execution Metrics]: output cardinality = 4, thread time = 0ms, cpu time = 0ms
 \_[1] [Aggregate] GroupBy: [ref_1] Aggregates: [avg2(ref_0)]
   |   [RowType]: text null, double precision null
   |   [Execution Metrics]: output cardinality = 4, thread time = 49ms, cpu time = 49ms
    \_[2] [Projection] ref_1, ref_3
      |   [RowType]: bigint null, text null
      |   [Execution Metrics]: output cardinality = 1809815, thread time = 0ms, cpu time = 0ms
       \_[3] [Join] Mode: Right [(ref_0 = ref_2)]
         |   [RowType]: integer null, bigint null, integer null, text null
         |   [Execution Metrics]: output cardinality = 1809815, thread time = 15289ms, cpu time = 15188ms
          \_[4] [StoredTable] Name: "playstats", used 2/13 column(s) FACT, ref_0: "playerid" ref_1: "currentscore"
          |     [RowType]: integer null, bigint null
          |     [Execution Metrics]: output cardinality = 1036270144, thread time = 10580ms, cpu time = 9749ms
          \_[5] [Projection] ref_0, ref_1
            |   [RowType]: integer null, text null
            |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
             \_[6] [Filter] (ref_2 = DATE '2022-07-22')
               |   [RowType]: integer null, text null, date null
               |   [Execution Metrics]: output cardinality = 11, thread time = 0ms, cpu time = 0ms
                \_[7] [StoredTable] Name: "players", used 3/10 column(s) FACT, ref_0: "playerid" ref_1: "agecategory" ref_2: "registeredon"
                      [RowType]: integer null, text null, date null
                      [Execution Metrics]: output cardinality = 11, thread time = 1ms, cpu time = 1ms

Output analysis:

  • [StoredTable] Steps: Two table are accessed, players and playstats, showing large data movement particularly from playstats with over 1 billion rows processed, consuming significant CPU time (9749ms). Notice Thread time equals 10580ms, suggesting there was a minor overhead on IO operations.

  • [Join] Step: Merges data on playerid, maintaining high cardinality, illustrating the computational load of the join operation with over 15 seconds of CPU time (15188ms).

    • Note: Although the SQL specifies a LEFT JOIN, the plan shows a RIGHT JOIN (Mode: Right). This is due to the Firebolt optimizer that can decide to transform it into a RIGHT JOIN if it determines that it will be more efficient, by processing the larger table first.
  • [Aggregate] Step: Aggregation for average calculation on currentscore, handled efficiently post-join with reduced output cardinality and moderate CPU time (49ms).

You may find this interesting -

In the example above, the query plan shows a total CPU time of 15 seconds for the JOIN operation and 9 seconds for retrieving data from the playstats table. While these times might initially seem high, they actually demonstrate impressive performance given the scale of the data involved.

Specifically, the query is processing and joining over 1 billion rows in a remarkably short time frame. This efficiency is achieved through the Firebolt optimizer intelligent decisions, such as transforming a LEFT JOIN into a RIGHT JOIN to leverage optimal data process.

Conclusion

Utilizing EXPLAIN (ANALYZE) effectively allows developers to peer into the SQL processing workflow, making it an indispensable tool for optimizing queries. By understanding each step of the execution plan and the resources involved, one can fine-tune their queries to achieve better performance and efficiency.

For further details and advanced usage, refer to the official documentation on the EXPLAIN command.