Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1ngruc-0004Zz-JE for pgsql-admin@arkaria.postgresql.org; Tue, 19 Apr 2022 17:45:14 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1ngrub-0007jU-Du for pgsql-admin@arkaria.postgresql.org; Tue, 19 Apr 2022 17:45:13 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1ngrua-0007jJ-NE for pgsql-admin@lists.postgresql.org; Tue, 19 Apr 2022 17:45:13 +0000 Received: from mail-yb1-xb2b.google.com ([2607:f8b0:4864:20::b2b]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1ngruX-0007eI-8v for pgsql-admin@lists.postgresql.org; Tue, 19 Apr 2022 17:45:11 +0000 Received: by mail-yb1-xb2b.google.com with SMTP id p65so32385554ybp.9 for ; Tue, 19 Apr 2022 10:45:09 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=saama.com; s=google; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=AjvavIkDNlAqZpwdg+VvA1FYx47muAapPakMOj1WyvE=; b=UYI555YLGFATXr7LYnUeG8dQhDnjWW27xDuiAa3MF330QYClaK6Lhnr0/aCkDoEgGt TdYEj7b8xLpS473XipasOmz1ypqm/SlM7IUBWIhOhEinFK/htRvESHX2QRNuS3zgC0/3 2a7ojSLy0/g8+65TdMwQtdFRajB9t9Jaff4js= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=AjvavIkDNlAqZpwdg+VvA1FYx47muAapPakMOj1WyvE=; b=cGYdAstIGNeU3n2PSscTEIDN36IJPdFR9TrGMLKVpBMBT7ixwMzPmZmSRZzQ3fHRdL O1ewHSHG29ReaQcRgV5aXE+IRwshKqbz1PS8fXYNF0PVoyghS57dXmdNOhwPGFf6iUUE OMcMxrq5N2x95AJFJ/nEOIXp2xVZitsuZ1vWjGBWIK1KV0ccdAp8EftA0c1g+1RSxuZe X8HJo5bLNHPNfbA1KlUe/d81vPqcLSaJ/8MWevsqrDjL9bomVdBbv5nyTXfkG0z2CFBq UlDoLFd9QMs0AY7wy8w6H7+Sa9PeYsrzoQ17Sz08mbz/uUlQ2dOCKO3of2yXxIKpLh7s XSsg== X-Gm-Message-State: AOAM5337ufQ1yis4OuTc7f2IhEpuB+ShmupJYBauX2g+g6r+WEeXxdTc wN7pK4rebQCF7fB+p/4Dk/T3CObhgWtIu8PT1wO9o9MbVj4qVdNVrTyi95OmVZVtzf5Hymf0xo5 pGkgvGtbOC4poWGHPlhFz+//VtTL4K2dfoVhj8w== X-Google-Smtp-Source: ABdhPJz6NRICoObF9wryl4HcqQI1doFjBIMfcNXpnwA+tPh7hDdgecZE5iRtyDV0AUIwnWTFjXrbQOgV8SBAKNBP4MQ= X-Received: by 2002:a25:d203:0:b0:641:6e3c:c56d with SMTP id j3-20020a25d203000000b006416e3cc56dmr15774245ybg.191.1650390308511; Tue, 19 Apr 2022 10:45:08 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: Gaurav Anand Date: Tue, 19 Apr 2022 23:14:57 +0530 Message-ID: Subject: Re: PG Query Planner To: Kenny Bachman Cc: pgsql-admin@lists.postgresql.org Content-Type: multipart/alternative; boundary="0000000000001476bf05dd057091" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --0000000000001476bf05dd057091 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable Looks like your Index has gone wrong, instead of 92355 records it is scanning 8021769 rows which is why it is taking 6s. Share the sql too On Tue, 19 Apr 2022 at 11:07 PM, Kenny Bachman wrote: > Hello, > > I wonder how the query planner works in postgresql. So, I have a query > that takes 6 seconds with an index scan. However, the same query takes > 0.1ms when I set disable index scan parameter. > > How do I get the planner to make the right decision? Also, I ran ANALYZE > command many times. > > And I have an index on job_next_process_time column but did not use it b= y > the planner. > > Limit (cost=3D0.56..29.04 rows=3D1 width=3D695) (actual time=3D6386.751.= .6386.753 > rows=3D0 loops=3D1) > -> Nested Loop (cost=3D0.56..692987.46 rows=3D24331 width=3D695) (ac= tual > time=3D6386.749..6386.751 rows=3D0 loops=3D1) > Join Filter: (subs.offer_id =3D offer1.id) > -> Index Scan using subs_pkey on subscription subs > (cost=3D0.56..572151.65 rows=3D8053633 width=3D695) (actual time=3D0.008= ..5554.872 > rows=3D8021769 loops=3D1) > Filter: ((NOT job_in_progress) AND (job_next_process_time = < > '2022-04-19 09:25:25.535'::timestamp without time zone)) > Rows Removed by Filter: 72039 > -> Materialize (cost=3D0.00..31.31 rows=3D1 width=3D8) (actual > time=3D0.000..0.000 rows=3D0 loops=3D8021769) > -> Seq Scan on offer offer1 (cost=3D0.00..31.31 rows=3D1 > width=3D8) (actual time=3D0.087..0.088 rows=3D0 loops=3D1) > Filter: (NOT is_external_lifecycle_management) > Rows Removed by Filter: 334 > Planning Time: 1.335 ms > Execution Time: 6386.792 ms > > *SET enable_indexscan =3D OFF;* > > Limit (cost=3D84760.55..84760.55 rows=3D1 width=3D695) (actual > time=3D0.092..0.093 rows=3D0 loops=3D1) > -> Sort (cost=3D84760.55..84822.63 rows=3D24832 width=3D695) (actual > time=3D0.092..0.092 rows=3D0 loops=3D1) > Sort Key: subs.id > Sort Method: quicksort Memory: 25kB > -> Nested Loop (cost=3D955.54..84636.39 rows=3D24832 width=3D6= 95) > (actual time=3D0.090..0.090 rows=3D0 loops=3D1) > -> Seq Scan on offer offer1 (cost=3D0.00..31.31 rows=3D1 > width=3D8) (actual time=3D0.089..0.089 rows=3D0 loops=3D1) > Filter: (NOT is_external_lifecycle_management) > Rows Removed by Filter: 334 > -> Bitmap Heap Scan on subscription subs > (cost=3D955.54..83681.53 rows=3D92355 width=3D695) (never executed) > Recheck Cond: (offer_id =3D offer1.id) > Filter: ((NOT job_in_progress) AND > (job_next_process_time < '2022-04-19 09:25:25.535'::timestamp without tim= e > zone)) > -> Bitmap Index Scan on i_fk_subscription_offer > (cost=3D0.00..932.45 rows=3D93029 width=3D0) (never executed) > Index Cond: (offer_id =3D offer1.id) > Planning Time: 0.266 ms > Execution Time: 0.126 ms > --=20 Thanks. Regards, Gaurav Anand [image: logo] --=20 This communication is confidential and subject to and governed by=C2=A0Saama=E2=80=99s=C2=A0 Electronic Communications Disclaimer.=20 =C2=A0 --0000000000001476bf05dd057091 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
Looks like your Index has gone wrong, = instead of 92355 records it is scanning =C2=A0=C2=A0 =C2=A08021769 rows which is why it is taking 6s.

Share the sql too

On Tue, 19 Apr 2022 at 11:= 07 PM, Kenny Bachman <kenny= .bachman17@gmail.com> wrote:
Hello,

I wonder how the query planner works in postg= resql. So, I have a query that takes 6 seconds with an index scan. However,= the same query takes 0.1ms when I set disable index scan parameter.
<= div>
How do I get the=C2=A0planner to make the right decision= ? Also, I ran ANALYZE command many times.

And I ha= ve an index on job_next_process_time=C2=A0 column but did not use it by the= planner.

Limit =C2=A0(cost=3D0.56..29.04 rows=3D1= width=3D695) (actual time=3D6386.751..6386.753 rows=3D0 loops=3D1)
=C2= =A0 =C2=A0-> =C2=A0Nested Loop =C2=A0(cost=3D0.56..692987.46 rows=3D2433= 1 width=3D695) (actual time=3D6386.749..6386.751 rows=3D0 loops=3D1)
=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Join Filter: (subs.offer_id =3D offer1.id)
=C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0-> =C2=A0Index Scan using subs_pkey on subscription subs = =C2=A0(cost=3D0.56..572151.65 rows=3D8053633 width=3D695) (actual time=3D0.= 008..5554.872 rows=3D8021769 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0Filter: ((NOT job_in_progress) AND (job_next_proces= s_time < '2022-04-19 09:25:25.535'::timestamp without time zone)= )
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Rows Removed by= Filter: 72039
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Materialize= =C2=A0(cost=3D0.00..31.31 rows=3D1 width=3D8) (actual time=3D0.000..0.000 = rows=3D0 loops=3D8021769)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0-> =C2=A0Seq Scan on offer offer1 =C2=A0(cost=3D0.00..31.31 ro= ws=3D1 width=3D8) (actual time=3D0.087..0.088 rows=3D0 loops=3D1)
=C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Filte= r: (NOT is_external_lifecycle_management)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Rows Removed by Filter: 334=
=C2=A0Planning Time: 1.335 ms
=C2=A0Execution Time: 6386.792 ms
<= /div>

SET enable_indexscan =3D OFF;
=C2=A0 Limit =C2=A0(cost=3D84760.55..84760.55 rows=3D1 width=3D= 695) (actual time=3D0.092..0.093 rows=3D0 loops=3D1)
=C2=A0 =C2=A0-> = =C2=A0Sort =C2=A0(cost=3D84760.55..84822.63 rows=3D24832 width=3D695) (actu= al time=3D0.092..0.092 rows=3D0 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0Sort Key: subs.id=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Sort Method: quicksort =C2=A0Memory: 25k= B
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Nested Loop =C2=A0(cost= =3D955.54..84636.39 rows=3D24832 width=3D695) (actual time=3D0.090..0.090 r= ows=3D0 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0-> =C2=A0Seq Scan on offer offer1 =C2=A0(cost=3D0.00..31.31 rows=3D1 = width=3D8) (actual time=3D0.089..0.089 rows=3D0 loops=3D1)
=C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Filter: (NOT= is_external_lifecycle_management)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Rows Removed by Filter: 334
=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Bitmap Heap= Scan on subscription subs =C2=A0(cost=3D955.54..83681.53 rows=3D92355 widt= h=3D695) (never executed)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Recheck Cond: (offer_id =3D offer1.id)
=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Filter: ((NOT job_in_pr= ogress) AND (job_next_process_time < '2022-04-19 09:25:25.535'::= timestamp without time zone))
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Bitmap Index Scan on i_fk_sub= scription_offer =C2=A0(cost=3D0.00..932.45 rows=3D93029 width=3D0) (never e= xecuted)
=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: (offer_id =3D offer1.id)
=C2=A0Planning Time: 0.26= 6 ms
=C2=A0Execution Time: 0.126 ms
--
<= div>

Thanks.

R= egards,
Gaurav Anand

3D"logo"

This communication is confidential and subject to and governed by=C2=A0Saama=E2=80=99s=C2=A0Electronic Communications Disclaimer.

=C2=A0

--0000000000001476bf05dd057091--