< Back to blog home Fujitsu PostgreSQL blog

Improved logging by libpq in PostgreSQL 14

Aya Iwata | July 15, 2021

Background

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:

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

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 .

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:

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 function, which was added as a part of this improvement.

Effect

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

The 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.

We also have a series of technical articles for PostgreSQL enthusiasts of all stripes, with tips and how-to's.