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: 'Yugo Nagata' <nagata@sraoss.co.jp>
Cc: "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>
Date: 2018-09-04T00:29:09Z
Lists: pgsql-hackers 
> > I'm going to propose libpq debug log for analysis of queries on the application
> side.
> > I think that it is useful to determine whether the cause is on the application
> side or the server side when a slow query occurs.
> 
> Do you mean you want to monitor the protocol message exchange at the client
> side to analyze performance issues, right?  Actually, this might be useful to
> determin where is the problem, for example, the client application, the backend
> PostgreSQL, or somewhere in the network.
> 
> Such logging can be implemented in the application, but if libpq provides the
> standard way, it would be helpful to resolve a problem without modifying the
> application code.

Since I'd like to monitor the information the server and the client exchange,
I think monitoring protocol messages is good.

When a slow query is occurs, we check this client side trace log.
The purpose of this log acquisition I thought is to identify where is the problem: 
server side, application side or traffic. 
And if the problem is in application side, checking the trace log to identify what is the problem.

> > The provided information is "date and time" at which execution of processing
> is started, "query", "application side processing", which is picked up
> information from PQtrace(), and "connection id", which is for uniquely
> identifying the connection.
> 
> I couldn't image how this is like. Could you show us a sample of log lines in
> your head?

I am roughly thinking as follows;

...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
STATUS : Connection
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
QUERY : DECLARE myportal CURSOR FOR select * from pg_database
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...

> > To collect the log, set the connection string or environment variable.
> > - logdir or PGLOGDIR : directory where log file written
> > - logsize or PGLOGSIZE : maximum log size
> 
> How we can specify the log file name?  What should happen if a file size exceeds
> to PGLOGSIZE?

The log file name is determined as follow.
libpq-%ApplicationName-%Y-%m-%d_%H%M%S.log

When the log file size exceeds to PGLOGSIZE, the log is output to another file.

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.