IssueTracker

Hello,

Background on PostgreSQL and query plans

TL;DR feel free to skip directly to the feature request below if you are already aware of the loops caveat in explain plan actuals.

PostgreSQL can surface “Actual” query runtime telemetry via ANALYZE argument of EXPLAIN.
For example:

->  Bitmap Index Scan on tango_hotel  
    (cost=0.00..611.59 rows=26555 width=0) 
    (actual time=2.492..2.492 rows=25677 loops=410652)
      Index Cond: (tango_three_whiskey.kilo_quebec = 'romeo_echo'::uuid)
      Buffers: shared hit=41475751 read=101
      I/O Timings: read=5.302

Given the above, one would think that the query actually took 2.492 ms to run, and processed 25677 rows. However, this important caveat from the EXPLAIN ANALYZE [1] documentation tells us that this is not true:

In some query plans, it is possible for a subplan node to be executed more than once. For example, the inner index scan will be executed once per outer row in the above nested-loop plan. In such cases, the loops value reports the total number of executions of the node,
-----------> and the actual time and rows values shown are averages per-execution. This is done to make the numbers comparable with the way that the cost estimates are shown.
-----------> Multiply by the loops value to get the total time actually spent in the node.
In the above example, we spent a total of 0.220 milliseconds executing the index scans on tenk2.

Taking the loops caveat into consideration, the Actual Rows here are 25677 rows * 410652 loops; roughly 10 billion rows and Actual Time is 2.492 ms * 410652 loops; roughly 1023 seconds.

Most Postgres EXPLAIN plan visualization/evaluation tools take this caveat into account and apply logic in order to properly display the costs/timings of the plan. Here is an example anonymized plan [2] and also attached [3].

The Feature request

In Cloud SQL, Query Insights shows a visual representation of an EXPLAIN plan similar to the community built tools. It also offers useful tips, pointing out plan nodes with the "Highest Latency”, “Highest Row count” and “Highest Cost”.
Unfortunately, this information is not always accurate; specifically regarding the loops caveat.

Here is an example of where Cloud SQL gets the Latency correct, but it does not apply the loops caveat so the number of rows is incorrect and thus, the "Highest Row count" tip is also incorrect. [4]

Additionally, the “Highest Latency” feature does not work properly. It labels the parent plan node as the “Highest Latency”, yet the only reason the latency is high in the Parent is because of this child subplan node. The example above should be labeled “Highest Latency”, “Highest Row count” and probably “Highest cost”, or cost should be thrown out all together when dealing with the loop caveat as it cannot be trusted.

In Summary, make the following enhancements to Query Insights plan visualizer:

• Take the loops caveat into account when showing "Rows returned" in query plan nodes and when declaring a node as "Highest row count"
• Improve the “Highest Latency” tip, focusing on the actual plan node that is causing the latency

I understand that this information can be retrieved by configuring auto_explain, but having it in the UI would make it much more accessible to Cloud SQL users.

Thank you!

References:

[1] https://www.postgresql.org/docs/current/using-explain.html#USING-EXPLAIN-ANALYZE
[2] https://explain.dalibo.com/plan/964ec4a3f2b3c1a9#plan/node/10
[3] dalibo_screenshot.jpg
[4] bad_rows_returnd.jpg