Re: [HACKERS] Something is rotten in the state of Denmark...
Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 3:59 PM, Tom Lane t...@sss.pgh.pa.us wrote: Perhaps the difference has to do with whether pg_am's pg_class tuple is on a page that hasn't got enough room for a HOT update? But I definitely tried it several times and consistently got the same failure before. That seems plausible, except that I have no idea why that would vary from one test setup to another. I suggest pushing the patch you proposed upthread and seeing what the buildfarm thinks. Yeah. I have errands to do right now but will push it later. 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
Re: [HACKERS] Something is rotten in the state of Denmark...
Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 2:55 PM, Tom Lane t...@sss.pgh.pa.us wrote: Actually, now that I think it through, the could not open relation error is pretty odd in itself. If we are trying to open pg_am using a stale catalog snapshot, it seems like we ought to reliably find its old pg_class tuple (the one with the obsolete relfilenode), rather than finding nothing. But the latter is the behavior I'm seeing. What's to stop the old tuple from being HOT-pruned? Hm, that may be it. I went back to the previous test scenario, and now I can *only* get the cache lookup failed for access method behavior, instead of what I was getting before, so I'm getting a bit confused :-(. However, it does seem clear that the mechanism is indeed that we're relying on an obsolete copy of pg_am's pg_class tuple, hence scanning a truncated relfilenode, and that the patch I proposed fixes it. Perhaps the difference has to do with whether pg_am's pg_class tuple is on a page that hasn't got enough room for a HOT update? But I definitely tried it several times and consistently got the same failure before. 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
Re: [HACKERS] Something is rotten in the state of Denmark...
On Wed, Apr 1, 2015 at 7:05 PM, Tom Lane t...@sss.pgh.pa.us wrote: I've been able to reproduce this. The triggering event seems to be that the VACUUM FULL pg_am in vacuum.sql has to happen while another backend is starting up. With a ten-second delay inserted at the bottom of PerformAuthentication(), it's trivial to hit it manually. The reason we'd not seen this before the rolenames.sql test was added is that none of the other tests that run concurrently with vacuum.sql perform mid-test reconnections, or ever have AFAIR. So as long as they all managed to start up before vacuum.sql got to the dangerous step, no problem. I've not fully tracked it down, but I think that the blame falls on the MVCC-snapshots-for-catalog-scans patch; it appears that it's trying to read pg_am's pg_class entry with a snapshot that's too old, possibly because it assumes that sinval signaling is alive which I think ain't so. Hmm, sorry for the bug. It looks to me like sinval signaling gets started up at the beginning of InitPostgres(). Perhaps something like this? diff --git a/src/backend/utils/time/snapmgr.c b/src/backend/utils/time/snapmgr.c index 7cfa0cf..47c4002 100644 --- a/src/backend/utils/time/snapmgr.c +++ b/src/backend/utils/time/snapmgr.c @@ -303,7 +303,7 @@ GetNonHistoricCatalogSnapshot(Oid relid) * Mark new snapshost as valid. We must do this last, in case an * ERROR occurs inside GetSnapshotData(). */ - CatalogSnapshotStale = false; + CatalogSnapshotStale = !IsNormalProcessingMode(); } return CatalogSnapshot; -- 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
Re: [HACKERS] Something is rotten in the state of Denmark...
Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 2:40 PM, Tom Lane t...@sss.pgh.pa.us wrote: However, I'm having second thoughts about whether we've fully diagnosed this. Three out of the four failures we've seen in the buildfarm reported cache lookup failed for access method 403, not could not open relation with OID 2601 ... and I'm so far only able to replicate the latter symptom. It's really unclear how the former one could arise, because nothing that vacuum.sql does would change xmin of the rows in pg_am. It probably changes the *relfilenode* of pg_am, because it runs VACUUM FULL on that catalog. Perhaps some backend sees the old relfilenode value and tries to a heap scan, interpreting the now-truncated file as empty? Yeah, I came up with the same theory a few minutes later. Trying to reproduce on that basis. Actually, now that I think it through, the could not open relation error is pretty odd in itself. If we are trying to open pg_am using a stale catalog snapshot, it seems like we ought to reliably find its old pg_class tuple (the one with the obsolete relfilenode), rather than finding nothing. But the latter is the behavior I'm seeing. 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
Re: [HACKERS] Something is rotten in the state of Denmark...
On Thu, Apr 2, 2015 at 2:55 PM, Tom Lane t...@sss.pgh.pa.us wrote: Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 2:40 PM, Tom Lane t...@sss.pgh.pa.us wrote: However, I'm having second thoughts about whether we've fully diagnosed this. Three out of the four failures we've seen in the buildfarm reported cache lookup failed for access method 403, not could not open relation with OID 2601 ... and I'm so far only able to replicate the latter symptom. It's really unclear how the former one could arise, because nothing that vacuum.sql does would change xmin of the rows in pg_am. It probably changes the *relfilenode* of pg_am, because it runs VACUUM FULL on that catalog. Perhaps some backend sees the old relfilenode value and tries to a heap scan, interpreting the now-truncated file as empty? Yeah, I came up with the same theory a few minutes later. Trying to reproduce on that basis. Actually, now that I think it through, the could not open relation error is pretty odd in itself. If we are trying to open pg_am using a stale catalog snapshot, it seems like we ought to reliably find its old pg_class tuple (the one with the obsolete relfilenode), rather than finding nothing. But the latter is the behavior I'm seeing. What's to stop the old tuple from being HOT-pruned? -- 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
Re: [HACKERS] Something is rotten in the state of Denmark...
Robert Haas robertmh...@gmail.com writes: On Wed, Apr 1, 2015 at 7:05 PM, Tom Lane t...@sss.pgh.pa.us wrote: I've not fully tracked it down, but I think that the blame falls on the MVCC-snapshots-for-catalog-scans patch; it appears that it's trying to read pg_am's pg_class entry with a snapshot that's too old, possibly because it assumes that sinval signaling is alive which I think ain't so. Hmm, sorry for the bug. It looks to me like sinval signaling gets started up at the beginning of InitPostgres(). Perhaps something like this? Yeah, it does, so you'd think this would work. I've now tracked down exactly what's happening, and it's this: while we're reading pg_authid during PerformAuthentication, we establish a catalog snapshot. Later on, we read pg_database to find out what DB we're connecting to. If any sinval messages for unshared system catalogs arrive at that point, they'll effectively be ignored, *because our MyDatabaseId is still zero and so doesn't match the incoming message*. That's okay as far as the catcaches are concerned, cause they're empty, and the relcache only knows about shared catalogs so far. But InvalidateCatalogSnapshot doesn't get called by LocalExecuteInvalidationMessage, and so we think we can plow ahead with the old snapshot. It looks to me like an appropriate fix would be as attached; thoughts? (I've tested this with a delay during relation lock acquisition and concurrent whole-database VACUUM FULLs, and so far been unable to break it.) regards, tom lane diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c index 1e646a1..6aa6868 100644 *** a/src/backend/utils/init/postinit.c --- b/src/backend/utils/init/postinit.c *** InitPostgres(const char *in_dbname, Oid *** 853,858 --- 853,866 MyProc-databaseId = MyDatabaseId; /* + * We may have already established a catalog snapshot while trying to read + * pg_authid; but until we have set up MyDatabaseId, we won't react to + * incoming sinval messages properly, so we won't realize it if the + * snapshot has been invalidated. Best to assume it's no good anymore. + */ + InvalidateCatalogSnapshot(); + + /* * Now, take a writer's lock on the database we are trying to connect to. * If there is a concurrently running DROP DATABASE on that database, this * will block us until it finishes (and has committed its update of -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Something is rotten in the state of Denmark...
Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 12:54 PM, Tom Lane t...@sss.pgh.pa.us wrote: It looks to me like an appropriate fix would be as attached; thoughts? Hmm, that fix doesn't reach as far as what I did. My proposal would regard a catalog snapshot as immediately stale, so if we're asked for a catalog snapshot multiple times before InitPostgres() is called, we'll take a new one every time. Your proposal invalidates them just once, after setting up MyDatabaseId. Assuming yours is safe, it's better, because it invalidates less aggressively. Right. The only thing I'm worried about is that I think PerformAuthentication() runs before InitPostgres(); sinval isn't working at all at that point, even for shared catalogs. No, PerformAuthentication is called by InitPostgres. However, I'm having second thoughts about whether we've fully diagnosed this. Three out of the four failures we've seen in the buildfarm reported cache lookup failed for access method 403, not could not open relation with OID 2601 ... and I'm so far only able to replicate the latter symptom. It's really unclear how the former one could arise, because nothing that vacuum.sql does would change xmin of the rows in pg_am. 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
Re: [HACKERS] Something is rotten in the state of Denmark...
On Thu, Apr 2, 2015 at 2:40 PM, Tom Lane t...@sss.pgh.pa.us wrote: Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 12:54 PM, Tom Lane t...@sss.pgh.pa.us wrote: It looks to me like an appropriate fix would be as attached; thoughts? Hmm, that fix doesn't reach as far as what I did. My proposal would regard a catalog snapshot as immediately stale, so if we're asked for a catalog snapshot multiple times before InitPostgres() is called, we'll take a new one every time. Your proposal invalidates them just once, after setting up MyDatabaseId. Assuming yours is safe, it's better, because it invalidates less aggressively. Right. The only thing I'm worried about is that I think PerformAuthentication() runs before InitPostgres(); sinval isn't working at all at that point, even for shared catalogs. No, PerformAuthentication is called by InitPostgres. Oops, OK. However, I'm having second thoughts about whether we've fully diagnosed this. Three out of the four failures we've seen in the buildfarm reported cache lookup failed for access method 403, not could not open relation with OID 2601 ... and I'm so far only able to replicate the latter symptom. It's really unclear how the former one could arise, because nothing that vacuum.sql does would change xmin of the rows in pg_am. It probably changes the *relfilenode* of pg_am, because it runs VACUUM FULL on that catalog. Perhaps some backend sees the old relfilenode value and tries to a heap scan, interpreting the now-truncated file as empty? -- 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
Re: [HACKERS] Something is rotten in the state of Denmark...
On Thu, Apr 2, 2015 at 12:54 PM, Tom Lane t...@sss.pgh.pa.us wrote: Robert Haas robertmh...@gmail.com writes: On Wed, Apr 1, 2015 at 7:05 PM, Tom Lane t...@sss.pgh.pa.us wrote: I've not fully tracked it down, but I think that the blame falls on the MVCC-snapshots-for-catalog-scans patch; it appears that it's trying to read pg_am's pg_class entry with a snapshot that's too old, possibly because it assumes that sinval signaling is alive which I think ain't so. Hmm, sorry for the bug. It looks to me like sinval signaling gets started up at the beginning of InitPostgres(). Perhaps something like this? Yeah, it does, so you'd think this would work. I've now tracked down exactly what's happening, and it's this: while we're reading pg_authid during PerformAuthentication, we establish a catalog snapshot. Later on, we read pg_database to find out what DB we're connecting to. If any sinval messages for unshared system catalogs arrive at that point, they'll effectively be ignored, *because our MyDatabaseId is still zero and so doesn't match the incoming message*. That's okay as far as the catcaches are concerned, cause they're empty, and the relcache only knows about shared catalogs so far. But InvalidateCatalogSnapshot doesn't get called by LocalExecuteInvalidationMessage, and so we think we can plow ahead with the old snapshot. It looks to me like an appropriate fix would be as attached; thoughts? (I've tested this with a delay during relation lock acquisition and concurrent whole-database VACUUM FULLs, and so far been unable to break it.) Hmm, that fix doesn't reach as far as what I did. My proposal would regard a catalog snapshot as immediately stale, so if we're asked for a catalog snapshot multiple times before InitPostgres() is called, we'll take a new one every time. Your proposal invalidates them just once, after setting up MyDatabaseId. Assuming yours is safe, it's better, because it invalidates less aggressively. The only thing I'm worried about is that I think PerformAuthentication() runs before InitPostgres(); sinval isn't working at all at that point, even for shared catalogs. If we were to lock a relation, build a relcache entry, unlock it, and then do that again, all before SharedInvalBackendInit(false) is called, what would keep us from failing to notice an intervening invalidation? Maybe there is something, because otherwise this was probably broken even before the MVCC-catalog-snapshots patch, but I don't know what it is. -- 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
Re: [HACKERS] Something is rotten in the state of Denmark...
On Thu, Apr 2, 2015 at 3:59 PM, Tom Lane t...@sss.pgh.pa.us wrote: Robert Haas robertmh...@gmail.com writes: On Thu, Apr 2, 2015 at 2:55 PM, Tom Lane t...@sss.pgh.pa.us wrote: Actually, now that I think it through, the could not open relation error is pretty odd in itself. If we are trying to open pg_am using a stale catalog snapshot, it seems like we ought to reliably find its old pg_class tuple (the one with the obsolete relfilenode), rather than finding nothing. But the latter is the behavior I'm seeing. What's to stop the old tuple from being HOT-pruned? Hm, that may be it. I went back to the previous test scenario, and now I can *only* get the cache lookup failed for access method behavior, instead of what I was getting before, so I'm getting a bit confused :-(. However, it does seem clear that the mechanism is indeed that we're relying on an obsolete copy of pg_am's pg_class tuple, hence scanning a truncated relfilenode, and that the patch I proposed fixes it. Perhaps the difference has to do with whether pg_am's pg_class tuple is on a page that hasn't got enough room for a HOT update? But I definitely tried it several times and consistently got the same failure before. That seems plausible, except that I have no idea why that would vary from one test setup to another. I suggest pushing the patch you proposed upthread and seeing what the buildfarm thinks. -- 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
Re: [HACKERS] Something is rotten in the state of Denmark...
I wrote: Observe these recent buildfarm failures: http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=muledt=2015-03-21%2000%3A30%3A02 http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=guaibasaurusdt=2015-03-23%2004%3A17%3A01 http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=muledt=2015-03-31%2023%3A30%3A02 Three similar-looking failures, on two different machines, in a regression test that has existed for less than three weeks. Something is very wrong. I've been able to reproduce this. The triggering event seems to be that the VACUUM FULL pg_am in vacuum.sql has to happen while another backend is starting up. With a ten-second delay inserted at the bottom of PerformAuthentication(), it's trivial to hit it manually. The reason we'd not seen this before the rolenames.sql test was added is that none of the other tests that run concurrently with vacuum.sql perform mid-test reconnections, or ever have AFAIR. So as long as they all managed to start up before vacuum.sql got to the dangerous step, no problem. I've not fully tracked it down, but I think that the blame falls on the MVCC-snapshots-for-catalog-scans patch; it appears that it's trying to read pg_am's pg_class entry with a snapshot that's too old, possibly because it assumes that sinval signaling is alive which I think ain't so. For even more fun, try VACUUM FULL pg_class instead: psql: PANIC: could not open critical system index 2662 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
