RE: libpq debug log - Mailing list pgsql-hackers

From Iwata, Aya
Subject RE: libpq debug log
Date
Msg-id 71E660EB361DF14299875B198D4CE5423DFBBFCB@g01jpexmbkw25
Whole thread Raw
In response to RE: libpq debug log  ("Iwata, Aya" <iwata.aya@jp.fujitsu.com>)
Responses Re: libpq debug log  (Alvaro Herrera from 2ndQuadrant <alvherre@alvh.no-ip.org>)
List pgsql-hackers
Hi, 

This is a summary of the whole thread.
I am currently improving PQtrace() by adjusting its output to one line per protocol message as per the advice of
reviewers.

Purpose:
If a problem occurs, such as a slow query, you want to know which query takes time.
In Current libpq, there is PQtrace(FILE *filename) facility to output exchanging protocol messages to file.
But I think current PQtrace() has following issues: 
* The output is confusing. It is difficult to analyze information because it is printed one by one, and only a
characterrepresenting a message (ex. printed 'T' means RowDescription).
 
* Timestamp is not output. So we cannot identify which process took a long time. That would be possible when we compare
timestamps.
* PQtrace() code must be included in libpq application's source code. If you want to get log, you should change code
andre-compile it for logging. Some application cannot do this.
 

Compared to tcpdump:
There is tcpdump for similar use, but it has the following problems:
- Windows users cannot use it.
- If the communication is encrypted, it is possible that you may not see the information you want as explained by
Andres.
- Information can only be retrieved by limited users due to OS permissions.

Solution:
Work on following improvements in order:
1. Adjusting it to emit one line per protocol message and output timestamp.
2. Enables logging control without recompiling the application. 
   I thought it would be better to control it with parameters. However since this method is controversial (Security
implications,etc.), we will consider a good method after completing 1.   
 

Latest patch just contains 1. Hence, the usage of this feature is the same as current PQtrace().

Example of log output:
In current PQtrace log:

To backend> Msg Q
                   
 
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60

I changed like this:

2019-04-04 02:39:51.488 UTC  > Query 59 "SELECT pg_catalog.set_config('search_path', '', false)"

I appreciate your advice regarding the one line protocol message. Thank you in advance.

Regards,
Aya Iwata

Attachment

pgsql-hackers by date:

Previous
From: Michael Paquier
Date:
Subject: Re: pg_receivewal documentation
Next
From: Michael Paquier
Date:
Subject: Re: refactoring - share str2*int64 functions