Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1X21bU-00028B-F7 for pgsql-performance@arkaria.postgresql.org; Tue, 01 Jul 2014 17:12:24 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1X21bT-00059q-QH for pgsql-performance@arkaria.postgresql.org; Tue, 01 Jul 2014 17:12:23 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1X21bS-00059j-6C for pgsql-performance@postgresql.org; Tue, 01 Jul 2014 17:12:22 +0000 Received: from smtp144.ord.emailsrvr.com ([173.203.6.144]) by makus.postgresql.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.80) (envelope-from ) id 1X21bP-00077n-6S for pgsql-performance@postgresql.org; Tue, 01 Jul 2014 17:12:20 +0000 Received: from localhost (localhost.localdomain [127.0.0.1]) by smtp27.relay.ord1a.emailsrvr.com (SMTP Server) with ESMTP id 2634A3803A7; Tue, 1 Jul 2014 13:12:17 -0400 (EDT) X-Virus-Scanned: OK Received: by smtp27.relay.ord1a.emailsrvr.com (Authenticated sender: jeff.frost-AT-pgexperts.com) with ESMTPSA id C0662380261; Tue, 1 Jul 2014 13:12:15 -0400 (EDT) X-Sender-Id: jeff.frost@pgexperts.com Received: from [10.10.10.17] (8.202-62-69.ftth.swbr.surewest.net [69.62.202.8]) (using TLSv1 with cipher AES128-SHA) by 0.0.0.0:587 (trex/5.2.4); Tue, 01 Jul 2014 17:12:16 GMT Content-Type: multipart/alternative; boundary="Apple-Mail=_A9F57A1A-072F-4C2F-BFC2-B827AA78A2F8" Mime-Version: 1.0 (Mac OS X Mail 7.3 \(1878.2\)) Subject: Re: Postgres Replaying WAL slowly From: Jeff Frost In-Reply-To: Date: Tue, 1 Jul 2014 10:12:14 -0700 Cc: Andres Freund , Matheus de Oliveira , Soni M , Heikki Linnakangas , pgsql-performance Message-Id: <608DF51D-AEFB-422B-AD2C-ABA9A114AA27@pgexperts.com> References: <20140630171416.GK21422@awork2.anarazel.de> <8DA8C140-818D-4184-AAE6-CA37278B983C@pgexperts.com> <20140630183908.GT26930@awork2.anarazel.de> <0A7B96D4-DB10-49A8-A268-F28960F2E137@pgexperts.com> <20300.1404156750@sss.pgh.pa.us> <20140630201523.GV26930@awork2.anarazel.de> <943ECC8E-8899-422E-937C-50DE20E1F7AC@pgexperts.com> <21474.1404160784@sss.pgh.pa.us> <2E438E7D-E3C1-47A1-A1AF-9FE50A14A302@pgexperts.com> <571D044B-260A-4E06-ACBC-8869B8F73C0F@pgexperts.com> <24455.1404169460@sss.pgh.pa.us> To: Tom Lane X-Mailer: Apple Mail (2.1878.2) X-Pg-Spam-Score: -2.6 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --Apple-Mail=_A9F57A1A-072F-4C2F-BFC2-B827AA78A2F8 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=us-ascii On Jun 30, 2014, at 4:57 PM, Jeff Frost wrote: >=20 > On Jun 30, 2014, at 4:04 PM, Tom Lane wrote: >=20 >> Ah ... that's more like a number I can believe something would have >> trouble coping with. Did you see a noticeable slowdown with this? >> Now that we've seen that number, of course it's possible there was an >> even higher peak occurring when you saw the trouble. >>=20 >> Perhaps there's an O(N^2) behavior in StandbyReleaseLocks, or maybe >> it just takes awhile to handle that many locks. >>=20 >> Did you check whether the locks were all on temp tables of the >> ON COMMIT DROP persuasion? >=20 >=20 > Unfortunately not, because I went for a poor man's: SELECT count(*) = FROM pg_locks WHERE mode =3D 'AccessExclusiveLock'=20 > run in cron every minute. >=20 > That said, I'd bet it was mostly ON COMMIT DROP temp tables. >=20 > The unfortunate thing is I wouldn't know how to correlate that spike = with the corresponding slowdown because the replica is about 5.5hrs = lagged at the moment. >=20 > Hopefully it will get caught up tonight and we can see if there's a = correlation tomorrow. And indeed it did catch up overnight and the lag increased shortly after = a correlating spike in AccessExclusiveLocks that were generated by temp = table creation with on commit drop. --Apple-Mail=_A9F57A1A-072F-4C2F-BFC2-B827AA78A2F8 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=us-ascii On Jun = 30, 2014, at 4:57 PM, Jeff Frost <jeff@pgexperts.com> = wrote:


On Jun 30, 2014, at 4:04 PM, Tom Lane = <tgl@sss.pgh.pa.us> = wrote:

Ah ... that's more like a number I = can believe something would have
trouble coping with.  Did = you see a noticeable slowdown with this?
Now that we've seen that = number, of course it's possible there was an
even higher peak occurring when you saw the = trouble.

Perhaps there's an O(N^2) behavior in StandbyReleaseLocks, = or maybe
it just takes awhile to handle that many locks.

Did you check whether the = locks were all on temp tables of the
ON COMMIT DROP = persuasion?


Unfortunately= not, because I went for a poor man's: SELECT count(*) FROM pg_locks = WHERE mode =3D 'AccessExclusiveLock' 
run in cron every = minute.

That said, I'd bet it was mostly ON = COMMIT DROP temp tables.

The unfortunate thing = is I wouldn't know how to correlate that spike with the corresponding = slowdown because the replica is about 5.5hrs lagged at the = moment.

Hopefully it will get caught up tonight = and we can see if there's a correlation = tomorrow.

And indeed it did catch = up overnight and the lag increased shortly after a correlating spike in = AccessExclusiveLocks that were generated by temp table creation with on = commit drop.


= --Apple-Mail=_A9F57A1A-072F-4C2F-BFC2-B827AA78A2F8--