Re: emergency outage requiring database restart
Re: [HACKERS] emergency outage requiring database restart
От:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
Дата:
On 11/7/16 5:31 PM, Merlin Moncure wrote: > Regardless, it seems like you might be on to something, and I'm > inclined to patch your change, test it, and roll it out to production. > If it helps or at least narrows the problem down, we ought to give it > consideration for inclusion (unless someone else can think of a good > reason not to do that, heh!). Any results yet? -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: [HACKERS] emergency outage requiring database restart
От:
Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
Дата:
On 11/2/16 11:45 AM, Oskari Saarenmaa wrote: > 26.10.2016, 21:34, Andres Freund kirjoitti: >> Any chance that plsh or the script it executes does anything with the file descriptors it inherits? That'd certainly one way to get into odd corruption issues. >> >> We processor really should use O_CLOEXEC for the majority of it file handles. > > Attached a patch to always use O_CLOEXEC in BasicOpenFile if we're not > using EXEC_BACKEND. It'd be nice to not expose all fds to most > pl-languages either, but I guess there's no easy solution to that > without forcibly closing all fds whenever any functions are called. It seems like everyone was generally in favor of this. I looked around the internet for caveats but everyone was basically saying, you should definitely do this. Why not for EXEC_BACKEND? O_CLOEXEC is a newer interface. There are older systems that don't have it but have FD_CLOEXEC for fcntl(). We should use that as a fallback. Have you gone through the code and checked for other ways file descriptors might get opened? Here is a blog posts that lists some candidates: http://udrepper.livejournal.com/20407.html Ideally, we would have a test case that exec's something that lists the open file descriptors, and we check that there are only those we expect. The comment "We don't expect execve() calls inside the postgres code" is not quite correct, as we do things like archive_command and COPY to program (see OpenPipeStream()). -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: [HACKERS] emergency outage requiring database restart
От:
Ants Aasma <ants.aasma@eesti.ee>
Дата:
On Wed, Jan 18, 2017 at 4:33 PM, Merlin Moncure wrote: > On Wed, Jan 18, 2017 at 4:11 AM, Ants Aasma wrote: >> On Wed, Jan 4, 2017 at 5:36 PM, Merlin Moncure wrote: >>> Still getting checksum failures. Over the last 30 days, I see the >>> following. Since enabling checksums FWICT none of the damage is >>> permanent and rolls back with the transaction. So creepy! >> >> The checksums still only differ in least significant digits which >> pretty much means that there is a block number mismatch. So if you >> rule out filesystem not doing its job correctly and transposing >> blocks, it could be something else that is resulting in blocks getting >> read from a location that happens to differ by a small multiple of >> page size. Maybe somebody is racily mucking with table fd's between >> seeking and reading. That would explain the issue disappearing after a >> retry. >> >> Maybe you can arrange for the RelFileNode and block number to be >> logged for the checksum failures and check what the actual checksums >> are in data files surrounding the failed page. If the requested block >> number contains something completely else, but the page that follows >> contains the expected checksum value, then it would support this >> theory. > > will do. Main challenge is getting hand compiled server to swap in > so that libdir continues to work. Getting access to the server is > difficult as is getting a maintenance window. I'll post back ASAP. As a new datapoint, we just had a customer with an issue that I think might be related. The issue was reasonably repeatable by running a report on the standby system. Issue manifested itself by first "could not open relation" and/or "column is not in index" errors, followed a few minutes later by a PANIC from startup process due to "specified item offset is too large", "invalid max offset number" or "page X of relation base/16384/1259 is uninitialized". I took a look at the xlog dump and it was completely fine. For instance in the "specified item offset is too large" case there was a INSERT_LEAF redo record inserting the preceding offset just a couple hundred kilobytes back. Restarting the server sometimes successfully applied the offending WAL, sometimes it failed with other corruption errors. The offending relations were always pg_class or pg_class_oid_index. Replacing plsh functions with dummy plpgsql functions made the problem go away, reintroducing plsh functions made it reappear. The only thing I came up with that is consistent with the symptoms is that a page got thrown out of shared_buffers between the two xlog records referencing it (shared_buffers was default 128MB), and then read back by a backend process, where in the time between FileSeek and FileRead calls in mdread a subprocess mucked with the fd's offset so that a different page than intended got read in. Or basically the same race condition, but on the write side. Maybe somebody else has a better imagination than me... Regards, Ants Aasma
Re: [HACKERS] emergency outage requiring database restart
От:
Ants Aasma <ants.aasma@eesti.ee>
Дата:
On Wed, Jan 4, 2017 at 5:36 PM, Merlin Moncure wrote: > Still getting checksum failures. Over the last 30 days, I see the > following. Since enabling checksums FWICT none of the damage is > permanent and rolls back with the transaction. So creepy! The checksums still only differ in least significant digits which pretty much means that there is a block number mismatch. So if you rule out filesystem not doing its job correctly and transposing blocks, it could be something else that is resulting in blocks getting read from a location that happens to differ by a small multiple of page size. Maybe somebody is racily mucking with table fd's between seeking and reading. That would explain the issue disappearing after a retry. Maybe you can arrange for the RelFileNode and block number to be logged for the checksum failures and check what the actual checksums are in data files surrounding the failed page. If the requested block number contains something completely else, but the page that follows contains the expected checksum value, then it would support this theory. Regards, Ants Aasma
Re: [HACKERS] emergency outage requiring database restart
От:
Michael Paquier <michael.paquier@gmail.com>
Дата:
On Wed, Jan 4, 2017 at 4:17 AM, Peter Eisentraut wrote: > It seems like everyone was generally in favor of this. I looked around > the internet for caveats but everyone was basically saying, you should > definitely do this. > > Why not for EXEC_BACKEND? > > O_CLOEXEC is a newer interface. There are older systems that don't have > it but have FD_CLOEXEC for fcntl(). We should use that as a fallback. > > Have you gone through the code and checked for other ways file > descriptors might get opened? Here is a blog posts that lists some > candidates: http://udrepper.livejournal.com/20407.html > > Ideally, we would have a test case that exec's something that lists the > open file descriptors, and we check that there are only those we expect. > > The comment "We don't expect execve() calls inside the postgres code" is > not quite correct, as we do things like archive_command and COPY to > program (see OpenPipeStream()). Oskari, are you planning to answer to this review? As the thread has died 3 weeks ago, I am marking this as returned with feedback. Don't hesitate to change the status of the patch if you have a new version. -- Michael
Re: [HACKERS] emergency outage requiring database restart
От:
Merlin Moncure <mmoncure@gmail.com>
Дата:
On Tue, Jan 3, 2017 at 1:05 PM, Peter Eisentraut
wrote:
> On 11/7/16 5:31 PM, Merlin Moncure wrote:
>> Regardless, it seems like you might be on to something, and I'm
>> inclined to patch your change, test it, and roll it out to production.
>> If it helps or at least narrows the problem down, we ought to give it
>> consideration for inclusion (unless someone else can think of a good
>> reason not to do that, heh!).
>
> Any results yet?
Not yet unfortunately. I compiled the server with the change, but was
not able get $libdir working so that I could just do a binary swap
over my pgdg compiled package. If anyone has some pointers on how to
do that, I'd appreciated it.
Still getting checksum failures. Over the last 30 days, I see the
following. Since enabling checksums FWICT none of the damage is
permanent and rolls back with the transaction. So creepy!
[root@rcdylsdbmpf001 pg_log]# cat *.log | grep "page verification failed"
2016-12-05 10:17:48 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 61797 but expected 61798
2016-12-05 11:15:31 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 37750 but expected 37749
2016-12-05 11:15:58 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 44483 but expected 44482
2016-12-05 11:16:33 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 58926 but expected 58925
2016-12-05 11:17:08 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 38527 but expected 38528
2016-12-05 11:18:34 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 61932 but expected 61933
2016-12-05 11:18:55 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 23757 but expected 23758
2016-12-05 12:13:48 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 44192 but expected 44225 at character 417
2016-12-08 14:18:37 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 36083 but expected 36082
2016-12-08 15:52:31 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 63414 but expected 63415 at
character 1096
2016-12-09 09:12:21 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 25781 but expected 25780
2016-12-09 09:13:20 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 63043 but expected 63044 at
character 4230
2016-12-12 08:57:45 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 31775 but expected 31771
2016-12-13 09:47:11 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 40802 but expected 40806
2016-12-15 12:49:04 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 11625 but expected 11592 at character 417
2016-12-15 12:51:08 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 51017 but expected 51018
2016-12-15 12:52:36 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 51017 but expected 51018 at character 417
2016-12-16 12:16:31 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 23580 but expected 23576
2016-12-20 13:59:33 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 45273 but expected 45285
2016-12-20 14:00:22 CST [postgres@castaging]: WARNING: page
verification failed, calculated checksum 10524 but expected 10525
note second database 'mpf2'. This is a new development. Example of
query that is jacking things is this:
2016-12-15 12:51:08 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 51017 but expected 51018
2016-12-15 12:51:08 CST [rms@mpf2]: CONTEXT: SQL statement " COPY ( SELECT 'DELETE FROM tblNAptCommonSample WHERE ReportPeriod = 201612;' UNION ALL SELECT format( 'INSERT INTO tblNAptCommonSample(' 'ReportPeriod, Period, AdjustmentType, PlanType, MSA, MSASubMkt, ' 'Sample, Occupancy, OccupancyChange, AverageRent,
AverageRentChange, RentSF, ' 'RentSFChange)' 'VALUES(' '%s, %s, ''%s'', ''%s'', ''%s'', %s,' '%s, %s, %s, %s, %s, %s,' '%s)', ReportPeriod, Period, AdjustmentType, PlanType, MSA, MSASubMkt, c(Sample), c(Occupancy), c(OccupancyChange), c(AverageRent),
c(AverageRentChange), c(RentSF), c(RentSFChange)) FROM tblNAptCommonSample WHERE Period = 201612 AND MSA != '5610' UNION ALL SELECT 'go' ) TO '/tmp/tblnaptcommonsample.sql'; " PL/pgSQL function writempf1history(integer) line 75 at EXECUTE
or this:
2016-12-15 12:52:36 CST [rms@mpf2]: WARNING: page verification
failed, calculated checksum 51017 but expected 51018 at character 417
2016-12-15 12:52:36 CST [rms@mpf2]: QUERY: COPY ( SELECT 'DELETE FROM tbltwrexistingunits WHERE ReportPeriod = 201612;' UNION ALL SELECT format( 'INSERT INTO tbltwrexistingunits(' 'ReportPeriod, market, submarketnum, yr_qtr, cmpltns, deletions, ' 'existing, unadjexisting)' 'VALUES(' '%s, ''%s'', %s, ''%s'', %s, %s,' '%s, %s)', ReportPeriod, market, submarket, yr_qtr, c(cmpltns), c(deletions), c(existing), c(unadjexisting)) FROM tbltwrexistingunits WHERE ReportPeriod = 201612 AND market != '5610' UNION ALL SELECT 'go' ) TO '/tmp/tbltwrexistingunits.sql';
2016-12-15 12:52:36 CST [rms@mpf2]: CONTEXT: PL/pgSQL function
writempf1history(integer) line 109 at EXECUTE
This is another (much simpler) routine that:
1. writes out data to scratch file with COPY
2. uses pl/sh to pipe to sqsh
merlin
Re: emergency outage requiring database restart
От:
Merlin Moncure <mmoncure@gmail.com>
Дата:
On Wed, Oct 26, 2016 at 12:43 PM, Merlin Moncure wrote: > On Wed, Oct 26, 2016 at 11:35 AM, Merlin Moncure wrote: >> On Tue, Oct 25, 2016 at 3:08 PM, Merlin Moncure wrote: >>> Confirmation of problem re-occurrence will come in a few days. I'm >>> much more likely to believe 6+sigma occurrence (storage, freak bug, >>> etc) should it prove the problem goes away post rebuild. >> >> ok, no major reported outage yet, but just got: >> >> 2016-10-26 11:27:55 CDT [postgres@castaging]: ERROR: invalid page in >> block 12 of relation base/203883/1259 *) I've now strongly correlated this routine with the damage. [root@rcdylsdbmpf001 ~]# cat /var/lib/pgsql/9.5/data/pg_log/postgresql-26.log | grep -i pushmarketsample | head -5 2016-10-26 11:26:27 CDT [postgres@castaging]: LOG: execute : SELECT PushMarketSample($1::TEXT) AS published 2016-10-26 11:26:40 CDT [postgres@castaging]: LOG: execute : SELECT PushMarketSample($1::TEXT) AS published PL/pgSQL function pushmarketsample(text,date,integer) line 103 at SQL statement PL/pgSQL function pushmarketsample(text,date,integer) line 103 at SQL statement 2016-10-26 11:26:42 CDT [postgres@castaging]: STATEMENT: SELECT PushMarketSample($1::TEXT) AS published *) First invocation was 11:26:27 CDT *) Second invocation was 11:26:40 and gave checksum error (as noted earlier 11:26:42) *) Routine attached (if interested) My next step is to set up test environment and jam this routine aggressively to see what happens. merlin
Re: [HACKERS] emergency outage requiring database restart
От:
Merlin Moncure <mmoncure@gmail.com>
Дата:
On Tue, Jan 3, 2017 at 1:05 PM Peter Eisentraut wrote: > > On 11/7/16 5:31 PM, Merlin Moncure wrote: > > Regardless, it seems like you might be on to something, and I'm > > inclined to patch your change, test it, and roll it out to production. > > If it helps or at least narrows the problem down, we ought to give it > > consideration for inclusion (unless someone else can think of a good > > reason not to do that, heh!). > > Any results yet? Not yet. But I do have some interesting findings. At this point I do not think the problem is within pl/sh itself, but that when a process is invoked from pl/sh misbehaves that misbehavior can penetrate into the database processes. I also believe that this problem is fd related, so that the 'close on exec' might reasonably fix it. All cases of database damage I have observed remain completely mitigated by enabling database checksums. Recently, a sqsh process kicked off via pl/sh crashed with signal 11 but the database process was otherwise intact and fine. This is strong supporting evidence to my points above, I think. I've also turned up a fairly reliable reproduction case from some unrelated application changes. If I can demonstrate that close on exec flag works and prevents these occurrences we can close the book on this. merlin
Re: [HACKERS] emergency outage requiring database restart
От:
Merlin Moncure <mmoncure@gmail.com>
Дата:
On Wed, Jan 18, 2017 at 4:11 AM, Ants Aasma wrote: > On Wed, Jan 4, 2017 at 5:36 PM, Merlin Moncure wrote: >> Still getting checksum failures. Over the last 30 days, I see the >> following. Since enabling checksums FWICT none of the damage is >> permanent and rolls back with the transaction. So creepy! > > The checksums still only differ in least significant digits which > pretty much means that there is a block number mismatch. So if you > rule out filesystem not doing its job correctly and transposing > blocks, it could be something else that is resulting in blocks getting > read from a location that happens to differ by a small multiple of > page size. Maybe somebody is racily mucking with table fd's between > seeking and reading. That would explain the issue disappearing after a > retry. > > Maybe you can arrange for the RelFileNode and block number to be > logged for the checksum failures and check what the actual checksums > are in data files surrounding the failed page. If the requested block > number contains something completely else, but the page that follows > contains the expected checksum value, then it would support this > theory. will do. Main challenge is getting hand compiled server to swap in so that libdir continues to work. Getting access to the server is difficult as is getting a maintenance window. I'll post back ASAP. merlin
Re: [HACKERS] emergency outage requiring database restart
От:
Merlin Moncure <mmoncure@gmail.com>
Дата:
On Thu, Aug 10, 2017 at 12:01 PM, Ants Aasma wrote: > On Wed, Jan 18, 2017 at 4:33 PM, Merlin Moncure wrote: >> On Wed, Jan 18, 2017 at 4:11 AM, Ants Aasma wrote: >>> On Wed, Jan 4, 2017 at 5:36 PM, Merlin Moncure wrote: >>>> Still getting checksum failures. Over the last 30 days, I see the >>>> following. Since enabling checksums FWICT none of the damage is >>>> permanent and rolls back with the transaction. So creepy! >>> >>> The checksums still only differ in least significant digits which >>> pretty much means that there is a block number mismatch. So if you >>> rule out filesystem not doing its job correctly and transposing >>> blocks, it could be something else that is resulting in blocks getting >>> read from a location that happens to differ by a small multiple of >>> page size. Maybe somebody is racily mucking with table fd's between >>> seeking and reading. That would explain the issue disappearing after a >>> retry. >>> >>> Maybe you can arrange for the RelFileNode and block number to be >>> logged for the checksum failures and check what the actual checksums >>> are in data files surrounding the failed page. If the requested block >>> number contains something completely else, but the page that follows >>> contains the expected checksum value, then it would support this >>> theory. >> >> will do. Main challenge is getting hand compiled server to swap in >> so that libdir continues to work. Getting access to the server is >> difficult as is getting a maintenance window. I'll post back ASAP. > > As a new datapoint, we just had a customer with an issue that I think > might be related. The issue was reasonably repeatable by running a > report on the standby system. Issue manifested itself by first "could > not open relation" and/or "column is not in index" errors, followed a > few minutes later by a PANIC from startup process due to "specified > item offset is too large", "invalid max offset number" or "page X of > relation base/16384/1259 is uninitialized". I took a look at the xlog > dump and it was completely fine. For instance in the "specified item > offset is too large" case there was a INSERT_LEAF redo record > inserting the preceding offset just a couple hundred kilobytes back. > Restarting the server sometimes successfully applied the offending > WAL, sometimes it failed with other corruption errors. The offending > relations were always pg_class or pg_class_oid_index. Replacing plsh > functions with dummy plpgsql functions made the problem go away, > reintroducing plsh functions made it reappear. Fantastic. I was never able to attempt to apply O_CLOEXEC patch (see upthread) due to the fact that access to the system is highly limited and compiling a replacement binary was a bit of a headache. IIRC this was the best theory on the table as to the underlying cause and we ought to to try that first, right? Reminder; I was able to completely eliminate all damage (but had to handle occasional unexpected rollback) via enabling checksums. merlin
Re: emergency outage requiring database restart
От:
Oskari Saarenmaa <os@ohmu.fi>
Дата:
26.10.2016, 21:34, Andres Freund kirjoitti: > Any chance that plsh or the script it executes does anything with the file descriptors it inherits? That'd certainly one way to get into odd corruption issues. > > We processor really should use O_CLOEXEC for the majority of it file handles. Attached a patch to always use O_CLOEXEC in BasicOpenFile if we're not using EXEC_BACKEND. It'd be nice to not expose all fds to most pl-languages either, but I guess there's no easy solution to that without forcibly closing all fds whenever any functions are called. / Oskari
