Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dhMFr-0007cp-FK for pgsql-performance@arkaria.postgresql.org; Mon, 14 Aug 2017 20:46:31 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1dhMFr-0008EO-0j for pgsql-performance@arkaria.postgresql.org; Mon, 14 Aug 2017 20:46:31 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1dhMFp-00089Y-Oi for pgsql-performance@postgresql.org; Mon, 14 Aug 2017 20:46:30 +0000 Received: from mail-wm0-x22b.google.com ([2a00:1450:400c:c09::22b]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1dhMFm-0005ea-AU for pgsql-performance@postgresql.org; Mon, 14 Aug 2017 20:46:28 +0000 Received: by mail-wm0-x22b.google.com with SMTP id t201so1911786wmt.1 for ; Mon, 14 Aug 2017 13:46:26 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :cc; bh=LE49pJLr39ilB4iiC4sGS3y+bKRqi3eR2yuG+2sMB7g=; b=CqmE8hwGOVrx96iRrfehxVG45mySDG+aF45Vp1b06I55OdlXsibirdL95kSETR4vKT lyydTlcV8dFgQ0dRnduAcNiM1pwy4sOkad+vCJzNkGmysjFXcAwMORe7f7LQenlEcW+O F8jSHuV7IuvtSlDC1WjjGaUHa9eluxCvXcFV2Y9Up6PDpdzHEXoihw2rBSsi0NwravKw TxrByeY2/q82K6t8JckxwBUKj2TAO6SlTxUFy26+D17APSvWagxRkptt40Kx54BxzRzB fZXGv68pcPK460ra2RV81mbvL1x8tE46xxVIkTc/+vVCCDI9BawRydKuFWPKoLgCW13R qKxQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to:cc; bh=LE49pJLr39ilB4iiC4sGS3y+bKRqi3eR2yuG+2sMB7g=; b=Jqv6rHJpN687AQA9a52XXxJ0JatypXkkvhatEQ78dEop2kEv6DRHoS53JX5bicVlcG Zo2D2yPzRdghKoWqe1yRDgnY7EvQybfCphrxr4xWc25E/VXmQpMRaQxlYVNneB8dlovy qOllCYCEDwEIoqAZCAjZQeNIYpGWBlnjWQzXgfhOrWMasRXocd//hIC1oerXgOoWniVJ 7SE9cv2GVh0yyGI7zl/Y0psKhbBYOLA8r1H0CQc6fbdGb7I0Zmo14LFIr0Qzooi9YA+i 5uRKcimwbci7owEYpcVaEF65BPO7xZrAoHl+8EHai8GJIopbHL0TT3Q9047qq8zy9Nmi qtJA== X-Gm-Message-State: AHYfb5jt+osZLn1XU9cUBv4DOHMy1uBW0EpzgTGZyjqiPvuFNGuyCtqZ ToOe3EDEIBe9B7V2n8wOgjDDCmatOQ== X-Received: by 10.28.142.203 with SMTP id q194mr135747wmd.174.1502743584154; Mon, 14 Aug 2017 13:46:24 -0700 (PDT) MIME-Version: 1.0 Received: by 10.223.130.113 with HTTP; Mon, 14 Aug 2017 13:46:23 -0700 (PDT) In-Reply-To: References: From: Jeremy Finzel Date: Mon, 14 Aug 2017 15:46:23 -0500 Message-ID: Subject: Re: Odd sudden performance degradation related to temp object churn To: Scott Marlowe Cc: postgres performance list Content-Type: multipart/alternative; boundary="001a1143bf2685a8290556bcc1be" 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 --001a1143bf2685a8290556bcc1be Content-Type: text/plain; charset="UTF-8" On Mon, Aug 14, 2017 at 3:01 PM, Scott Marlowe wrote: > On Mon, Aug 14, 2017 at 1:53 PM, Jeremy Finzel wrote: > > This particular db is on 9.3.15. Recently we had a serious performance > > degradation related to a batch job that creates 4-5 temp tables and 5 > > indexes. It is a really badly written job but what really confuses us is > > that this job has been running for years with no issue remotely > approaching > > this one. We are also using pgpool. > > > > The job would kick off with 20-30 of similar queries running at once. > The > > thing normally takes only 30ms or so to run - it only operates on 1 > customer > > at a time (yes, it's horribly written). All of a sudden the cluster > started > > thrashing and performance seriously degraded. We tried a number of > things > > with no success: > > > > Analyzed the whole database > > Turned off full logging > > Turned off synchronous commit > > Vacuumed several of the catalog tables > > Checked if we had an abnormal high amount of traffic this time - we > didn't > > No abnormal disk/network issues (we would have seen much larger issues if > > that had been the case) > > Tried turning down the number of app nodes running > > > > What ended up completely resolving the issue was converting the query to > use > > ctes instead of temp tables. That means we avoided the disk writing and > the > > catalog churn, and useless indexes. However, we are baffled as to why > this > > could make such a big difference when we had no issue like this before, > and > > we have seen no systematic performance degradation in our system. > > > > Any insights would be greatly appreciated, as we are concerned not > knowing > > the root cause. > > How are your disks setup? One big drive with everything on it? > Separate disks for pg_xlog and pg's data dir and the OS logging? IO > contention is one of the big killers of db performance. It's one san volume ssd for the data and wal files. But logging and memory spilling and archived xlogs go to a local ssd disk. > Logging likely isn't your problem, but yeah you don't need to log > ERRYTHANG to see the problem either. Log long running queries temp > usage, buffer usage, query plans on slow queries, stuff like that. > > You've likely hit a "tipping point" in terms of data size. Either it's > cause the query planner to make a bad decision, or you're spilling to > disk a lot more than you used to. Be sure to log temporary stuff with log_temp_files = 0 in your > postgresql.conf and then look for temporary file in your logs. I bet > you've started spilling into the same place as your temp tables are > going, and by default that's your data directory. Adding another drive > and moving pgsql's temp table space to it might help. > We would not have competition between disk spilling and temp tables because what I described above - they are going to two different places. Also, I neglected to mention that we turned on auto-explain during this crisis, and found the query plan was good, it was just taking forever due to thrashing just seconds after we kicked off the batches. I did NOT turn on log_analyze and timing but it was enough to see there was no apparent query plan regression. Also, we had no change in the performance/plan after re-analyzing all tables. > Also increasing work_mem (but don't go crazy, it's per sort, so can > multiply fast on a busy server) > We are already up at 400MB, and this query was using memory in the low KB levels because it is very small (1 - 20 rows of data per temp table, and no expensive selects with missing indexes or anything). > Also log your query plans or run explain / explain analyze on the slow > queries to see what they're doing that's so expensive. > Yes, we did do that and there was nothing remarkable about the plan when we ran them in production. All we saw was that over time, the actual execution time (along with everything else on the entire system) started slowing down more and more as thrashing increased. But we found no evidence of a plan regression. Thank you! Any more feedback is much appreciated. --001a1143bf2685a8290556bcc1be Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
On M= on, Aug 14, 2017 at 3:01 PM, Scott Marlowe <scott.marlowe@gmail.com<= /a>> wrote:
On Mon, Aug 14, 2017 at 1:53 PM, Jeremy Finzel <finzelj@gmail.com> wrote:
> This particular db is on 9.3.15.=C2=A0 Recently we had a serious perfo= rmance
> degradation related to a batch job that creates 4-5 temp tables and 5<= br> > indexes.=C2=A0 It is a really badly written job but what really confus= es us is
> that this job has been running for years with no issue remotely approa= ching
> this one.=C2=A0 We are also using pgpool.
>
> The job would kick off with 20-30 of similar queries running at once.= =C2=A0 The
> thing normally takes only 30ms or so to run - it only operates on 1 cu= stomer
> at a time (yes, it's horribly written).=C2=A0 All of a sudden the = cluster started
> thrashing and performance seriously degraded.=C2=A0 We tried a number = of things
> with no success:
>
> Analyzed the whole database
> Turned off full logging
> Turned off synchronous commit
> Vacuumed several of the catalog tables
> Checked if we had an abnormal high amount of traffic this time - we di= dn't
> No abnormal disk/network issues (we would have seen much larger issues= if
> that had been the case)
> Tried turning down the number of app nodes running
>
> What ended up completely resolving the issue was converting the query = to use
> ctes instead of temp tables.=C2=A0 That means we avoided the disk writ= ing and the
> catalog churn, and useless indexes.=C2=A0 However, we are baffled as t= o why this
> could make such a big difference when we had no issue like this before= , and
> we have seen no systematic performance degradation in our system.
>
> Any insights would be greatly appreciated, as we are concerned not kno= wing
> the root cause.

How are your disks setup? One big drive with everything on it?<= br> Separate disks for pg_xlog and pg's data dir and the OS logging? IO
contention is one of the big killers of db performance.
It's one san volume ssd for the data and wal files.=C2=A0 = But logging and memory spilling and archived xlogs go to a local ssd disk.<= /div>
=C2=A0
Logging likely isn'= ;t your problem, but yeah you don't need to log
ERRYTHANG to see the problem either. Log long running queries temp
usage, buffer usage, query plans on slow queries, stuff like that.

You've likely hit a "tipping point" in terms of data size. Ei= ther it's
cause the query planner to make a bad decision, or you're spilling to disk a lot more than you used to.=C2=A0
Be sure to log temporary stuff with log_temp_files =3D 0 in your
postgresql.conf and then look for temporary file in your logs. I bet
you've started spilling into the same place as your temp tables are
going, and by default that's your data directory. Adding another drive<= br> and moving pgsql's temp table space to it might help.
<= div>
We would not have competition between disk spilling and = temp tables because what I described above - they are going to two differen= t places.=C2=A0 Also, I neglected to mention that we turned on auto-explain= during this crisis, and found the query plan was good, it was just taking = forever due to thrashing just seconds after we kicked off the batches.=C2= =A0 I did NOT turn on log_analyze and timing but it was enough to see there= was no apparent query plan regression.=C2=A0 Also, we had no change in the= performance/plan after re-analyzing all tables.
=C2=A0
Also increasing work_mem (but don't go crazy, it's per sort, so can=
multiply fast on a busy server)

We are = already up at 400MB, and this query was using memory in the low KB levels b= ecause it is very small (1 - 20 rows of data per temp table, and no expensi= ve selects with missing indexes or anything).
=C2=A0
Also log your query plans or run explain / explain analyze on the slow
queries to see what they're doing that's so expensive.

Yes, we did do that= and there was nothing remarkable about the plan when we ran them in produc= tion.=C2=A0 All we saw was that over time, the actual execution time (along= with everything else on the entire system) started slowing down more and m= ore as thrashing increased.=C2=A0 But we found no evidence of a plan regres= sion.

= Thank you!=C2=A0 Any more feedback is much appreciated.
--001a1143bf2685a8290556bcc1be--