Many times, we see PostgreSQL users getting confused about the query/statement duration reported in PostgreSQL logs. Other PostgreSQL tools like pgBadger present the same data based on the log file, which further increases the confusion. Knowing the full impact of network-related overhead and cursors is important not only to alleviate the confusion but also to get the best performance.
One might ask “Why discuss Network overhead and Cursors specifically?”. Well, they are the hidden cost after the/in the query execution. Once the query execution starts and there is some data to be given to the client, these are the factors that mainly affect the performance. So the important point which we may want to keep in mind is since all these happens outside the query execution, the corresponding information will not be available through the EXPLAIN (ANALYZE).
Impact of Network
For the demonstration, I am using a query based on pgBench tables.
1 2 3 | select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid; |
There is no significance for this query. A random query is selected which takes some time in the database to execute.
In order to capture the Explain Analyze output, auto_explain is used. Settings are made to capture all statements which take more than 250ms.
1 | ALTER SYSTEM SET auto_explain.log_min_duration = 250 |
A few other settings to capture additional details with EXPLAIN ANALYZE are:
1 2 3 4 5 6 | ALTER SYSTEM SET auto_explain.log_analyze = on; ALTER SYSTEM SET auto_explain.log_buffers=on; ALTER SYSTEM SET auto_explain.log_timing=on; ALTER SYSTEM SET auto_explain.log_verbose=on; ALTER SYSTEM SET auto_explain.log_triggers=on; ALTER SYSTEM SET auto_explain.log_wal=on; |
In order to Illustratre the difference, the same query will be executed from
1. The database Host Server
2. The application Host Server that is connected over a network
Queries Returning a Large Number of Rows
Case 1. Executing on the Database Host Itself
Following are the few lines from PostgreSQL logs generated by auto_explain:
1 2 3 4 5 6 7 8 9 | 2021-08-02 03:27:56.347 UTC [25537] LOG: duration: 1591.784 ms plan: Query Text: select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid; Nested Loop (cost=12322.13..63020.46 rows=833333 width=12) (actual time=119.739..1069.924 rows=1000000 loops=1) Output: a.bid, b.cnt Join Filter: (b.bid > a.bid) Rows Removed by Join Filter: 1500000 ... |
As we can see, the outer nested loop of the query was completed in 1069.924 ms returning 1 million records, but the total duration of the query is reported as 1591.784 ms. What could be the difference?
A straight, EXPLAIN ANALYZE shows that the planning time is sub milliseconds for this simple query where data is coming from a single table without any index. So the planning time shouldn’t be the reason.
Case 2. Executing from a Remote Application Host
Again the information from the PostgreSQL log looks different:
1 2 3 4 5 6 7 8 9 | 2021-08-02 04:08:58.955 UTC [25617] LOG: duration: 6568.659 ms plan: Query Text: select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid; Nested Loop (cost=12322.13..63020.46 rows=833333 width=12) (actual time=140.644..1069.153 rows=1000000 loops=1) Output: a.bid, b.cnt Join Filter: (b.bid > a.bid) Rows Removed by Join Filter: 1500000 ... |
As we can see the statement duration jumped to 6568.659 ms! even though the actual execution of the query remained pretty much the same 1069.153 ms. That’s a huge difference. What could be the reason?
Queries Returning a Fewer Number of Rows
The above-mentioned query can be slightly modified to return only the max values. The modified test query may look like this:
1 2 3 | select max(a.bid), max(b.cnt) from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid ; |
The query plan or time doesn’t change much other than there is an additional aggregate. Even if there is a change in plan that is not relevant for the topic, we are discussing it because we are considering only the time difference between the outer node of the query execution and the duration reported by PostgreSQL.
Case 1: Executing on the Database Host Itself
1 2 3 4 5 6 7 8 9 10 11 12 | 2021-08-03 06:58:14.364 UTC [28129] LOG: duration: 1011.143 ms plan: Query Text: select max(a.bid), max(b.cnt) from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid ; Aggregate (cost=67187.12..67187.13 rows=1 width=12) (actual time=1010.914..1011.109 rows=1 loops=1) Output: max(a.bid), max(b.cnt) Buffers: shared hit=12622 read=3786 -> Nested Loop (cost=12322.13..63020.46 rows=833333 width=12) (actual time=135.635..908.315 rows=1000000 loops=1) Output: a.bid, b.cnt Join Filter: (b.bid > a.bid) Rows Removed by Join Filter: 1500000 Buffers: shared hit=12622 read=3786 |
As we can see there is not much difference between the completion of the query 1011.109 and the duration reported 1011.143 ms. The observation so far indicates that there is extra time consumed when there is a lot of rows are returned.
Case 2: Executing the Statement from the Remote Host
1 2 3 4 5 6 7 8 9 10 11 12 | 2021-08-03 06:55:37.221 UTC [28111] LOG: duration: 1193.387 ms plan: Query Text: select max(a.bid), max(b.cnt) from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid ; Aggregate (cost=67187.12..67187.13 rows=1 width=12) (actual time=1193.139..1193.340 rows=1 loops=1) Output: max(a.bid), max(b.cnt) Buffers: shared hit=11598 read=4810 -> Nested Loop (cost=12322.13..63020.46 rows=833333 width=12) (actual time=124.508..1067.409 rows=1000000 loops=1) Output: a.bid, b.cnt Join Filter: (b.bid > a.bid) Rows Removed by Join Filter: 1500000 Buffers: shared hit=11598 read=4810 |
Again there is not much difference 1193.340 vs 1193.387 ms. Overall, I feel safe to assume from the results that if the data transfer is minimal, the application server on a different host machine doesn’t make much difference; meanwhile, the impact is huge if there is a lot of result transfer is involved.
Analyzing the Wait Events
Luckily, newer versions of PostgreSQL provide us with an excellent way to monitor the “wait event” information from the pg_stat_activity view of session/connection.
At Percona support we use a script from pg_gather snippet for gathering performance information including the wait events by collecting multiple samples. The script collects samples of wait events in every 10ms gap, so there will be 2000 samples in 20 seconds. Apart from UI, the gathered information can be analyzed using backend queries also.
The following is what I could see about PID: 25617 (the case of returning a large number of rows to remote host).
1 2 3 4 5 6 7 | postgres=# select pid,wait_event,count(*) from pg_pid_wait where pid=25617 group by 1,2 order by 3 desc; pid | wait_event | count -------+--------------+------- 25617 | ClientWrite | 286 25617 | | 75 25617 | DataFileRead | 3 (3 rows) |
The sessions are spending more time on “ClientWrite” As per PostgreSQL documentation.
ClientWrite | Waiting to write data to the client. |
It is the time spend on writing the data to the client. The wait_event NULL indicates the CPU utilization.
Impact of Cursors
Typically, after a query execution, the result data need to be processed by the application. Cursors are used for holding the result of queries and processing them. The impact on query performance is mainly decided by where the cursor is residing, whether on PostgreSQL server-side or at the client-side. The location of the cursor is expected to affect when the query is issued from a separate application host, so I am testing only that case.
Client-Side Cursors
Generally, this is the case with most of the PostgreSQL clients and applications. The data is retrieved fully to the database client end and then processed one by one.
Here is a simple python snippet (to mimic the application connection) for testing the same. (Only the relevant lines are copied.)
1 2 3 4 5 6 7 8 9 10 11 | conn = psycopg2.connect(connectionString) cur = conn.cursor() cur.itersize = 2000 cur.execute("select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid") row = cur.fetchone() while row is not None: print(row) time.sleep(0.001) row = cur.fetchone() conn.close() |
As we can see itersize is specified so only those many records are to be fetched at a time for processing and there is a 1-millisecond delay in a loop using fetchone() in each loop
But none of these affects the server-side query performance because the cursor is already cached on the client-side. The query time and duration reported are similar to executing from a remote application host for a large number of rows. As expected, the impact of the network is clearly visible:
1 2 3 4 5 6 7 8 9 10 | 2021-08-03 17:39:17.119 UTC [29180] LOG: duration: 5447.793 ms plan: Query Text: select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid Nested Loop (cost=12322.13..63020.46 rows=833333 width=12) (actual time=130.919..1240.727 rows=1000000 loops=1) Output: a.bid, b.cnt Join Filter: (b.bid > a.bid) Rows Removed by Join Filter: 1500000 Buffers: shared hit=1647 read=14761 -> Seq Scan on public.pgbench_accounts a (cost=0.00..13197.00 rows=500000 width=4) (actual time=0.086..183.503 rows=500000 loops=1) Output: a.aid, a.bid, a.abalance, a.filler Buffers: shared hit=864 read=7333 |
Server-Side Cursors
The way the cursor is created and used will be totally changing if we have a named cursor that stays on the server-side, and the statement cur = conn.cursor() is modified to include a name like cur = conn.cursor('curname').
As the psycopg2: (The Python connector for PostgreSQL) documentation says:
“Psycopg wraps the database server-side cursor in named cursors. A named cursor is created using the cursor() method specifying the name parameter”
Surprisingly, the PostgreSQL log does not give any more information about the query even though auto_explain is configured. No duration information either. There is only a single line of info:
1 | 2021-08-03 18:02:45.184 UTC [29249] LOG: duration: 224.501 ms statement: FETCH FORWARD 1 FROM "curname" |
PostgreSQL cursor supports various FETCH options with custom size specifications. Please refer to the documentation for FETCH for more details. It is up to the language driver/connector to wrap this functionality into corresponding functions.
The python driver for PostgreSQL – psychopg2 – wraps the functionality to run FETCH rows with the custom batch size specified as follows:
1 | cur.fetchmany(size=20000) |
Which produces a PostgreSQL log entry like:
1 | 2021-08-05 05:13:30.728 UTC [32374] LOG: duration: 262.931 ms statement: FETCH FORWARD 20000 FROM "curname" |
As we expected, the fetch size is increased.
But the important point to note here is: even though the application iterating over a server-side cursor took a hell of a lot of time (running into several minutes), there is almost zero information about the query or the session in the PostgreSQL logs.
Ahh! This could the weirdest thing someone would expect.
Wait Event Analysis
Again wait event analysis comes in handy to understand what’s happening. Out of 2000 wait event samples collected by the pg_gather script, the wait events looks like this:
1 2 3 4 5 | pid | wait_event | count -------+--------------+------- 30115 | ClientRead | 1754 30115 | (CPU) | 245 30115 | DataFileRead | 1 |
The time is pend on the “ClientRead” weight event. This means that the server-side is waiting for the client to send the next request. So a slow network between the application server and the database server can adversely affect the server-side cursors. But no information will be available in the PostgreSQL logs about the statement.
Conclusion
In this blog post, I tried to assess the impact of transferring a large amount of data from a Database Host to an Application Host.
PLEASE NOTE: The numbers discussed in the blog post in terms of the number of rows and the time recorded don’t have any absolute relevance and it might change from system to system with many environmental factors.
The discussion is more on the areas of impact and what we should expect and how to analyze as an end-user rather than any absolute numbers.
- Always try to specify the minimum number of columns in the query. Avoid “SELECT *” or columns that are not used on the application side to avoid unnecessary data transfer.
- Avoid fetching a large number of rows to the application at a time. If required, use proper paging with LIMIT and OFFSET.
- Avoid server-side cursors wherever possible. PostgreSQL reports only the duration of the first fetch and the actual query performance may go unnoticed. Bad performing queries could be hiding behind.
- Client-side cursors and data processing time won’t affect the query performance at the PostgreSQL server-side.
- Wait event analysis is very handy in understanding where the server is spending time.
Percona Distribution for PostgreSQL provides the best and most critical enterprise components from the open-source community, in a single distribution, designed and tested to work together.
Download Percona Distribution for PostgreSQL Today!
