Message-ID: <511F508A.9080004@normation.com>
Date: Sat, 16 Feb 2013 10:25:30 +0100
From: Nicolas Charles <nicolas.charles@normation.com>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:14.0) Gecko/20120713 Thunderbird/14.0
MIME-Version: 1.0
To: Jeff Janes <jeff.janes@gmail.com>
CC: pgsql-performance@postgresql.org
Subject: Re: Surprising no use of indexes - low performance
References: <511D0430.1090603@normation.com>
	<CAMkU=1xkpCOvzO-nsruDnDpZy8J3bCgLr7fAEEWOQYthJ_2y6g@mail.gmail.com>
	<511DF928.8070101@normation.com>
	<CAMkU=1yhw1-yhx8_ugDxJ811UbJ8m9+KNHW9WUnaVy=r4bxzWQ@mail.gmail.com>
In-Reply-To: 
 <CAMkU=1yhw1-yhx8_ugDxJ811UbJ8m9+KNHW9WUnaVy=r4bxzWQ@mail.gmail.com>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: quoted-printable
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Le 15/02/2013 19:04, Jeff Janes a =E9crit :
> On Fri, Feb 15, 2013 at 1:00 AM, Nicolas Charles
> <nicolas.charles@normation.com> wrote:
>> On 14/02/2013 20:27, Jeff Janes wrote:
>>>> I'm surprised that the executiontimestamp index is not used, since it
>>>> seems
>>>> to be where most of the query time is spent.
>>> I do not draw that conclusion from your posted information.  Can you
>>> highlight the parts of it that lead you to this conclusion?
>> The index scan are on nodeid_idx and configurationruleid_idx, not on
>> executiontimestamp
>> Or am I misreading the output ?
> You are correct about the use of nodeid_idx and
> configurationruleid_idx.  But the part about most of the time going
> into filtering out rows that fail to match executiontimestamp is the
> part that I don't think is supported by the explained plan.  The
> information given by the explain plan is not sufficient to decide that
> one way or the other.  Some more recent improvements in "explain
> (analyze, buffers)" would make it easier (especially with
> track_io_timing on) but it would still be hard to draw a definitive
> conclusion.  The most definitive thing would be to do the experiment
> of adding executiontimestamp as a *trailing* column to the end of one
> of the existing indexes and see what happens.
I added this index
"composite_idx" btree (ruleid, serial, executiontimestamp)
and lowered the shared_buffer to 54 MB.

For this specific query, it is indeed a bit better. (23s against 28s)

  Sort  (cost=3D43449.44..43459.07 rows=3D3854 width=3D252) (actual=20
time=3D23375.247..23394.704 rows=3D62403 loops=3D1)
    Sort Key: executiontimestamp
    Sort Method:  external merge  Disk: 17480kB
    ->  Bitmap Heap Scan on ruddersysevents (cost=3D28884.44..43219.89=20
rows=3D3854 width=3D252) (actual time=3D1528.704..23155.991 rows=3D62403 lo=
ops=3D1)
          Recheck Cond: ((ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10) AND=20
(executiontimestamp >=3D to_timestamp('2012-11-22 16:00:16.005'::text,=20
'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND (executiontimestamp <=3D=20
to_timestamp('2013-01-25 18:53:52.467'::text, 'YYYY-MM-DD=20
HH24:MI:SS.MS'::text)) AND (nodeid =3D=20
'31264061-5ecb-4891-9aa4-83824178f43d'::text))
          ->  BitmapAnd  (cost=3D28884.44..28884.44 rows=3D3854 width=3D0)=
=20
(actual time=3D1517.310..1517.310 rows=3D0 loops=3D1)
                ->  Bitmap Index Scan on composite_idx=20
(cost=3D0.00..3062.16 rows=3D59325 width=3D0) (actual time=3D775.418..775.4=
18=20
rows=3D811614 loops=3D1)
                      Index Cond: ((ruleid =3D=20
'61713ff1-aa6f-4c86-b3cb-7012bee707dd'::text) AND (serial =3D 10) AND=20
(executiontimestamp >=3D to_timestamp('2012-11-22 16:00:16.005'::text,=20
'YYYY-MM-DD HH24:MI:SS.MS'::text)) AND (executiontimestamp <=3D=20
to_timestamp('2013-01-25 18:53:52.467'::text, 'YYYY-MM-DD=20
HH24:MI:SS.MS'::text)))
                ->  Bitmap Index Scan on nodeid_idx (cost=3D0.00..25820.11=
=20
rows=3D717428 width=3D0) (actual time=3D714.254..714.254 rows=3D690503 loop=
s=3D1)
                      Index Cond: (nodeid =3D=20
'31264061-5ecb-4891-9aa4-83824178f43d'::text)
  Total runtime: 23419.411 ms
(11 lignes)

But since there were a lot of Sort Method:  external merge, and a lot of=20
object instanciations in our batch, we tried to split the job on 5 days=20
interval, so the average number of line returned is closed to 5000

Load/IO of the system was *significantly* lower during the batch=20
treatment with this index than with the previous attempt (load around .7=20
instead of 1.8)

And batch execution time is now 1h08 rather than 2h20

>>> If the indexes fit in RAM, they fit in RAM.  If anything, increasing
>>> shared_buffers could make it harder to fit them entirely in RAM.  If
>>> your shared buffers undergo a lot of churn, then the OS cache and the
>>> shared buffers tend to uselessly mirror each other, meaning there is
>>> less space for non-redundant pages.
>> Oh !
>> So I completely misunderstood the meaning of shared_buffer; I figured th=
at
>> it was somehow the place where the data would be stored by postgres (like
>> indexes)
> That is correct, it is the space used by postgres to cache data.  But,
> the rest of RAM (beyond shared_buffers) will also be used to cache
> data; but by the OS rather than by postgres.  On a dedicated server,
> the OS will generally choose to (or at least attempt to) use this
> space for the benefit of postgres anyway.  If shared_buffers > RAM/2,
> it won't be very successful at this, but it will still try.  The
> kernel and postgres do not have intimate knowledge of each other, so
> it is hard to arrange that all pages show up in just one place or the
> other but not both.
>


Thank you very much for your explainations !

Nicolas


--=20
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance