Received: from makus.postgresql.org (makus.postgresql.org [98.129.198.125]) by mail.postgresql.org (Postfix) with ESMTP id 67B9111DF228 for ; Thu, 31 May 2012 20:01:44 -0300 (ADT) Received: from na3sys009aog135.obsmtp.com ([74.125.149.84]) by makus.postgresql.org with smtp (Exim 4.72) (envelope-from ) id 1SaENC-0008Nf-C0 for pgsql-performance@postgresql.org; Thu, 31 May 2012 23:01:44 +0000 Received: from mail-pb0-f52.google.com ([209.85.160.52]) (using TLSv1) by na3sys009aob135.postini.com ([74.125.148.12]) with SMTP ID DSNKT8f4SZj3346mNxUBrmOp6be6xEPy9Vvd@postini.com; Thu, 31 May 2012 16:01:42 PDT Received: by pbbro8 with SMTP id ro8so2350197pbb.11 for ; Thu, 31 May 2012 16:01:28 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=message-id:date:from:user-agent:mime-version:cc:subject:references :in-reply-to:content-type:x-gm-message-state; bh=WZgEGNtDP2jvAwGJBSnyze+OpNzhOyMhgpxQAW1a0Nw=; b=lidqc384eegSuojStZ1StV3e0ixfuu4VkVQrI9G7vsD7OwV2veAiMNNU4gIv1KF9GR jKemYXKUZf+vEFwwZvYHO4SnJ9nvWbT+6fPIbIEY+URPctDg00DJ7fY8i4g0nKrwFTab 7KWGYA5XEfQjqIDQgswQgHVrGbxTlSd+TO7YXeSY9FSqU8A7V/mM6gvRLkm2KT5qjmek AAW/HUWDqhisoffDCnRX7H7Dhom5i0QWQaJVfGw2LjxwAxKZW1iq0ZpTLbqDPmoURLT5 4oicJzik/rEextjmaXKtSfsrHIU2V2H/V4hTYt63zLAefmskEs4AXdclw7/kFwaWvnNf li7g== Received: by 10.68.241.228 with SMTP id wl4mr5149257pbc.51.1338505288739; Thu, 31 May 2012 16:01:28 -0700 (PDT) Received: from [172.20.9.121] (eth59-167-133-99.static.internode.on.net. [59.167.133.99]) by mx.google.com with ESMTPS id rx8sm515087pbc.60.2012.05.31.16.01.26 (version=TLSv1/SSLv3 cipher=OTHER); Thu, 31 May 2012 16:01:27 -0700 (PDT) Message-ID: <4FC7F844.8070205@atlassian.com> Date: Fri, 01 Jun 2012 09:01:24 +1000 From: Trevor Campbell User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:12.0) Gecko/20120430 Thunderbird/12.0.1 MIME-Version: 1.0 CC: pgsql-performance@postgresql.org Subject: Re: Trouble with plan statistics for behaviour for query. References: <4FC7F0DB.40600@atlassian.com> In-Reply-To: Content-Type: multipart/alternative; boundary="------------020008010002060103050300" X-Gm-Message-State: ALoCoQmNjqNdE+OD6aV+3JtZqgtLg+qDqTeVMu5WovAgEYZiEij4ck/7EQPYWzpB1+OWiouJnv2K X-Pg-Spam-Score: -2.2 (--) X-Archive-Number: 201205/199 X-Sequence-Number: 47023 This is a multi-part message in MIME format. --------------020008010002060103050300 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit On 01/06/12 08:55, Craig James wrote: > > > On Thu, May 31, 2012 at 3:29 PM, Trevor Campbell > wrote: > > We are having trouble with a particular query being slow in a strange manner. > > The query is a join over two large tables that are suitably indexed. > > select CG.ID , CG.ISSUEID, CG.AUTHOR, CG.CREATED, CI.ID , CI.FIELDTYPE, CI.FIELD, > CI.OLDVALUE, CI.OLDSTRING, CI.NEWVALUE, CI.NEWSTRING > from PUBLIC.CHANGEGROUP CG inner join PUBLIC.CHANGEITEM CI on CG.ID = CI.GROUPID where > CG.ISSUEID=? order by CG.CREATED asc, CI.ID asc > > > This has an unbound variable '?' in it. These queries are being run from a java application using JDBC and when run the variable is bound to an long integer value. While trying to investigate the problem, I have been just hard coding a value in the statement. > > > For some tasks we run this particular query a very large number of times and it has a significant performance > impact when it runs slowly. > > If we run ANALYSE over the CHANGEITEM table then the performance picks up by a factor of 5 or more. The problem > is that a day later the performance will have dropped back to its previously slow state. > > The reason this is so hard to understand is that the activity on this table is very low, with no updates and only > a relatively small number of inserts each day, < 0.1% of the table size. > > Explain output: > Sort (cost=86.90..86.93 rows=11 width=118) (actual time=0.086..0.087 rows=14 loops=1) > Sort Key: cg.created, ci.id > Sort Method: quicksort Memory: 26kB > -> Nested Loop (cost=0.00..86.71 rows=11 width=118) (actual time=0.022..0.061 rows=14 loops=1) > -> Index Scan using chggroup_issue on changegroup cg (cost=0.00..17.91 rows=8 width=33) (actual > time=0.012..0.015 rows=7 loops=1) > Index Cond: (issueid = 81001::numeric) > -> Index Scan using chgitem_chggrp on changeitem ci (cost=0.00..8.58 rows=2 width=91) (actual > time=0.005..0.005 rows=2 loops=7) > Index Cond: (groupid = cg.id ) > Total runtime: 0.116 ms > > > What's the exact SQL you used to get this ... did you use a specific CG.ISSUEID to run your test? If that's the case, > this EXPLAIN ANALYZE won't be the same as the one generated for your actual application. > > Craig > > > The explain output always seems the same even when the performance is poor, but I can't be sure of that. > > Overall it seems like PostgreSQL just forgets about the statistics it has gathered after a short while. > > Schema details: > CREATE TABLE changegroup > ( > id numeric(18,0) NOT NULL, > issueid numeric(18,0), > author character varying(255), > created timestamp with time zone, > CONSTRAINT pk_changegroup PRIMARY KEY (id ) > ) > WITH ( > OIDS=FALSE > ); > CREATE INDEX chggroup_issue > ON changegroup > USING btree > (issueid ); > > CREATE TABLE changeitem > ( > id numeric(18,0) NOT NULL, > groupid numeric(18,0), > fieldtype character varying(255), > field character varying(255), > oldvalue text, > oldstring text, > newvalue text, > newstring text, > CONSTRAINT pk_changeitem PRIMARY KEY (id ) > ) > WITH ( > OIDS=FALSE > ); > > CREATE INDEX chgitem_chggrp > ON changeitem > USING btree > (groupid ); > > CREATE INDEX chgitem_field > ON changeitem > USING btree > (field COLLATE pg_catalog."default" ); > > Table sizes > changegroup : 2,000,000 rows > changeitem : 2,500,000 rows > > The changegroup table has on average about 4 rows per issueid value, which is the query parameter. > > We run autovacuum and autoanalyse, but as the activity in the table is low these are rarely if ever invoked on > these tables. > > Environment. > Testing using PostgreSQL 9.1.3 on x86_64-redhat-linux-gnu, although this is a problem across a variety of > postgres versions. > > --------------020008010002060103050300 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit On 01/06/12 08:55, Craig James wrote:


