Thread: 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
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
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 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. 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
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
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
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
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
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
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
Attachment
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
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