Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1aVf7h-0006EL-Tu for pgsql-performance@arkaria.postgresql.org; Tue, 16 Feb 2016 12:52:58 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84) (envelope-from ) id 1aVf7h-00008J-Ah for pgsql-performance@arkaria.postgresql.org; Tue, 16 Feb 2016 12:52:57 +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) (envelope-from ) id 1aVf7g-00008D-Nw for pgsql-performance@postgresql.org; Tue, 16 Feb 2016 12:52:56 +0000 Received: from mail-wm0-x22a.google.com ([2a00:1450:400c:c09::22a]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84) (envelope-from ) id 1aVf7c-0007XI-Vq for pgsql-performance@postgresql.org; Tue, 16 Feb 2016 12:52:55 +0000 Received: by mail-wm0-x22a.google.com with SMTP id c200so159607311wme.0 for ; Tue, 16 Feb 2016 04:52:52 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=message-id:subject:from:reply-to:to:cc:date:in-reply-to:references :content-type:mime-version; bh=oETnC47YZE2KOzAltqwU0MkojQHvvwo/fPkBcchz+IM=; b=VJ/wAp/D7kwmbG0s2ja70dMxshj/YSNmmUMuvbYEJ/axsCiI5AwoCbUn+BthCQ4B6Z tuwIaE+NlrozqSsX8U4ce5lUpMJ4PCI7+H2UijXpIwlC1rp4cp/i8WjvW0pTo4NocmlW bvBMV1C4SIpV+pI+h07xyQ7diXHiy0dZq/MjV5dtlcN9H7w8E3SvwuLK5ptwoVtIJTkF 6pC/HVPlopF9usZUlbq6s3ySCeDxZCButxH44nlfSLVozlh6bR+ybUpT2WcKasgJZGLc D5zZC6kLEgZG+gX/+H3sNv8V2/XQiJUVTi8jmpLxEIUQjQnMMRgpx6O6fLh//LFyjQgP l3tQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:message-id:subject:from:reply-to:to:cc:date :in-reply-to:references:content-type:mime-version; bh=oETnC47YZE2KOzAltqwU0MkojQHvvwo/fPkBcchz+IM=; b=Txj+sc7RT/ZmEp1put34Xmg1AAYUnf2/F83sjItck5H39w0CVg9ndL4XqpaYf1Iot5 7nC1lDL5F3Ra7pnrAyPeaYyFkQjEzDGg442pOn4up/J1tJ1UVYWFsI+c2LhGJFEUHk+0 Pnvk5ipn/aKlSrr4HXtyjh23hgT+oohIK7BInAZ+iGvEfpJTgx8g1M+1BARvSxHiwp45 cuGj8DuEM7zYqmpxXh46cx6ZRK8CPCq2OZomxKKi1AN7sqdS+KNZtYD7zGx/pb80mlcc qVaCyhqG9l8WngwQE+Z2GLxDpkx79JVmOZWZzNq1H1EnVrp33KVs7sDFglvt7Opqtai+ JzYA== X-Gm-Message-State: AG10YOSJRr29eur2b+K0/E+cE9jIHgfQxJR6V+1qhAJ193NM7AOkdP3bnETXn28fx1diQg== X-Received: by 10.28.100.7 with SMTP id y7mr17389013wmb.87.1455627171698; Tue, 16 Feb 2016 04:52:51 -0800 (PST) Received: from enterprisedb01 (213.37.241.36.dyn.user.ono.com. [213.37.241.36]) by smtp.googlemail.com with ESMTPSA id v191sm20460038wme.1.2016.02.16.04.52.50 (version=TLSv1/SSLv3 cipher=OTHER); Tue, 16 Feb 2016 04:52:50 -0800 (PST) Message-ID: <1455627169.7311.61.camel@gmail.com> Subject: Re: Primary key index suddenly became very slow From: jaime soler Reply-To: jaime.soler@gmail.com To: Gustav Karlsson , "pgsql-performance@postgresql.org" Cc: Frode =?ISO-8859-1?Q?Nerbr=E5ten?= Date: Tue, 16 Feb 2016 13:52:49 +0100 In-Reply-To: References: <1DF45FCC-BB65-44B7-B10E-5A8EED3C6C84@bekk.no> Content-Type: multipart/alternative; boundary="=-xRRhNcEQ1q95pw1pWWGM" X-Mailer: Evolution 3.16.5-1ubuntu3.1 Mime-Version: 1.0 X-Pg-Spam-Score: -2.7 (--) 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 --=-xRRhNcEQ1q95pw1pWWGM Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 8bit El lun, 08-02-2016 a las 10:04 +0000, Gustav Karlsson escribió: > Additional information: > > The problematic row has likely received many hot updates (100k+). > Could this be a likely explanation for the high execution time? > > Could you check if autovacuum is doing its job with this query: select * from pg_stat_user_tables where relname='konto' , is it last_autovaccum and last_autoanalyze recent ? if you don't reduce n_dead_tup in a short time after the bulk process of hot update, it will be a explanation, and also a "idle in transaction" connection could cause it. This link: https://brandur.org/postgres-queues could help you. > > > Regards, > > Gustav > > > > > > > > > > > > > On Feb 8, 2016, at 10:45 AM, Gustav Karlsson wrote: > > > > > > > > > > Hi, > > > > > > > > Question: > > > > > > > > What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem. > > > > > > > > > > > > Background: > > > > > > > > We have a simple table ‘KONTO’ with about 600k rows. > > > > > > > > > > > > > > Column | Type | Modifiers > > > > ------------------------------+-----------------------------+--------------- > > > > id | bigint | not null > > > > > > ... > > > > > > > > > > Indexes: > > > > "konto_pk" PRIMARY KEY, btree (id) > > > > > > ... > > > > > > > > > > > > Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record: > > > > > > > > > > QUERY PLAN > > > > Index Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1) > > > > Index Cond: (id = 2121172829) > > > > Planning time: 0.376 ms > > > > Execution time: 2094.585 ms > > > > > > > > > > > > > > After a manual Vacuum the execution time is OK: > > > > > > > > > > QUERY PLAN > > > > Index Scan using konto_pk on konto (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1) > > > > Index Cond: (id = 2121172829) > > > > Planning time: 0.793 ms > > > > Execution time: 2.971 ms > > > > > > > > > > > > > > So things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4) > > > > > > > > > > > > > > > > Regards, > > > > Gustav > > > > > > > > > > > > > > > --=-xRRhNcEQ1q95pw1pWWGM Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: 8bit
El lun, 08-02-2016 a las 10:04 +0000, Gustav Karlsson escribió:
Additional information:

