The usability of the libpq feature to trace application's server/client communications has been enhanced in PostgreSQL 14, with an improved format and an option to control output.

img-featured-blog-improved-logging-by-libpg-in-postgresql-14

photo-aya-iwata-in-red-circleBackground

libpq is one of the client libraries in which users can run the PQtrace function to log client-server communication. This communication is a protocol message used by PostgreSQL, containing:

  • The message identifier for the message type
  • The length of the message, and
  • Message content for the exchanged information

Application developers can use this log to determine whether communication is occurring as intended or not.

Using the statement below as an example:

CREATE TABLESPACE regress_tblspacewith
LOCATION '/home/postgres/src/test/regress/testtablespace'
WITH (random_page_cost = 3.0);

Up to PostgreSQL 13, an application calling PQtrace would output a log like the following to the specified file:

From backend> Z 1
From backend (#4)> 5
From backend> I
To backend> Msg Q
To backend> "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/postgres/…
To backend> Msg complete, length 133
From backend> C 1
From backend (#4)> 22
From backend> "CREATE TABLESPACE"
From backend> Z
From backend (#4)> 5
From backend> I
Log generated by libpq in PostgreSQL 13

Note that the log output of PQtrace in the current PostgreSQL version does not include timestamps, so it cannot be referenced to investigate slow processing.

In addition, because the message identifier, server/client message length, and content are each output in separate lines, readability was poor and protocol messages analysis is very difficult. Z and C marked with 1 in the log above are identifiers for protocol messages. To understand the meaning of each identifier, you need to refer to PostgreSQL Documentation's section Message Formats icon-external-link-02-variation-01.

Functional improvement overview

In PostgreSQL 14, the PQtrace function is improved to make the log more readable and to output timestamps. Also, a new function PQsetTraceFlags has been added to control the output of timestamps.

Improved log output

The improved trace functions in PostgreSQL 14 produce outputs similar to the following:

            1              2            3
2021-06-30 09:21:56.366698  B   5   ReadyForQuery    I
2021-06-30 09:21:56.366741  F   133 Query    "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/postgres/…
2021-06-30 09:21:56.367679  B   22  CommandComplete  "CREATE TABLESPACE"
2021-06-30 09:21:56.367696  B   5   ReadyForQuery    I 4
Log generated by libpq in PostgreSQL 14

This is the log for the exact same operation as the example log output of PostgreSQL 13 shown above. There are four improvements:

1 Timestamps are now included.
2 The message direction code is intuitive: F for frontend, and B for backend.
3 The formal message name is output instead of the identifier of the protocol message.
4 Meaningful protocol messages are output in one line.

Log retrieval methods

As before, you start logging by calling libpq's PQtrace function - this remains the same as in previous versions. If you don't need the timestamp output, you can control it with the newly introduced PQsetTraceFlags icon-external-link-02-variation-01 function, which was added as a part of this improvement.

Effect

_img-woman-using-computer-04

The fact that PQtrace now outputs timestamps allows users to identify time-consuming operations. For example, if an application suddenly slows down, you 

can determine whether the server or client is taking longer to process by looking at the timestamp differences in the log.

Meaningful protocol messages are output in a single line, making it easy for those unfamiliar with the libpq logs to understand what communication is taking place between the server and the client.

By controlling whether or not timestamps are output using the PQsetTraceFlags function, you can use this log for regression tests. By not outputting timestamps, you can pre-populate the log with the results of the expected test run and compare it easily with the log obtained from the test run.

For the future

img-abstract-0s-and-1s-02The libpq log in PostgreSQL 14 will include timestamps and more readable text.

In the following versions, we will examine these areas to further enhance usability:

  • The current function writes the log to the file specified to the PQtrace function. This can result in very large log files and slow file operations in some cases. To resolve this problem, we want to provide a functionality to specify the maximum file size.
  • We want to add environment variables and connection parameters which set log destination directories and log file names to suit each environment without requiring changes to the application.
Subscribe to be notified of future blog posts
If you would like to be notified of my next blog posts and other PostgreSQL-related articles, fill the form here.
We also have a series of technical articles for PostgreSQL enthusiasts of all stripes, with tips and how-to's.

 

Explore PostgreSQL Insider

Topics: PostgreSQL, PostgreSQL Community, Data Governance

Receive our blog

Receive notification of PostgreSQL-based articles for business and technical audiences.

SEARCH BY TOPIC

see all

Read our latest blogs

Read our most recent articles regarding all aspects of PostgreSQL and FUJITSU Enterprise Postgres.