Only first XLogRecData is visible to rm_desc with WAL_DEBUG
As we all know, when you compile with WAL_DEBUG, and enable wal_debug
GUC, you get output like this in the log for every inserted WAL record:
LOG: INSERT @ 0/5407E578: prev 0/5407E4D0; xid 0; len 32: Standby -
running xacts: nextXid 774 latestCompletedXid 771 oldestRunningXid 772;
2 xacts: 7877929 0
What I did *not* realize before is that the redo routine only gets
passed the first XLogRecData struct in the chain. Because of that, the
"xacts: 7877929 0" information above is garbage. That's probably not the
only rm_desc routine that didn't get the memo.
There are a few alternatives on how to fix that:
1. Do nothing. Add a comment somewhere explaining that rm_redo cannot
safely look at data beyond what's inserted in the first XLogRecData.
2. Reconstruct the WAL data from the XLogRecData entries in a palloc'd
buffer, and pass that to rm_redo. That would be fairly expensive, but
you probably don't care about that if you've enabled wal_debug.
3. Remove the feature altogether, so that enabling wal_debug doesn't
cause all insertions to be logged anymore (no changes to the logging
during replay). It's a lot less interesting now that we have pg_xlogdump.
Thoughts?
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Heikki Linnakangas <hlinnakangas@vmware.com> writes:
As we all know, when you compile with WAL_DEBUG, and enable wal_debug
GUC, you get output like this in the log for every inserted WAL record:
LOG: INSERT @ 0/5407E578: prev 0/5407E4D0; xid 0; len 32: Standby -
running xacts: nextXid 774 latestCompletedXid 771 oldestRunningXid 772;
2 xacts: 7877929 0
What I did *not* realize before is that the redo routine only gets
passed the first XLogRecData struct in the chain. Because of that, the
"xacts: 7877929 0" information above is garbage. That's probably not the
only rm_desc routine that didn't get the memo.
Yeah, I recall having fixed at least one such bug in the past.
There are a few alternatives on how to fix that:
1. Do nothing. Add a comment somewhere explaining that rm_redo cannot
safely look at data beyond what's inserted in the first XLogRecData.
We'll probably just make the same mistake again :-(. And I think there
already is such a comment someplace.
2. Reconstruct the WAL data from the XLogRecData entries in a palloc'd
buffer, and pass that to rm_redo. That would be fairly expensive, but
you probably don't care about that if you've enabled wal_debug.
3. Remove the feature altogether, so that enabling wal_debug doesn't
cause all insertions to be logged anymore (no changes to the logging
during replay). It's a lot less interesting now that we have pg_xlogdump.
I think the main use-case for rm_desc anymore is making CONTEXT lines
for errors reported during WAL replay. I guess that situation does not
have the same problem, since we've already loaded the complete WAL record.
However, I'm not sure how easy it's going to be for WAL_DEBUG to make the
data look the same as the replay case: in particular, substitution of
full-page-images for data would be tough to predict in advance (and moving
the printout into the critical section seems like a bad answer).
I'd be okay with removing WAL_DEBUG, I think, particularly in view of the
fact that there have been no requests to make it a compiled-by-default
feature.
regards, tom lane
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Mar 24, 2014 at 7:14 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Heikki Linnakangas <hlinnakangas@vmware.com> writes:
As we all know, when you compile with WAL_DEBUG, and enable wal_debug
GUC, you get output like this in the log for every inserted WAL record:LOG: INSERT @ 0/5407E578: prev 0/5407E4D0; xid 0; len 32: Standby -
running xacts: nextXid 774 latestCompletedXid 771 oldestRunningXid 772;
2 xacts: 7877929 0What I did *not* realize before is that the redo routine only gets
passed the first XLogRecData struct in the chain. Because of that, the
"xacts: 7877929 0" information above is garbage. That's probably not the
only rm_desc routine that didn't get the memo.Yeah, I recall having fixed at least one such bug in the past.
There are a few alternatives on how to fix that:
1. Do nothing. Add a comment somewhere explaining that rm_redo cannot
safely look at data beyond what's inserted in the first XLogRecData.We'll probably just make the same mistake again :-(. And I think there
already is such a comment someplace.2. Reconstruct the WAL data from the XLogRecData entries in a palloc'd
buffer, and pass that to rm_redo. That would be fairly expensive, but
you probably don't care about that if you've enabled wal_debug.3. Remove the feature altogether, so that enabling wal_debug doesn't
cause all insertions to be logged anymore (no changes to the logging
during replay). It's a lot less interesting now that we have pg_xlogdump.I think the main use-case for rm_desc anymore is making CONTEXT lines
for errors reported during WAL replay. I guess that situation does not
have the same problem, since we've already loaded the complete WAL record.However, I'm not sure how easy it's going to be for WAL_DEBUG to make the
data look the same as the replay case: in particular, substitution of
full-page-images for data would be tough to predict in advance (and moving
the printout into the critical section seems like a bad answer).I'd be okay with removing WAL_DEBUG, I think, particularly in view of the
fact that there have been no requests to make it a compiled-by-default
feature.
I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.
I don't know whether I'm the only one, though.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Robert Haas wrote:
On Mon, Mar 24, 2014 at 7:14 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
3. Remove the feature altogether, so that enabling wal_debug doesn't
cause all insertions to be logged anymore (no changes to the logging
during replay). It's a lot less interesting now that we have pg_xlogdump.I think the main use-case for rm_desc anymore is making CONTEXT lines
for errors reported during WAL replay. I guess that situation does not
have the same problem, since we've already loaded the complete WAL record.However, I'm not sure how easy it's going to be for WAL_DEBUG to make the
data look the same as the replay case: in particular, substitution of
full-page-images for data would be tough to predict in advance (and moving
the printout into the critical section seems like a bad answer).I'd be okay with removing WAL_DEBUG, I think, particularly in view of the
fact that there have been no requests to make it a compiled-by-default
feature.I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.I don't know whether I'm the only one, though.
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.
--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 03/25/2014 02:13 AM, Alvaro Herrera wrote:
Robert Haas wrote:
On Mon, Mar 24, 2014 at 7:14 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
3. Remove the feature altogether, so that enabling wal_debug doesn't
cause all insertions to be logged anymore (no changes to the logging
during replay). It's a lot less interesting now that we have pg_xlogdump.I think the main use-case for rm_desc anymore is making CONTEXT lines
for errors reported during WAL replay. I guess that situation does not
have the same problem, since we've already loaded the complete WAL record.However, I'm not sure how easy it's going to be for WAL_DEBUG to make the
data look the same as the replay case: in particular, substitution of
full-page-images for data would be tough to predict in advance (and moving
the printout into the critical section seems like a bad answer).I'd be okay with removing WAL_DEBUG, I think, particularly in view of the
fact that there have been no requests to make it a compiled-by-default
feature.I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.I don't know whether I'm the only one, though.
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.
I find it useful too, but I think pg_xlogdump can serve the same purpose.
One thing missing from pg_xlogdump is the capability to keep tracking
the inserted WAL, instead of dumping to the end of WAL and stopping
there. If we add an option to pg_xlogdump to poll the WAL instead of
bailing out at an error, I think it's a good replacement.
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Heikki Linnakangas wrote:
On 03/25/2014 02:13 AM, Alvaro Herrera wrote:
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.I find it useful too, but I think pg_xlogdump can serve the same purpose.
One thing missing from pg_xlogdump is the capability to keep
tracking the inserted WAL, instead of dumping to the end of WAL and
stopping there. If we add an option to pg_xlogdump to poll the WAL
instead of bailing out at an error, I think it's a good replacement.
"tail -f"-style? If we can make that work I'm okay with removing it
from the backend.
--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Tue, Mar 25, 2014 at 12:30 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:
I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.I don't know whether I'm the only one, though.
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.I find it useful too, but I think pg_xlogdump can serve the same purpose.
One thing missing from pg_xlogdump is the capability to keep tracking the
inserted WAL, instead of dumping to the end of WAL and stopping there. If we
add an option to pg_xlogdump to poll the WAL instead of bailing out at an
error, I think it's a good replacement.
Well, one nice thing about wal_debug is that the WAL is at that point
still associated with the session that generated it. But I grant
that's not a huge issue. How much work are we talking about to fix
this, though?
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 2014-03-25 10:49:54 -0700, Robert Haas wrote:
On Tue, Mar 25, 2014 at 12:30 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.I don't know whether I'm the only one, though.
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.I find it useful too, but I think pg_xlogdump can serve the same purpose.
One thing missing from pg_xlogdump is the capability to keep tracking the
inserted WAL, instead of dumping to the end of WAL and stopping there. If we
add an option to pg_xlogdump to poll the WAL instead of bailing out at an
error, I think it's a good replacement.Well, one nice thing about wal_debug is that the WAL is at that point
still associated with the session that generated it. But I grant
that's not a huge issue. How much work are we talking about to fix
this, though?
It's not entirely trivial, we'd essentially need to copy the loop in
CopyXLogRecordToWAL(). And do so while still holding the
WALInsertLock().
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 03/25/2014 08:05 PM, Andres Freund wrote:
On 2014-03-25 10:49:54 -0700, Robert Haas wrote:
On Tue, Mar 25, 2014 at 12:30 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:I've found WAL_DEBUG quite useful in the past, when working on
scalability, and have indeed wished for it to be
compiled-in-by-default.I don't know whether I'm the only one, though.
You are not. I would rather have it fixed than removed, if possible. I
don't really care too much about getting a performance hit to palloc the
records, really; being able to actually read what's happening is much
more useful.I find it useful too, but I think pg_xlogdump can serve the same purpose.
One thing missing from pg_xlogdump is the capability to keep tracking the
inserted WAL, instead of dumping to the end of WAL and stopping there. If we
add an option to pg_xlogdump to poll the WAL instead of bailing out at an
error, I think it's a good replacement.Well, one nice thing about wal_debug is that the WAL is at that point
still associated with the session that generated it. But I grant
that's not a huge issue. How much work are we talking about to fix
this, though?It's not entirely trivial, we'd essentially need to copy the loop in
CopyXLogRecordToWAL(). And do so while still holding the
WALInsertLock().
Oh, no, there's no need to do it while holding WALInsertLock. It's quite
trivial, actually, see attached. So it's not difficult to fix this if we
want to.
I just committed a patch to add a -f/--follow flag to pg_xlogdump. That
seems very handy, even if we decide to fix the wal_debug code. It
doesn't require compiling with wal_debug, and pg_xlogdump allows
filtering by rmgr id etc.
- Heikki
Attachments:
fix-wal-debug-on-insert.patchtext/x-diff; name=fix-wal-debug-on-insert.patchDownload
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index b573185..3b28905 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -1262,8 +1262,20 @@ begin:;
xlog_outrec(&buf, rechdr);
if (rdata->data != NULL)
{
+ StringInfoData recordbuf;
+
+ /*
+ * We have to piece together the WAL record data from the
+ * XLogRecData entries, so that we can pass it to the rm_desc
+ * function as one contiguous chunk.
+ */
+ initStringInfo(&recordbuf);
+ for (;rdata != NULL; rdata = rdata->next)
+ appendBinaryStringInfo(&recordbuf, rdata->data, rdata->len);
+
appendStringInfoString(&buf, " - ");
- RmgrTable[rechdr->xl_rmid].rm_desc(&buf, rechdr->xl_info, rdata->data);
+ RmgrTable[rechdr->xl_rmid].rm_desc(&buf, rechdr->xl_info, recordbuf.data);
+ pfree(recordbuf.data);
}
elog(LOG, "%s", buf.data);
pfree(buf.data);
On Wed, Mar 26, 2014 at 5:08 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:
Oh, no, there's no need to do it while holding WALInsertLock. It's quite
trivial, actually, see attached. So it's not difficult to fix this if we
want to.
Well is there any reason not to just commit that patch? I mean, it
seems odd to rip this out if the fix is straightforward and already
written.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 03/26/2014 04:51 PM, Robert Haas wrote:
On Wed, Mar 26, 2014 at 5:08 AM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:Oh, no, there's no need to do it while holding WALInsertLock. It's quite
trivial, actually, see attached. So it's not difficult to fix this if we
want to.Well is there any reason not to just commit that patch? I mean, it
seems odd to rip this out if the fix is straightforward and already
written.
I guess so. Committed..
- Heikki
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers