Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dpEPN-00026k-Er for pgsql-performance@arkaria.postgresql.org; Tue, 05 Sep 2017 14:00:53 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1dpEPM-0001N9-RN for pgsql-performance@arkaria.postgresql.org; Tue, 05 Sep 2017 14:00:52 +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 1dpENZ-0006ft-QI for pgsql-performance@postgresql.org; Tue, 05 Sep 2017 13:59:02 +0000 Received: from mail-io0-x231.google.com ([2607:f8b0:4001:c06::231]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84_2) (envelope-from ) id 1dpENT-0007ye-2m for pgsql-performance@postgresql.org; Tue, 05 Sep 2017 13:59:00 +0000 Received: by mail-io0-x231.google.com with SMTP id i200so16559432ioa.2 for ; Tue, 05 Sep 2017 06:58:54 -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; bh=lnd4s1aKmUN5DLvgpOjmNe/ed3O9lmiTX2yWNHNlD2Y=; b=YKTB4hY3ebEAcSqI7WvlpDX+zE7b+0VlNiQZYIgpymXleRSMZmydTjjjCQNNo8abzs vIgmGrI0gF6zDr+4gus99Xf/CIJ4a768WsKXJvsMlWT9/kekOJFL7L5p/pDgWh9VT3bH +UEXTBAz3a1ULUrOh5Rcahtdmp7krIMerwIzpCngQMA+NtGv9WqyjPGrWr5jVAPHOKs2 dPOr2togYDADFwRhaUYnpItWn6H/lQSlnEgHFTwGGwD66LV6mk2cEC8ExoX+f4BKUOkn QwbXojaFI0ujdLNcEKtfh4Z+yDAVCl2seKnKqgJkwb7bm0wDh+yfB2StDcfMD7AkUJGG VhPg== 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; bh=lnd4s1aKmUN5DLvgpOjmNe/ed3O9lmiTX2yWNHNlD2Y=; b=DHtXS1NqF8H0p6H2xgvFKd7eCYRTDegzA1OjAWG9CRr+rxEJr5dj6l9885iurBlkcj R2KUnpOkVUHJnNXka2w4/eIio7glGppLfgroYWYEVSQxPfsxUeKzrZZpJHJ0y7EnZM9Y gHna2Z7ZTgbPIwWE8y9cXh2zPbTMmXgQ9pjJf4pFgZX0et43Y3wTipfQAK5+08inZTE7 d1VT9yMXq8o+a6FnJXWtuUCp57TEHH0nFFCi6efQWs1xTgqheaLdgBZ37BIIbjRj/j7M C1YiGtdLEXl0QJ4IzWL5FXUe1SjveSERnk9iJBEPSFW6YPAtYKBhAxvKD19UI/Yc4JN6 OveQ== X-Gm-Message-State: AHPjjUh3ywnIqkNPM/xLnn7UPg5xSJx3EFkRzSKrgJKlJKqXAY516+SN CoKY98l9fhl6HKwGAOBJjLFHD7KzLamK X-Google-Smtp-Source: ADKCNb4VVWUQDzEcI/DWZRMn3HYO1Xujew0mf3/KRLrK23X39fGlQgbp3n33/9yPNCUxcjLNDbU7p4izG6A8JgPflF0= X-Received: by 10.36.36.67 with SMTP id f64mr4795379ita.10.1504619934069; Tue, 05 Sep 2017 06:58:54 -0700 (PDT) MIME-Version: 1.0 Received: by 10.79.140.148 with HTTP; Tue, 5 Sep 2017 06:58:53 -0700 (PDT) In-Reply-To: References: From: Soni M Date: Tue, 5 Sep 2017 20:58:53 +0700 Message-ID: Subject: Re: slow index scan performance To: "pgsql-performance@postgresql.org" Content-Type: multipart/alternative; boundary="001a1146ea90b13e6f055871a04a" 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 --001a1146ea90b13e6f055871a04a Content-Type: text/plain; charset="UTF-8" Trying on another server, it gives different result. -> Index Scan using response_log_by_activity on public.response_log rl2 (cost=0.00..50.29 rows=17 width=8) (actual time=0.955..0.967 rows=0 loops=30895) Output: rl2.activity_id, rl2.feed_id Index Cond: (rl2.activity_id = rl.activity_id) Filter: rl2.success Buffers: shared hit=2311312 read=132342 -> Index Scan using activity_pkey on public.activity a (cost=0.00..49.79 rows=1 width=12) (actual time=13.747..13.762 rows=1 loops=30892) Output: a.status_id, a.activity_id, a.visit_id Index Cond: (a.activity_id = rl.activity_id) Buffers: shared hit=124463 read=30175 Now, index scan on activity_pkey which take much slower. Can someone please explain these ? Thanks On Tue, Sep 5, 2017 at 8:46 PM, Soni M wrote: > It's Postgres 9.1.24 on RHEL 6.5 > > On Tue, Sep 5, 2017 at 8:24 PM, Soni M wrote: > >> Consider these 2 index scan produced by a query >> >> -> Index Scan using response_log_by_activity on public.response_log rl2 >> (cost=0.00..51.53 rows=21 width=8) (actual time=9.017..9.056 rows=0 >> loops=34098) >> Output: rl2.activity_id, >> rl2.feed_id >> Index Cond: (rl2.activity_id = >> rl.activity_id) >> Filter: rl2.success >> Buffers: shared hit=3357159 >> read=153313 >> -> Index Scan using activity_pkey on >> public.activity a (cost=0.00..51.10 rows=1 width=12) (actual >> time=0.126..0.127 rows=1 loops=34088) >> Output: a.status_id, a.activity_id, >> a.visit_id >> Index Cond: (a.activity_id = >> rl.activity_id) >> Buffers: shared hit=137925 read=32728 >> >> >> And it's size >> >> conscopy=# select pg_size_pretty(pg_relation_siz >> e('response_log_by_activity'::regclass)); >> pg_size_pretty >> ---------------- >> 7345 MB >> (1 row) >> >> conscopy=# select pg_size_pretty(pg_relation_siz >> e('activity_pkey'::regclass)); >> pg_size_pretty >> ---------------- >> 8110 MB >> (1 row) >> >> Index scan on response_log_by_activity is far slower. The table has just >> been repacked, and index rebuilt, but still slow. >> >> Is there any other way to make it faster ? >> >> Why Buffers: shared hit=3,357,159 read=153,313 on >> response_log_by_activity is much bigger than Buffers: shared hit=137925 >> read=32728 on activity_pkey while activity_pkey size is bigger ? >> >> -- >> Regards, >> >> Soni Maula Harriz >> > > > > -- > Regards, > > Soni Maula Harriz > -- Regards, Soni Maula Harriz --001a1146ea90b13e6f055871a04a Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Trying on another server, it gives different result.
<= br>
-> =C2=A0Index Scan using response_log_by_activity on= public.response_log rl2 =C2=A0(cost=3D0.00..50.29 rows=3D17 width=3D8) (ac= tual time=3D0.955..0.967 rows=3D0 loops=3D30895)
=C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Output: rl2.activity_id= , rl2.feed_id
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0Index Cond: (rl2.activity_id =3D rl.activity_id)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Filter: r= l2.success
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0Buffers: shared hit=3D2311312 read=3D132342
=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0-> =C2=A0Index Scan using activity_pkey on public.activ= ity a =C2=A0(cost=3D0.00..49.79 rows=3D1 width=3D12) (actual time=3D13.747.= .13.762 rows=3D1 loops=3D30892)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0Output: a.status_id, a.activity_id, a.visit_id
=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Index Cond: (a.activity_id =3D rl.= activity_id)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Buffers: = shared hit=3D124463 read=3D30175

Now, index = scan on activity_pkey which take much slower. Can someone please explain th= ese ?

Thanks

On Tue, Sep 5, 2017 at 8:46 PM, Soni M <= diptatapa@gmail.com> wrote:
It's Postgres 9.1.24 on RHEL 6.5

On Tue, Sep 5, 2017 at 8:24 PM, Soni M <diptatapa@gmail.com&= gt; wrote:
Consid= er these 2 index scan produced by a query

-> =C2= =A0Index Scan using response_log_by_activity on public.response_log rl2 =C2= =A0(cost=3D0.00..51.53 rows=3D21 width=3D8) (actual time=3D9.017..9.056 row= s=3D0 loops=3D34098)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0Output: rl2.activity_id, rl2.feed_id
=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Index Cond: (= rl2.activity_id =3D rl.activity_id)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Filter: rl2.success
=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared = hit=3D3357159 read=3D153313
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0I= ndex Scan using activity_pkey on public.activity a =C2=A0(cost=3D0.00..51.1= 0 rows=3D1 width=3D12) (actual time=3D0.126..0.127 rows=3D1 loops=3D34088)<= /div>
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Output: a.status_id,= a.activity_id, a.visit_id
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0Index Cond: (a.activity_id =3D rl.activity_id)
=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Buffers: shared hit=3D137925 read=3D32728=


And it's size

conscopy=3D# select pg_size_pretty(pg_relation_size('= ;response_log_by_activity'::regclass));
=C2=A0pg_size_pr= etty=C2=A0
----------------
=C2=A07345 MB
(1 = row)

conscopy=3D# select pg_size_pretty(pg_relatio= n_size('activity_pkey'::regclass));
=C2=A0pg_size_pr= etty=C2=A0
----------------
=C2=A08110 MB
(1 = row)

Index scan on response_log_by_activity = is far slower. The table has just been repacked, and index rebuilt, but sti= ll slow.

Is there any other way to make it faster ?

Why Buffe= rs: shared hit=3D3,357,159 read=3D153,313 on response_log_by_activity is mu= ch bigger than Buffers: shared hit=3D137925 read=3D32728 on activity_pkey w= hile activity_pkey size is bigger ?

--
Regards,

Soni Maula Harriz



--
Regards,

Soni Maula Harriz



--
=
Regards,

Soni Maula Harriz
--001a1146ea90b13e6f055871a04a--