digoal
2021-07-19
PostgreSQL , PQTrace
https://www.postgresql.fastware.com/blog/improved-logging-by-libpq-in-postgresql-14
https://www.postgresql.org/docs/14/libpq-control.html
https://www.postgresql.org/docs/14/protocol-message-formats.html
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.
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.
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.
The improved trace functions in PostgreSQL 14 produce outputs similar to the following:
1 2 3 4
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
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.
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.
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.
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.
您的愿望将传达给PG kernel hacker、数据库厂商等, 帮助提高数据库产品质量和功能, 说不定下一个PG版本就有您提出的功能点. 针对非常好的提议，奖励限量版PG文化衫、纪念品、贴纸、PG热门书籍等，奖品丰富，快来许愿。开不开森.
