Client-Side vs Server-Side Latencies Demystified in PostgreSQL and YugabyteDB

Every execution of SQL in PostgreSQL and therefore in YugabyteDB YSQL takes some time to process. One of the most common ways to identify how much is time spent on processing is to use the pg_stat_statements view in the database. However, the time visible in pg_stat_statements might differ from the time a database client registers for the execution. Where does this difference come from? Let’s take a look.

An Example of Client-side vs Server-side Latency

In the example below, we show that the client-side latency is 24.6 ms versus the server-side latency of just 5.2ms.

Client-side latency via the connection profiler utility:

% ./target/release/connection-profiler -u "host=192.168.66.80 user=yugabyte password=yugabyte port=5433" -q 'select * from t'
create_connection                             15552 us
------------------------------------------------------------
run nr: 1
total simple query                            24586 us
============================================================

Server-side latency as seen in pg_stat_statements:

yugabyte=# select query, calls, total_time, min_time, max_time, mean_time, stddev_time from pg_stat_statements where query = 'select * from t';
      query      | calls | total_time | min_time | max_time | mean_time | stddev_time
-----------------+-------+------------+----------+----------+-----------+-------------
 select * from t |     1 |   2.168497 | 2.168497 | 2.168497 |  2.168497 |           0

This shows the processing of the query by the client took 15.6 ms to connect to the server, which is a one time cost. In addition, the latency of the query itself is 24.6ms, and the query time in pg_stat_statements is 2.2 ms. Why does this difference exist? Read on to find out.

Understanding the Simple vs Extended Query Protocol

When PostgreSQL processes a SQL statement, it performs the following steps:

• Parse and Rewrite
• Plan
• Execute

Each of these steps are required to perform the processing of a SQL statement.

To allow more granular SQL processing access for a database client, the extended query protocol can be used. The extended query protocol requires that the client performs the steps of Parse and Rewrite, Plan, and Execute individually. By using the extended query protocol, a database client can parse a prepared statement once, and then use the plan step to introduce new values to the prepared statement, execute it, and then perform the plan and execute steps reusing the prepared statement.

The use of the simple query protocol or the extended query protocol is a choice made by the programmer of the database client. The PostgreSQL ‘psql’ client and the YugabyteDB ‘ysqlsh’ client implement the simple query protocol. Most java based applications implement the extended query protocol.

The connection-profiler can perform the same SQL using the extended query protocol:

% ./target/release/connection-profiler -u "host=192.168.66.80 user=yugabyte password=yugabyte port=5433" -q 'select * from t' -p extended
create_connection                             14851 us
------------------------------------------------------------
run nr: 1
parse+describe+sync        9106 us
bind+execute+sync         15597 us
total extended protocol                       24759 us
============================================================

Server side latency as seen in pg_stat_statements:

yugabyte=# select query, calls, total_time, min_time, max_time, mean_time, stddev_time from pg_stat_statements where query = 'select * from t';
      query      | calls | total_time | min_time | max_time | mean_time | stddev_time
-----------------+-------+------------+----------+----------+-----------+-------------
 select * from t |     1 |   2.127028 | 2.127028 | 2.127028 |  2.127028 |           0

This shows the processing of the query on the client side taking 24.8 ms, which now is broken down into a parse step, a combined bind, and an execute step. There is a slight difference between the client- and server-side naming of the processing steps. The client-side Parse step includes the server side Parse and Rewrite steps; the client-side Bind step equals the server-side Plan step. The Execute steps are identically named between client and server.

The processing time is broken down into parse taking 9.1ms, bind and execute taking 15.6 ms, and the query time in pg_stat_statements taking 2.1ms. This still shows a difference between the time in pg_stat_statements and the times seen on the client side.

The reason for the difference between server-side time in pg_stat_statements and the client-side time is that the time in pg_stat_statements only measures the Execution step latency and not the steps of Parse, Rewrite, and Plan. In the extended protocol execution timing, above, the requests for Bind and Execution were combined. Therefore, the timing accounts for both these steps. This is why it didn’t match pg_stat_statements timing.

Server-side latency timing

PostgreSQL and YugabyteDB can be configured to log statement execution timing using the parameter log_min_duration_statement or the gflag –ysql_log_min_duration_statement. To log all statements, set it to ‘0’. The log output is in the postgres log file.

Setting this parameter comes with a caveat: it operates at the request level in the server. That sounds a bit cryptic, but what it means is that a SQL execution performed as simple query will be timed as a simple query execution, not showing the processing steps:

2022-10-07 08:36:45.661 UTC [7757] LOG:  duration: 23.138 ms  statement: select * from t;

And if a query is executed using the extended query protocol, the individual steps of parse, bind and execute will be timed:

2022-10-07 08:37:08.807 UTC [7771] LOG:  duration: 8.708 ms  parse s0: select * from t
2022-10-07 08:37:08.821 UTC [7771] LOG:  duration: 12.995 ms  bind s0: select * from t
2022-10-07 08:37:08.824 UTC [7771] LOG:  duration: 2.154 ms  execute s0: select * from t

The timing of the breakdown of the Parse, Bind and Execute steps show that the execute latency is very close to the time in pg_stat_statements. The reason the timing is not exact is that the log_min_duration_statement timing operates at a different layer in the PostgreSQL code than pg_stat_statements. log_min_duration_timing operates in the layer that deals with client requests, and the pg_stat_statements timing operates inside the executor code, which is in a much lower layer. The time in the logging; therefore, is slightly higher.

Conclusion

The pg_stat_statements view shows the timing of statement processing of the execution step, and excludes the parsing and planning steps. The excluded steps of statement processing can take some time too. This means that the time visible in pg_stat_statements is useful to understand statement processing latency, but is likely to be less than client-side-measured latency.

An application using the PostgreSQL wire protocol, such as PostgreSQL and YugabyteDB, can use the simple query protocol or the extended query protocol. Understanding the application or client side timing requires an understanding of what exactly is timed. This is obvious with the simple query protocol, but might be less easy to understand if the extended query protocol is used, especially if prepared statements are used. Normally, a client sends the Bind/Plan and Execute messages in one go, meaning that client-side observed latency includes more steps than the Execute step measured by the pg_stat_statements.

Using the server side pg_min_duration_statement parameter, the timing of the processing steps can be measured if the extended query protocol is used by the database client, which provides a full picture of the statement processing latency (excluding network latency). One downside is that this information is only available in the postgres log file.