Re: libpq debug log

Tom Lane <tgl@sss.pgh.pa.us>

From: Tom Lane <tgl@sss.pgh.pa.us>
To: "tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com>
Cc: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>, "k.jamison@fujitsu.com" <k.jamison@fujitsu.com>, "'Kyotaro Horiguchi'" <horikyota.ntt@gmail.com>, "alvherre@alvh.no-ip.org" <alvherre@alvh.no-ip.org>, "pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>
Date: 2021-03-04T23:03:43Z
Lists: pgsql-hackers
"tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com> writes:
> From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
>> Using (inCursor - inStart) as logCursor doesn't work correctly if tracing state
>> desyncs.  Once desync happens inStart can be moved at the timing that the
>> tracing code doesn't expect. This requires (as I mentioned upthread)
>> pqReadData to actively reset logCursor, though.
>> 
>> logCursor should move when bytes are fed to the tracing functoins even when
>> theyare the last bytes of a message.

> Hmm, sharp and nice insight.  I'd like Iwata-san and Kirk to consider this, including Horiguchi-san's previous mails.

I took a quick look through the v22 patch, and TBH I don't like much of
anything at all about the proposed architecture.  It's retained most
of the flavor of the way it was done before, which was a hangover from
the old process-on-the-fly scheme.

I think the right way to do this, now that we've killed off v2 protocol
support, is to rely on the fact that libpq fully buffers both incoming
and outgoing messages.  We should nuke every last bit of the existing
code that intersperses tracing logic with normal message decoding and
construction, and instead have two tracing entry points:

(1) Log a received message.  This is called as soon as we know (from
the length word) that we have the whole message available, and it's
just passed a pointer into the input buffer.  It should examine the
input message for itself and print the details.

(2) Log a message-to-be-sent.  Again, call it as soon as we've constructed
a complete message in the output buffer, and let it examine and print
that message for itself.

Both of these pieces of logic could be written directly from the protocol
specification, without any interaction with the main libpq code paths,
which would be a Good Thing IMO.  The current intertwined approach is
somewhere between useless and counterproductive if you're in need of
tracing down a libpq bug.  (In other words, I'm suggesting that the
apparent need for duplicate logic would be good not bad, and indeed that
it'd be best to write the tracing logic without consulting the existing
libpq code at all.)

This would, I think, also eliminate the need for extra storage to hold
info about bits of the message, which IMO is a pretty significant
downside of the proposed design.  The printing logic would just print
directly to Pfdebug; it wouldn't have to accumulate anything, and so
it wouldn't have the out-of-memory failure modes that this patch has.
You could also get rid of messy stuff like pqTraceForciblyCloseBeMsg.

Lastly, this'd reduce the overhead the tracing functionality imposes
on normal usage to about nil.  Admittedly, all those "if (Pfdebug)"
tests probably don't cost that much execution-wise, but they cost
something.  Making only one such test per sent or received message
has to be better.

			regards, tom lane



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.