The problematic row has likely received many hot updates (100k+). Could this be a likely explanation for the high execution time?




Could you check if autovacuum is doing its job with this query:
select * from pg_stat_user_tables where relname='konto' , is it last_autovaccum and last_autoanalyze recent ?

if you don't reduce n_dead_tup in a short time after the bulk process of hot update, it will  be a explanation, and also a "idle in transaction" connection could cause it.

This link: https://brandur.org/postgres-queues could help you.



Regards,
Gustav



On Feb 8, 2016, at 10:45 AM, Gustav Karlsson <gustav.karlsson@bekk.no> wrote:

Hi,

Question:

What may cause a primary key index to suddenly become very slow? Index scan for single row taking 2-3 seconds. A manual vacuum resolved the problem.


Background:

We have a simple table ‘KONTO’ with about 600k rows. 


            Column            |            Type             |   Modifiers
------------------------------+-----------------------------+---------------
 id                           | bigint                      | not null
...

Indexes:
    "konto_pk" PRIMARY KEY, btree (id)
...


Over the weekend we experienced that lookups using the primary key index (‘konto_pk’) became very slow, in the region 2-3s for fetching a single record:

QUERY PLAN
Index Scan using konto_pk on konto  (cost=0.42..6.44 rows=1 width=164) (actual time=0.052..2094.549 rows=1 loops=1)
  Index Cond: (id = 2121172829)
Planning time: 0.376 ms
Execution time: 2094.585 ms


After a manual Vacuum the execution time is OK:

QUERY PLAN
Index Scan using konto_pk on konto  (cost=0.42..6.44 rows=1 width=164) (actual time=0.037..2.876 rows=1 loops=1)
  Index Cond: (id = 2121172829)
Planning time: 0.793 ms
Execution time: 2.971 ms


So things are working OK again, but we would like to know what may cause such a degradation of the index scan, to avoid this happening again? (We are using Postgresql version 9.4.4)



Regards,
Gustav

--=-xRRhNcEQ1q95pw1pWWGM--