Обсуждение: WAL_DEBUG logs spurious data

Hi,

I stumbled across a minor issue in xlog.c:1030: the WAL_DEBUG code block
there passes rdata->data to the rm_desc() methode. However, that's only
the first XLogRecData struct, not the entire XLog record. So the
rm_desc() method effectively reports spurious data for any subsequent part.

Take a commit record with subxacts as an example: during XLogInsert,
Postgres reports the following:

LOG:  INSERT @ 0/16F3270: prev 0/16F3234; xid 688; len 16: Transaction -
commit: 2012-10-11 09:31:17.790368-07; subxacts: 3214563816

Note that the xid in subxacts is way off. During recovery from WAL, the
record is logged correctly:

LOG:  REDO @ 0/16F3270; LSN 0/16F329C: prev 0/16F3234; xid 688; len 16:
Transaction - commit: 2012-10-11 09:31:17.790368-07; subxacts: 689

Attached is a possible fix.

Regards

Markus Wanner

Markus Wanner <markus@bluegap.ch> writes:
> I stumbled across a minor issue in xlog.c:1030: the WAL_DEBUG code block
> there passes rdata->data to the rm_desc() methode. However, that's only
> the first XLogRecData struct, not the entire XLog record. So the
> rm_desc() method effectively reports spurious data for any subsequent part.

The original design intention was that rm_desc should not attempt to
print any such data, but obviously some folks didn't get the word.
The question is whether we're willing to add a lot of cycles to
XLOG_DEBUG mode in order to make the full record available for printing
purposes.  Not sure if it's a good tradeoff or not.
        regards, tom lane

Tom,

On 10/11/2012 03:11 PM, Tom Lane wrote:
> The original design intention was that rm_desc should not attempt to
> print any such data, but obviously some folks didn't get the word.

FWIW: in case the source code contains comments explaining that
intention, I certainly missed them so far.

Regards

Markus

Markus Wanner <markus@bluegap.ch> writes:
> On 10/11/2012 03:11 PM, Tom Lane wrote:
>> The original design intention was that rm_desc should not attempt to
>> print any such data, but obviously some folks didn't get the word.

> FWIW: in case the source code contains comments explaining that
> intention, I certainly missed them so far.

Yeah, if we decide to stick with the limitation, some documentation
would be called for.  I remember having run into this and having removed
functionality from an rm_desc function rather than question the premise.
But maybe the extra functionality is worth the cycles.
        regards, tom lane

On 10/11/2012 04:06 PM, Tom Lane wrote:
> Yeah, if we decide to stick with the limitation, some documentation
> would be called for.  I remember having run into this and having removed
> functionality from an rm_desc function rather than question the premise.
> But maybe the extra functionality is worth the cycles.

Well, I've been interested in getting it correct, and didn't care about
performance.

But I can certainly imagine someone enabling it on a production system
to get more debug info. In which case performance would matter more.
However, WAL_DEBUG being a #define, I bet only very few admins do that.
So I tend towards sacrificing performance for better debug info in the
WAL_DEBUG case. (Especially given that you can still disable it via GUC).

Regards

Markus

On Thu, Oct 11, 2012 at 07:06:15PM -0400, Tom Lane wrote:
> Markus Wanner <markus@bluegap.ch> writes:
> > On 10/11/2012 03:11 PM, Tom Lane wrote:
> >> The original design intention was that rm_desc should not attempt to
> >> print any such data, but obviously some folks didn't get the word.
> 
> > FWIW: in case the source code contains comments explaining that
> > intention, I certainly missed them so far.
> 
> Yeah, if we decide to stick with the limitation, some documentation
> would be called for.  I remember having run into this and having removed
> functionality from an rm_desc function rather than question the premise.
> But maybe the extra functionality is worth the cycles.

I assume there is no TODO item or patch here.

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + It's impossible for everything to be true. +