RE: libpq debug log

From: "Iwata, Aya" <iwata(dot)aya(at)jp(dot)fujitsu(dot)com>
To: "pgsql-hackers(at)postgresql(dot)org" <pgsql-hackers(at)postgresql(dot)org>
Cc: "tgl(at)sss(dot)pgh(dot)pa(dot)us" <tgl(at)sss(dot)pgh(dot)pa(dot)us>, "robertmhaas(at)gmail(dot)com" <robertmhaas(at)gmail(dot)com>, "pchampion(at)pivotal(dot)io" <pchampion(at)pivotal(dot)io>, "jdoty(at)pivotal(dot)io" <jdoty(at)pivotal(dot)io>, "raam(dot)soft(at)gmail(dot)com" <raam(dot)soft(at)gmail(dot)com>, "Nagaura, Ryohei" <nagaura(dot)ryohei(at)fujitsu(dot)com>, "nagata(at)sraoss(dot)co(dot)jp" <nagata(at)sraoss(dot)co(dot)jp>, "kommi(dot)haribabu(at)gmail(dot)com" <kommi(dot)haribabu(at)gmail(dot)com>, "peter(dot)eisentraut(at)2ndquadrant(dot)com" <peter(dot)eisentraut(at)2ndquadrant(dot)com>, 'Kyotaro HORIGUCHI' <horiguchi(dot)kyotaro(at)lab(dot)ntt(dot)co(dot)jp>, "Jamison, Kirk" <k(dot)jamison(at)jp(dot)fujitsu(dot)com>
Subject: RE: libpq debug log
Date: 2019-07-17 08:12:50
Message-ID: 71E660EB361DF14299875B198D4CE5423DFBBFCB@g01jpexmbkw25
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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 character representing 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 and re-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 Content-Type Size
v6-libpq-PQtrace-output-one-line.patch application/octet-stream 20.9 KB

In response to

Browse pgsql-hackers by date

  From Date Subject
Next Message Michael Paquier 2019-07-17 08:29:58 Re: refactoring - share str2*int64 functions
Previous Message Michael Paquier 2019-07-17 08:04:24 Re: pg_receivewal documentation