Redshift latency, i.e. discrepancy between "execution time" and "total runtime"

Viewed 979

I'm currently experimenting with Redshift and I've noticed that for a simple query like:

SELECT COUNT(*) FROM table WHERE column = 'value';

The execution time reported by Redshift is only 84ms, which is expected and pretty good with the table at ~33M rows. However, the total runtime, both observed on my local psql client as well as in Redshift's console UI is 5 seconds. I've tried the query on both a single node cluster and multi-node (2 nodes and 4 nodes) clusters.

In addition, when I try with more realistic, complicated queries, I can see similarly that the query execution itself is only ~500ms in a lot of cases, but the total runtime is ~7 seconds.

What causes this discrepancy? Is there anyway to reduce this latency? Any internal table to dive deeper into the time distribution that covers the entire end-to-end runtime?

I read about Cold query performance improvements that Amazon recently introduced, but this latency seems to be there even on queries past the first cold one, as long as I alter the value in my where clause. However, the latency is somewhat inconsistent but definitely still go all the way up to 5 seconds.

-- Edited to give more details based on Bill Weiner's answer below --

  • There is no difference between doing SELECT COUNT(*) vs SELECT COUNT(column) (where column is a dist key to avoid skew).
  • There are absolutely zero other activities happening on the cluster because this is for exploration only. I'm the only one issuing queries and making connections to the DB, so there should be no queueing or locking delays.
  • The data resides in the Redshift database, with a normal schema and common-sense dist key and sort key. I have not added explicit compression to any columns, so everything is just AUTO right now.

Looks like compile time is the culprit!

STL_WLM_QUERY shows that for query 12599, this is the exec_start_time/exec_end_time:

-[ RECORD 1 ]------------+-----------------------------------------------------------------
userid                   | 100
xid                      | 14812605
task                     | 7289
query                    | 12599
service_class            | 100
slot_count               | 1
service_class_start_time | 2021-04-22 21:46:49.217
queue_start_time         | 2021-04-22 21:46:49.21707
queue_end_time           | 2021-04-22 21:46:49.21707
total_queue_time         | 0
exec_start_time          | 2021-04-22 21:46:49.217077
exec_end_time            | 2021-04-22 21:46:53.762903
total_exec_time          | 4545826
service_class_end_time   | 2021-04-22 21:46:53.762903
final_state              | Completed
est_peak_mem             | 2097152
query_priority           | Normal
service_class_name       | Default queue

And from SVL_COMPILE, we have:

 userid |   xid    |  pid  | query | segment | locus |         starttime          |          endtime           | compile
--------+----------+-------+-------+---------+-------+----------------------------+----------------------------+---------
    100 | 14812605 | 30442 | 12599 |       0 |     1 | 2021-04-22 21:46:49.218872 | 2021-04-22 21:46:53.744529 |       1
    100 | 14812605 | 30442 | 12599 |       2 |     2 | 2021-04-22 21:46:53.745711 | 2021-04-22 21:46:53.745728 |       0
    100 | 14812605 | 30442 | 12599 |       3 |     2 | 2021-04-22 21:46:53.761989 | 2021-04-22 21:46:53.762015 |       0
    100 | 14812605 | 30442 | 12599 |       1 |     1 | 2021-04-22 21:46:53.745476 | 2021-04-22 21:46:53.745503 |       0
(4 rows)

It shows that compile took from 21:46:49.218872 to 2021-04-22 21:46:53.744529, i.e. the overwhelming majority of the 4545ms total exec time.

1 Answers

There's a lot that could be taking up this time. Looking a more of the query and queuing statistics will help track down what is happening. Here are a few possibilities that I've seen be significant in the past:

  1. Date return time. Since your query is an open select and could be returning a meaningful amount of data and moving this over the network to the requesting computer takes time.
  2. Queuing delays. What else is happening on your cluster? Does you query start right away or does it need to wait for a slot?
  3. Locking delays. What else is happening on your cluster? Are data/tables changing? Is the data your query needs being committed elsewhere?
  4. Compile time. Is this the first time this query is run?
  5. Is the table external? In S3 as an external table. Or are you using the new rs3 instance type? All the source data is in S3. (I'm guessing you are not on rs3 nodes but it doesn't hurt to ask)

A place to start is STL_WLM_QUERY to see where the query is spending this extra time.

Related