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(*)vsSELECT COUNT(column)(wherecolumnis 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
AUTOright 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.