Date: Wed, 23 Apr 2008 11:06:08 +0200
From: hans <hans.ekbrand@sociology.gu.se>
To: pgsql-performance@postgresql.org
Subject: Re: mysterious difference in speed when combining two queries with OR
Message-ID: <20080423090605.GE6957@Spelmaskinen>
References: <20080423072303.GF11886@amin>
	<20080423075810.GB8401@a-kretschmer.de>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha1;
	protocol="application/pgp-signature"; boundary="Qz2CZ664xQdCRdPu"
Content-Disposition: inline
In-Reply-To: <20080423075810.GB8401@a-kretschmer.de>
User-Agent: Mutt/1.5.15+20070412 (2007-04-11)


--Qz2CZ664xQdCRdPu
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Wed, Apr 23, 2008 at 09:58:10AM +0200, A. Kretschmer wrote:
> am  Wed, dem 23.04.2008, um  9:23:07 +0200 mailte Hans Ekbrand folgendes:
> > I cannot understand why the following two queries differ so much in exe=
cution time (almost ten times)
>=20
> wild guess: different execution plans.
>=20
>=20
> Can you show us the plans? (EXPLAIN ANALYSE SELECT ...)

Query A (first part)

fektest=3D> explain analyse select distinct moment.mid from moment,timecard=
 where parent =3D 45 and (pid=3D17 and timecard.mid =3D moment.mid) order b=
y moment.mid;
                                                         QUERY PLAN        =
                                                 =20
---------------------------------------------------------------------------=
--------------------------------------------------
 Unique  (cost=3D287.66..288.67 rows=3D203 width=3D4) (actual time=3D11.412=
=2E.11.622 rows=3D41 loops=3D1)
   ->  Sort  (cost=3D287.66..288.16 rows=3D203 width=3D4) (actual time=3D11=
=2E409..11.484 rows=3D57 loops=3D1)
         Sort Key: moment.mid
         ->  Hash Join  (cost=3D60.98..279.88 rows=3D203 width=3D4) (actual=
 time=3D2.346..11.182 rows=3D57 loops=3D1)
               Hash Cond: ("outer".mid =3D "inner".mid)
               ->  Seq Scan on timecard  (cost=3D0.00..211.78 rows=3D1017 w=
idth=3D4) (actual time=3D0.031..7.427 rows=3D995 loops=3D1)
                     Filter: (pid =3D 17)
               ->  Hash  (cost=3D59.88..59.88 rows=3D444 width=3D4) (actual=
 time=3D2.127..2.127 rows=3D0 loops=3D1)
                     ->  Seq Scan on moment  (cost=3D0.00..59.88 rows=3D444=
 width=3D4) (actual time=3D0.027..1.825 rows=3D199 loops=3D1)
                           Filter: (parent =3D 45)
 Total runtime: 11.852 ms
(11 rows)

Query A (second part)

fektest=3D> explain analyse select distinct moment.mid from moment,timecard=
 where parent =3D 45 and (pbar =3D 0) order by moment.mid;
                                                              QUERY PLAN   =
                                                          =20
---------------------------------------------------------------------------=
-----------------------------------------------------------
 Unique  (cost=3D192.62..3800.67 rows=3D20 width=3D4) (actual time=3D0.578.=
=2E109.274 rows=3D2 loops=3D1)
   ->  Nested Loop  (cost=3D192.62..3417.57 rows=3D153240 width=3D4) (actua=
l time=3D0.575..89.546 rows=3D15324 loops=3D1)
         ->  Index Scan using moment_mid_idx on moment  (cost=3D0.00..160.1=
5 rows=3D20 width=3D4) (actual time=3D0.544..3.490 rows=3D2 loops=3D1)
               Filter: ((parent =3D 45) AND (pbar =3D 0))
         ->  Materialize  (cost=3D192.62..269.24 rows=3D7662 width=3D0) (ac=
tual time=3D0.009..21.998 rows=3D7662 loops=3D2)
               ->  Seq Scan on timecard  (cost=3D0.00..192.62 rows=3D7662 w=
idth=3D0) (actual time=3D0.007..14.554 rows=3D7662 loops=3D1)
 Total runtime: 109.870 ms
(7 rows)

Query B

fektest=3D> EXPLAIN ANALYSE SELECT distinct moment.mid from moment,timecard=
 where parent =3D 45 and ((pid=3D17 and timecard.mid =3D moment.mid) or (pb=
ar =3D 0)) order by moment.mid;
                                                               QUERY PLAN  =
                                                             =20
---------------------------------------------------------------------------=
--------------------------------------------------------------
 Unique  (cost=3D192.62..102469.31 rows=3D444 width=3D4) (actual time=3D143=
=2E444..4838.067 rows=3D42 loops=3D1)
   ->  Nested Loop  (cost=3D192.62..102405.04 rows=3D25710 width=3D4) (actu=
al time=3D143.439..4818.215 rows=3D15379 loops=3D1)
         Join Filter: ((("inner".pid =3D 17) OR ("outer".pbar =3D 0)) AND (=
("inner".mid =3D "outer".mid) OR ("outer".pbar =3D 0)))
         ->  Index Scan using moment_mid_idx on moment  (cost=3D0.00..154.5=
8 rows=3D444 width=3D8) (actual time=3D0.390..5.954 rows=3D199 loops=3D1)
               Filter: (parent =3D 45)
         ->  Materialize  (cost=3D192.62..269.24 rows=3D7662 width=3D8) (ac=
tual time=3D0.001..9.728 rows=3D7662 loops=3D199)
               ->  Seq Scan on timecard  (cost=3D0.00..192.62 rows=3D7662 w=
idth=3D8) (actual time=3D0.007..17.007 rows=3D7662 loops=3D1)
 Total runtime: 4838.786 ms
(8 rows)

> > I should say that this is on postgresql 7.4.16 (debian stable).
>=20
> Uhh. Why not a recent version? We have 8.3.0...

No particularly good reason, just that I have taken over a production
system and I didn't want to mess up with before I am confident with
it. But I on a test-site I have migrated to 8.1 without problems, so
migration will happen, we just haven't a reason for doing it yet,
since 7.4 has served us well.

> > Can query B be rewritten so that it would execute faster?
>=20
> Quick and dirty: use both selects (query A) combined with UNION.

I will look into that.

> I guess, with a recent version the planner can use a bitmap index scan
> to perform Query B faster.

That might be a good reason to upgrade :-)

Thanks for your answer.

--=20
Every non-free program has a lord, a master --
and if you use the program, he is your master.
Learn to master free software: www.ubuntulinux.com

--Qz2CZ664xQdCRdPu
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: Digital signature
Content-Disposition: inline

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFIDvv9fCyHKnBQYU4RAvI8AJ9On4kjZLzdCqZlKkC0i+XrMPkATgCcDnuJ
Fn6JQY2mqxlgc4d2WhxrqJg=
=HaaT
-----END PGP SIGNATURE-----

--Qz2CZ664xQdCRdPu--