Some time ago my team noticed extreme slowness in SELECT queries on our production server. For a table with over 1 million rows, we're talking about a couple of minutes. These are simple queries, e.g.

SELECT id, name, serno FROM public.product_facts;

This, by contrast, is extremely fast:

EXPLAIN ANALYZE SELECT id, name, serno FROM public.product_facts;

The latter returns stats like the following:

Seq Scan on product_facts (cost=0.00..58167.86 rows=1339186 width=24) (actual time=0.012..435.753 rows=1399186 loops=1)
Planning time: 0.076 ms
Execution time: 708.078 ms

Likewise, this is very fast:

SELECT COUNT (id) FROM public.product_facts;

Server memory and CPU do not appear taxed. If I run the barebones SELECT in a tab in PGadmin and leave it to do its thing, I can run a separate operation in another tab or elsewhere, and it runs fine. Furthermore, examining processes and system consumption via top, I can see no sign of excessive CPU or memory consumption.

Network lag appears also an unlikely culprit. The network response times are within normal limits. This odd slowness started a few weeks ago, as mentioned, on our production server, then appeared on our UAT, and now on our non-production instance as well. Slowness seems proportional to record count but applies across all tables.

The EXPLAIN ANALYZE case is to me the most perplexing part of this whole situation. From my reading of the Postgres docs, I gather that the ANALYZE keyword causes the server to actually execute the command in question, then return the analysis of that execution. So how could a SELECT query take half a second in that case but over one minute in another case, with no indication of memory or CPU overload?

  • What's missing in your analisys is I/O. Try explain (analyze,buffers,verbose) <query> and check difference in shared hit and dirtied in consecutive runs of explain (analyze,buffers,verbose) .... Please add your findings to the question. Also, when running SELECT without EXPLAIN turn on '\timing to measure time and redirect your output to /dev/null to eliminate console output as your bottleneck (which is most likely the culprint). – tbielaszewski Nov 10 '20 at 8:58

EXPLAIN ANALYZE SELECT... executes the query, but sends to the client a single row consisting of the execution plan, which means a few hundred bytes to ship across the network and process on the client side.

The actual SELECT without the EXPLAIN ANALYZE sends all the results, which are over a million rows here. And when the client receives these results, it has to do something with them.

So it is to be expected that the second form is slower overall, even if several minutes versus 708ms is indeed a very significant difference.

There are two factors to consider to explain this difference: how big is the result in relation to how fast the network is, and how costly is the per-row client-side process. For instance, some graphical clients take a lot of time just putting results into columns. Or the psql command-line client formats the output by default to align the contents inside columns with blank-padding, which on some contents consume a lot of time.

If you're using psql, see how much time it takes with this sequence:

\set timing on
\pset format unaligned
SELECT id, name, serno FROM public.product_facts \g /dev/null

For the size of the resultset that is sent across the network, the result of SELECT sum(octet_length(concat(id,name,serno))) FROM public.product_facts should be a good ballpark estimate.

So how could a SELECT query take half a second in that case but over one minute in another case, with no indication of memory or CPU overload?

I think you're looking at the server, when what is consuming the time happens on the network and/or on the client machine. The server is just probably pushing results to the network socket as fast as the network is accepting them, and that generally does not keep a CPU busy.

  • 24 hours ago I wouldn't have agreed with you, but suddenly the queries are extremely fast. Even grabbing the entire 1M+ rows from our largest table isn't nearly as slow as it has been. And looking at the long-term system metrics, I can't see any indication of a change in the machine itself. So the simplest remaining explanation is a fluctuating network.Considering that it has taken upwards of 30 seconds to produce sets of 100 rows during business hours (again, simple SELECT queries), this network must have significant load-handling problems. – lima Nov 11 '20 at 6:51

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.