Horton

RE: libpq debug log

Iwata, Aya <iwata.aya@jp.fujitsu.com>

View thread View on postgr.es
From: "Iwata, Aya" <iwata.aya@jp.fujitsu.com>
To: "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Cc: "tgl@sss.pgh.pa.us" <tgl@sss.pgh.pa.us>, "robertmhaas@gmail.com" <robertmhaas@gmail.com>, "pchampion@pivotal.io" <pchampion@pivotal.io>, "jdoty@pivotal.io" <jdoty@pivotal.io>, "raam.soft@gmail.com" <raam.soft@gmail.com>, "Nagaura, Ryohei" <nagaura.ryohei@fujitsu.com>, "nagata@sraoss.co.jp" <nagata@sraoss.co.jp>, "kommi.haribabu@gmail.com" <kommi.haribabu@gmail.com>, "peter.eisentraut@2ndquadrant.com" <peter.eisentraut@2ndquadrant.com>, 'Kyotaro HORIGUCHI' <horiguchi.kyotaro@lab.ntt.co.jp>, "Jamison, Kirk" <k.jamison@jp.fujitsu.com>
Date: 2019-07-17T08:12:50Z
Lists: pgsql-hackers

Attachments

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

Commits

  1. Rename PQtraceSetFlags() to PQsetTraceFlags().

  2. Suppress length of Notice/Error msgs in PQtrace regress mode

  3. Strip file names reported in error messages on Windows, too.

  4. Fix setvbuf()-induced crash in libpq_pipeline

  5. libpq_pipeline: Must strdup(optarg) to avoid crash

  6. Remove setvbuf() call from PQtrace()

  7. Initialize conn->Pfdebug to NULL when creating a connection

  8. Disable force_parallel_mode in libpq_pipeline

  9. libpq_pipeline: add PQtrace() support and tests

  10. Improve PQtrace() output format

  11. Re-simplify management of inStart in pqParseInput3's subroutines.