Horton

Re: libpq debug log

Alvaro Herrera <alvherre@2ndquadrant.com>

View thread View on postgr.es
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>
Cc: "pgsql-hackers@postgresql.org" <pgsql-hackers@postgresql.org>, "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@fujitsu.com" <nagaura.ryohei@fujitsu.com>, "nagata@sraoss.co.jp" <nagata@sraoss.co.jp>, "peter.eisentraut@2ndquadrant.com" <peter.eisentraut@2ndquadrant.com>, 'Kyotaro HORIGUCHI' <horiguchi.kyotaro@lab.ntt.co.jp>, "k.jamison@fujitsu.com" <k.jamison@fujitsu.com>
Date: 2020-09-16T20:41:55Z
Lists: pgsql-hackers

Attachments

Hello Aya Iwata,

I like this patch, and I think we should have it.  I have updated it, as
it had conflicts.

In 0002, I remove use of ftime(), because that function is obsolete.
However, with that change we lose printing of milliseconds in the trace
lines.  I think that's not great, but I also think we can live without
them until somebody gets motivated to write the code for that.  It seems
a little messy so I'd prefer to leave that for a subsequent commit.
(Maybe we can just use pg_strftime.)

Looking at the message type tables, I decided to get rid of the "bf"
table, which had only two bytes, and instead put CopyData and CopyDone
in the other two tables.  That seems simpler.  Also, the COMMAND_x_MAX
macros were a bit pointless; I just expanded at the only caller of each,
using lengthof().  And since the message type is unsigned, there's no
need to do "c >= 0" since it must always be true.

I added setlinebuf() to the debug file.  Works better than without,
because "tail -f /tmp/libpqtrace.log" works as you'd expect.

One thing that it might be good to do is to avoid creating the message
type tables as const but instead initialize them if and only if tracing
is enabled, on the first call.  I think that would not only save space
in the constant area of the library for the 99.99% of the cases where
tracing isn't used, but also make the initialization code be more
sensible (since presumably you wouldn't have to initialize all the
zeroes.)

Opinions?  I experimented by patching psql as below (not intended for
commit) and it looks good.  Only ErrorResponse prints the terminator as
a control character, or something:

2020-09-16 13:27:29.072 -03  < ErrorResponse 117 S "ERROR" V "ERROR" C "42704" M "no existe el slot de replicación «foobar»" F "slot.c" L "408" R "ReplicationSlotAcquireInternal" ^@ 


diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
index 8232a0143b..01728ba8e8 100644
--- a/src/bin/psql/startup.c
+++ b/src/bin/psql/startup.c
@@ -301,6 +301,11 @@ main(int argc, char *argv[])
 
 	psql_setup_cancel_handler();
 
+	{
+		FILE *trace = fopen("/tmp/libpqtrace.log", "a+");
+		PQtrace(pset.db, trace);
+	}
+
 	PQsetNoticeProcessor(pset.db, NoticeProcessor, NULL);
 
 	SyncVariables();

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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.