On Thu, May 31, 2012 at 3:29 PM, Trevor Campbell <tcampbell@atlassian.com> wrote:
We are having trouble with a particular query being slow in a strange manner.

The query is a join over two large tables that are suitably indexed.

select CG.ID, CG.ISSUEID, CG.AUTHOR, CG.CREATED, CI.ID, CI.FIELDTYPE, CI.FIELD, CI.OLDVALUE, CI.OLDSTRING, CI.NEWVALUE, CI.NEWSTRING
   from PUBLIC.CHANGEGROUP CG inner join PUBLIC.CHANGEITEM CI on CG.ID = CI.GROUPID where CG.ISSUEID=? order by CG.CREATED asc, CI.ID asc

This has an unbound variable '?' in it.
These queries are being run from a java application using JDBC and when run the variable is bound to an long integer value.  While trying to investigate the problem, I have been just hard coding a value in the statement.


For some tasks we run this particular query a very large number of times and it has a significant performance impact when it runs slowly.

If we run ANALYSE over the CHANGEITEM table then the performance picks up by a factor of 5 or more.  The problem is that a day later the performance will have dropped back to its previously slow state.

The reason this is so hard to understand is that the activity on this table is very low, with no updates and only a relatively small number of inserts each day, < 0.1% of the table size.

Explain output:
Sort  (cost=86.90..86.93 rows=11 width=118) (actual time=0.086..0.087 rows=14 loops=1)
  Sort Key: cg.created, ci.id
  Sort Method: quicksort  Memory: 26kB
  ->  Nested Loop  (cost=0.00..86.71 rows=11 width=118) (actual time=0.022..0.061 rows=14 loops=1)
        ->  Index Scan using chggroup_issue on changegroup cg  (cost=0.00..17.91 rows=8 width=33) (actual time=0.012..0.015 rows=7 loops=1)
              Index Cond: (issueid = 81001::numeric)
        ->  Index Scan using chgitem_chggrp on changeitem ci  (cost=0.00..8.58 rows=2 width=91) (actual time=0.005..0.005 rows=2 loops=7)
              Index Cond: (groupid = cg.id)
Total runtime: 0.116 ms

What's the exact SQL you used to get this ... did you use a specific CG.ISSUEID to run your test?  If that's the case, this EXPLAIN ANALYZE won't be the same as the one generated for your actual application.

Craig

 

The explain output always seems the same even when the performance is poor, but I can't be sure of that.

Overall it seems like PostgreSQL just forgets about the statistics it has gathered after a short while.

Schema details:
CREATE TABLE changegroup
(
  id numeric(18,0) NOT NULL,
  issueid numeric(18,0),
  author character varying(255),
  created timestamp with time zone,
  CONSTRAINT pk_changegroup PRIMARY KEY (id )
)
WITH (
  OIDS=FALSE
);
CREATE INDEX chggroup_issue
  ON changegroup
  USING btree
  (issueid );

CREATE TABLE changeitem
(
  id numeric(18,0) NOT NULL,
  groupid numeric(18,0),
  fieldtype character varying(255),
  field character varying(255),
  oldvalue text,
  oldstring text,
  newvalue text,
  newstring text,
  CONSTRAINT pk_changeitem PRIMARY KEY (id )
)
WITH (
  OIDS=FALSE
);

CREATE INDEX chgitem_chggrp
  ON changeitem
  USING btree
  (groupid );

CREATE INDEX chgitem_field
  ON changeitem
  USING btree
  (field COLLATE pg_catalog."default" );

Table sizes
changegroup  :  2,000,000 rows
changeitem    :  2,500,000  rows

The changegroup table has on average about 4 rows per issueid value, which is the query parameter.

We run autovacuum and autoanalyse, but as the activity in the table is low these are rarely if ever invoked on these tables.

Environment.
Testing using PostgreSQL 9.1.3 on x86_64-redhat-linux-gnu,  although this is a problem across a variety of postgres versions.


--------------020008010002060103050300--