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
Attachments:
wal_debug_fix.difftext/x-diff; charset=iso-8859-1; name=wal_debug_fix.diffDownload
*** a/src/backend/access/transam/xlog.c
--- b/src/backend/access/transam/xlog.c
***************
*** 1033,1039 **** begin:;
#ifdef WAL_DEBUG
if (XLOG_DEBUG)
{
! StringInfoData buf;
initStringInfo(&buf);
appendStringInfo(&buf, "INSERT @ %X/%X: ",
--- 1033,1056 ----
#ifdef WAL_DEBUG
if (XLOG_DEBUG)
{
! StringInfoData buf;
! char *full_rec = palloc(write_len), *ins_ptr;
!
! /*
! * We need assemble the entire record once, to be able to dump it out
! * properly.
! */
! rdt = rdata;
! ins_ptr = full_rec;
! while (rdt)
! {
! if (rdt->data != NULL)
! {
! memcpy(ins_ptr, rdt->data, rdt->len);
! ins_ptr += rdt->len;
! }
! rdt = rdt->next;
! }
initStringInfo(&buf);
appendStringInfo(&buf, "INSERT @ %X/%X: ",
***************
*** 1042,1051 **** begin:;
if (rdata->data != NULL)
{
appendStringInfo(&buf, " - ");
! RmgrTable[rechdr->xl_rmid].rm_desc(&buf, rechdr->xl_info, rdata->data);
}
elog(LOG, "%s", buf.data);
pfree(buf.data);
}
#endif
--- 1059,1069 ----
if (rdata->data != NULL)
{
appendStringInfo(&buf, " - ");
! RmgrTable[rechdr->xl_rmid].rm_desc(&buf, rechdr->xl_info, full_rec);
}
elog(LOG, "%s", buf.data);
pfree(buf.data);
+ pfree(full_rec);
}
#endif
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. +
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers