RE: libpq debug log - Mailing list pgsql-hackers

Let me explain this trace log in a bit more detail.

This log is not turned on in the system by default. 
Turn it on when an issue occurs and you want to check the information in the application in order to clarify the
cause.

I will present three use cases for this log.

1. Confirmation on cause of out-of-memory
We assume that Out-of-memory occurred in the process of storing the data received from the database.
However, the contents or length of the data is not known.
A trace log is obtained to find these out and what kind of data you have in which part (i.e. query result when
receivingfrom database).
 

2. Protocol error confirmation
When there is an error in the protocol transmitted from the client and an error occurs in the database server, the
protocolsent by the client is checked.
 
When the network is unstable, log is checked whether the database server is receiving protocol messages. 

3. Processing delay survey
If the processing in the application is slow and the processing in the database is fast, investigate the cause of the
processingdelay.
 
4 kind of time can be obtained by the log;

 Timestamp when SQL started
 Timestamp when information began to be sent to the backend
 Timestamp when information is successfully received in the application
 Timestamp when SQL ended

Then the difference between the time is checked to find out which part of process takes time.


I reconfirm the function I proposed.

If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size. When the log file size exceeds to PGLOGSIZE, the log is output to another
file.

The log file name is determined as follow.
libpq-%ConnectionID-%Y-%m-%d_%H%M%S.log

This is a trace log example;

...
Start: 2018-09-03 18:16:35.357 Connection(1)
Status: Connection
Send message: 2018-09-03 18:16:35.358
<information send to backend...>
Receive message: 2018-09-03 18:16:35.359
<information receive from backend...>
End: 2018-09-03 18:16:35.360
...
Start: 2018-09-03 18:16:35.357 Connection(1)            ...(1), (2)
Query: DECLARE myportal CURSOR FOR select * from pg_database    ...(3)
Send message: 2018-09-03 18:16:35.358                ...(4)
<information send to backend...>                    ...(5)
Receive message: 2018/09/03 18:16:35.359                ...(6)
<information receive from backend...>                ...(7)
End: 2018-09-03 18:16:35.360                    ...(8)
...


(1) Timestamp when SQL started
(2) Connection ID (Identify the connection)
(3) SQL statement
(4) Timestamp when information began to be sent to the backend
(5) send message to backend (Result of query, Protocol messages)
(6) Timestamp when information is successfully received in the application
(7) receive message from backend (Result of query, Protocol messages)
(8) Timestamp when SQL ended


Regards,
Iwata Aya