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>
Cc: "Jamison, Kirk" <k.jamison@jp.fujitsu.com>, "Nagaura, Ryohei" <nagaura.ryohei@jp.fujitsu.com>, Jacob Champion <pchampion@pivotal.io>, "Jim Doty" <jdoty@pivotal.io>, 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-03-05T09:48:03Z
Lists: pgsql-hackers 
Hi everyone,

I appreciate all the helpful advice.

I agree to display message more clearly. I will follow your advice.
	
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


> > But I still don't really see a need for different levels or whatever.
> > I mean, you either want a dump of all of the protocol traffic, or you
> > don't, I think.  Or maybe I am confused as to what the goal of all
> > this really is.
> 
> Yeah, me too.  But a lot of this detail would only be useful if you were trying
> to diagnose something like a discrepancy between the server and libpq as to
> the width of some field.  And the number of users for that can be counted
> without running out of fingers.  I think what would be of use for a trace
> facility is as high-level a view as possible of the message contents.
> 
> Or, in other words: a large part of the problem with the existing PQtrace
> facility is that it *was* designed to help debug libpq itself, and that
> use-case is no longer very interesting.  We should assume that the library
> knows how to parse protocol messages.

Since I explained the reason in the previous email, I am copy-pasting it again here.

I think the purpose of the leveling is to provide an optional information for the user, 
which is useful for diagnosis during the performance deterioration.
When query delay happens, we want to know from which side(server or client) is the cause of it,
and then people want to know which process takes time.
I think the phase and time information are useful for diagnosis.
For example, when command processing function (ex. PQexec()) etc. start/end
and when client receive/send protocol messages.

So is it alright to add these information to the new/proposed PQtrace() default output?



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.