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: 'Tom Lane' <tgl@sss.pgh.pa.us>, Robert Haas <robertmhaas@gmail.com>, "Jacob Champion" <pchampion@pivotal.io>, Jim Doty <jdoty@pivotal.io>, "'raam.soft@gmail.com'" <raam.soft@gmail.com>
Cc: "Jamison, Kirk" <k.jamison@jp.fujitsu.com>, "Nagaura, Ryohei" <nagaura.ryohei@jp.fujitsu.com>, PostgreSQL mailing lists <pgsql-hackers@postgresql.org>, "nagata@sraoss.co.jp" <nagata@sraoss.co.jp>, Haribabu Kommi <kommi.haribabu@gmail.com>, Peter Eisentraut <peter.eisentraut@2ndquadrant.com>, 'Kyotaro HORIGUCHI' <horiguchi.kyotaro@lab.ntt.co.jp>
Date: 2019-04-05T02:42:35Z
Lists: pgsql-hackers

Attachments

Hi, 

> The basic idea being:
> 
> - Each line is a whole message.
> - The line begins with <<< for a message received and >>> for a message sent.
> - Strings in single quotes are those sent/received as a fixed number of bytes.
> - Strings in double quotes are those sent/received as a string.
> - 4-byte integers are printed unadorned.
> - 2-byte integers are prefixed by #.
> - I guess 1-byte integers would need some other prefix, maybe @ or ##.

I created v1 patch to improve PQtrace(); output log message in one line. 
Please find my attached patch.


Log output examples;

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)" 

In current PQtrace log:

From backend> T
>From backend (#4)> 35
>From backend (#2)> 1
>From backend> "set_config"
>From backend (#4)> 0
>From backend (#2)> 0
>From backend (#4)> 25
>From backend (#2)> 65535
>From backend (#4)> -1
>From backend (#2)> 0

I changed like this:

2019-04-04 02:39:51.489 UTC  < RowDescription 35 #1 "set_config" 0 #0 25 #65535 -1 #0


> I would like to add timestamp per line and when command processing function
> start/end.
> I think it is useful to know the application process start/end for diagnosis.
> So I will implement like this;
> 
> 2019-03-03 07:24:54.142 UTC   PQgetResult start
> 2019-03-03 07:24:54.143 UTC   < 'T' 35 1 "set_config" 0 #0 25 #65535 -1 #0
> 2019-03-03 07:24:54.144 UTC   PQgetResult end
I would like to add this in next patch if there are not any disagreement.

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.