Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrCkx-0004AE-Vt for pgsql-performance@arkaria.postgresql.org; Thu, 12 Dec 2013 20:21:12 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1VrCkx-0001WV-AN for pgsql-performance@arkaria.postgresql.org; Thu, 12 Dec 2013 20:21:11 +0000 Received: from makus.postgresql.org ([2001:4800:7903:4::125]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrCkw-0001WO-2s for pgsql-performance@postgresql.org; Thu, 12 Dec 2013 20:21:10 +0000 Received: from mail.brycecovertoperations.com ([198.199.108.214]) by makus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrCks-0007OS-38 for pgsql-performance@postgresql.org; Thu, 12 Dec 2013 20:21:09 +0000 Received: from localhost (localhost [127.0.0.1]) by mail.brycecovertoperations.com (Postfix) with ESMTP id 374F11078A6 for ; Thu, 12 Dec 2013 20:19:31 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d= brycecovertoperations.com; h=content-type:content-type :in-reply-to:references:subject:subject:to:mime-version :user-agent:from:from:date:date:message-id; s=dkim; t= 1386879569; x=1387743569; bh=qi48A+6Orn6xhZEZtm16h4Ply40wj0E3Uu3 gtpx2Qm0=; b=x/J4qEjGhOKuqnIpJB/ku202DcTDvffZkE518DN3Y4vN0qNWgr0 LVoKmrKsP9331JYgzrWe48B/h/60KSi2ANshPAk/iaaQ1fbnkilYDr7PM7Z86jUq 8HCc/80DU8XW0p9w0gsDB1tXLxvYornOEdVBcyBaSXkktgmf5b6Vh3u0= X-Virus-Scanned: Debian amavisd-new at mail.brycecovertoperations.com Received: from mail.brycecovertoperations.com ([127.0.0.1]) by localhost (mail.brycecovertoperations.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id GM4FZmNca12g for ; Thu, 12 Dec 2013 20:19:29 +0000 (UTC) Received: from hulkbrogan-2.local (unknown [199.231.240.50]) by mail.brycecovertoperations.com (Postfix) with ESMTPSA id 4697B107893; Thu, 12 Dec 2013 20:19:26 +0000 (UTC) Message-ID: <52AA1AAA.1030901@brycecovertoperations.com> Date: Thu, 12 Dec 2013 12:20:58 -0800 From: Bryce Covert User-Agent: Postbox 3.0.8 (Macintosh/20130427) MIME-Version: 1.0 To: Claudio Freire CC: postgres performance list Subject: Re: Slow query due to slow I/O References: <52AA1836.6020208@brycecovertoperations.com> In-Reply-To: Content-Type: multipart/alternative; boundary="------------030903030801020808080600" X-Pg-Spam-Score: -2.0 (--) 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 This is a multi-part message in MIME format. --------------030903030801020808080600 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit I don't have much info on disks, since this is a virtual server on linode. It is running ubuntu 12.04, 8cpus, 4GB ram, 95GB ext3 volume (noatime). Hopefully that's helpful. Bryce > Claudio Freire > December 12, 2013 12:15 PM > On Thu, Dec 12, 2013 at 5:10 PM, Bryce Covert > > > For this kind of diagnostic, you need to include hardware details. > > OS? Disks? RAID? > Bryce Covert > December 12, 2013 12:10 PM > > Hi, > > I'm seeing a slow running query. After some optimization with indexes, > it appears that the query plan is correct, it's just slow. Running the > query twice, not surprisingly, is very fast, due to OS caching or > shared_buffers caching. If the parameters for the query are different, > however, the query is slow until run a second time. In our usage > pattern, this query must run fast the first time it runs. > > A couple of general stats: this is a linode machine with a single 3GB > DB with 4GBs of ram. Shared buffers = 1024mb, > effective_cache_size=2048MB. We are running with postgres 9.1. The > machine is otherwise dormant when this query runs. Here is the schema: > > Table "public.premiseaccount" > Column | Type > | Modifiers > ------------------------+--------------------------+------------------------------------------------------------------------- > > id | integer | not null default > nextval('premiseaccount_id_seq'::regclass) > created | timestamp with time zone | not null default > '2013-09-25 07:00:00+00'::timestamp with time zone > modified | timestamp with time zone | not null default > '2013-09-25 07:00:00+00'::timestamp with time zone > account_id | integer | not null > premise_id | integer | not null > bucket | character varying(255) | > Indexes: > "premiseaccount_pkey" PRIMARY KEY, btree (id) > "premiseaccount_account_id" btree (account_id) > "premiseaccount_bucket" btree (bucket) > "premiseaccount_bucket_58c70392619aa36f" btree (bucket, id) > "premiseaccount_bucket_like" btree (bucket varchar_pattern_ops) > "premiseaccount_premise_id" btree (premise_id) > Foreign-key constraints: > "account_id_refs_id_529631edfff28022" FOREIGN KEY (account_id) > REFERENCES utilityaccount(id) DEFERRABLE INITIALLY DEFERRED > "premise_id_refs_id_5ecea2842007328b" FOREIGN KEY (premise_id) > REFERENCES premise(id) DEFERRABLE INITIALLY DEFERRED > > Table "public.electricusage" > Column | Type > | Modifiers > --------------------+--------------------------+------------------------------------------------------------------------ > > id | integer | not null default > nextval('electricusage_id_seq'::regclass) > created | timestamp with time zone | not null default > '2013-09-25 07:00:00+00'::timestamp with time zone > modified | timestamp with time zone | not null default > '2013-09-25 07:00:00+00'::timestamp with time zone > from_date | timestamp with time zone | not null > to_date | timestamp with time zone | not null > usage | numeric(9,2) | > demand | numeric(9,2) | > bill_amount | numeric(9,2) | > premise_account_id | integer | not null > Indexes: > "electricusage_pkey" PRIMARY KEY, btree (id) > "electricusage_premise_account_id" btree (premise_account_id) > "electricusage_covered_id_from_date_usage" btree > (premise_account_id, from_date, usage) > Foreign-key constraints: > "premise_account_id_refs_id_4c39e54406369128" FOREIGN KEY > (premise_account_id) REFERENCES premiseaccount(id) DEFERRABLE > INITIALLY DEFERRED > > > For reference, premiseaccount has about 1 million rows, one for each > account, grouped in buckets with an average of 5000 accounts per > bucket. electricusage has 10 million rows, about 10 rows per > premiseaccount. > > Here is the query: > > explain analyze > SELECT premiseaccount.id, SUM(electricusage.usage) AS total_kwh > FROM premiseaccount > LEFT OUTER JOIN electricusage > ON premiseaccount.id = electricusage.premise_account_id > WHERE premiseaccount.bucket = 'XXX' AND electricusage.from_date >= > '2012-11-20 00:00:00' > GROUP BY premiseaccount.id > HAVING SUM(electricusage.usage) BETWEEN 3284 and 3769 > LIMIT 50; > > > Limit (cost=0.00..1987.24 rows=50 width=8) (actual > time=931.524..203631.435 rows=50 loops=1) > -> GroupAggregate (cost=0.00..179487.78 rows=4516 width=8) > (actual time=931.519..203631.275 rows=50 loops=1) > Filter: ((sum(electricusage.usage) >= 3284::numeric) AND > (sum(electricusage.usage) <= 3769::numeric)) > -> Nested Loop (cost=0.00..179056.87 rows=36317 width=8) > (actual time=101.934..203450.761 rows=30711 loops=1) > -> Index Scan using > premiseaccount_bucket_58c70392619aa36f on premiseaccount > premiseaccount (cost=0.00..14882.30 rows=4516 width=4) (actual > time=77.620..7199.527 rows=3437 loops=1) > Index Cond: ((bucket)::text = 'XXX'::text) > -> Index Scan using > electricusage_premise_account_id_36bc8999ced10059 on electricusage > electricusage (cost=0.00..36.24 rows=9 width=8) (actual > time=8.607..57.055 rows=9 loops=3437) > Index Cond: ((premise_account_id = > premiseaccount.id) AND (from_date >= '2012-11-20 > 00:00:00+00'::timestamp with time zone)) > Total runtime: 203631.666 ms > > (see online at: http://explain.depesz.com/s/zeC) > > What am I missing here? It seems like this is a relatively > straightforward foreign key join, using the correct indexes, that is > just slow. Warming the OS cache seems like the only way to make this > actually perform reasonably, but it seems like it's masking the > underlying problem. I could probably do some denormalization, like > putting the bucket field on the electricusage table, but that seems > like a shoddy solution. > > Before running my query, I clear the os and postgres cache. I know > that in theory some subset of the data will be in the os cache and > postgres cache. But in the real world, what we see is that a number of > people get timeouts waiting for this query to finish, because it's not > in the cache. e.g., running the query with where bucket='xxx' will be > fast a second time, but where bucket='yyy' will not. > > > Here are things I've tried: > + Clustering premiseaccount on premiseaccount_bucket_58c70392619aa36f > and electricusage on electricusage_covered_id_from_date_usage. This > provided modest improvement > + Fit the whole DB in memory. Since this query is fast if the data is > cached, try to fit everything into the cache. Bumping the ram to 8GBs, > and warming up the os cache by taring the postgres data directory. On > the 4GB machine, I still run into slow performance, but at 8GBs, the > entire DB can fit in the OS cache. This made a huge improvement, but > will only work for a little while as the database grows. > + Tried on other linode servers - same results. > + Removing the from_date part of the query. It uses a different index > but same performance characteristics. > + Looked at kern, sys, and postgres logs. Nothing interesting. > > > I would really appreciate any help I could get! Thanks! > > Bryce > > --------------030903030801020808080600 Content-Type: multipart/related; boundary="------------030907090101020008080708" --------------030907090101020008080708 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit
I don't have much info on disks, since this is a virtual server on linode. It is running ubuntu 12.04, 8cpus, 4GB ram, 95GB ext3 volume (noatime). Hopefully that's helpful.

Bryce
December 12, 2013 12:15 PM
On Thu, Dec 12, 2013 at 5:10 PM, Bryce Covert


For this kind of diagnostic, you need to include hardware details.

OS? Disks? RAID?
December 12, 2013 12:10 PM

Hi,

I'm seeing a slow running query. After some optimization with indexes, it appears that the query plan is correct, it's just slow. Running the query twice, not surprisingly, is very fast, due to OS caching or shared_buffers caching. If the parameters for the query are different, however, the query is slow until run a second time. In our usage pattern, this query must run fast the first time it runs.

A couple of general stats: this is a linode machine with a single 3GB DB with 4GBs of ram. Shared buffers = 1024mb, effective_cache_size=2048MB. We are running with postgres 9.1. The machine is otherwise dormant when this query runs. Here is the schema:

                                          Table "public.premiseaccount"
         Column         |           Type           |                                Modifiers
------------------------+--------------------------+-------------------------------------------------------------------------
 id                     | integer                  | not null default nextval('premiseaccount_id_seq'::regclass)
 created                | timestamp with time zone | not null default '2013-09-25 07:00:00+00'::timestamp with time zone
 modified               | timestamp with time zone | not null default '2013-09-25 07:00:00+00'::timestamp with time zone
 account_id             | integer                  | not null
 premise_id             | integer                  | not null
 bucket                 | character varying(255)   |
Indexes:
    "premiseaccount_pkey" PRIMARY KEY, btree (id)
    "premiseaccount_account_id" btree (account_id)
    "premiseaccount_bucket" btree (bucket)
    "premiseaccount_bucket_58c70392619aa36f" btree (bucket, id)
    "premiseaccount_bucket_like" btree (bucket varchar_pattern_ops)
    "premiseaccount_premise_id" btree (premise_id)
Foreign-key constraints:
    "account_id_refs_id_529631edfff28022" FOREIGN KEY (account_id) REFERENCES utilityaccount(id) DEFERRABLE INITIALLY DEFERRED
    "premise_id_refs_id_5ecea2842007328b" FOREIGN KEY (premise_id) REFERENCES premise(id) DEFERRABLE INITIALLY DEFERRED

                                        Table "public.electricusage"
       Column       |           Type           |                               Modifiers
--------------------+--------------------------+------------------------------------------------------------------------
 id                 | integer                  | not null default nextval('electricusage_id_seq'::regclass)
 created            | timestamp with time zone | not null default '2013-09-25 07:00:00+00'::timestamp with time zone
 modified           | timestamp with time zone | not null default '2013-09-25 07:00:00+00'::timestamp with time zone
 from_date          | timestamp with time zone | not null
 to_date            | timestamp with time zone | not null
 usage              | numeric(9,2)             |
 demand             | numeric(9,2)             |
 bill_amount        | numeric(9,2)             |
 premise_account_id | integer                  | not null
Indexes:
    "electricusage_pkey" PRIMARY KEY, btree (id)
    "electricusage_premise_account_id" btree (premise_account_id)
    "electricusage_covered_id_from_date_usage" btree (premise_account_id, from_date, usage)
Foreign-key constraints:
    "premise_account_id_refs_id_4c39e54406369128" FOREIGN KEY (premise_account_id) REFERENCES premiseaccount(id) DEFERRABLE INITIALLY DEFERRED


For reference, premiseaccount has about 1 million rows, one for each account, grouped in buckets with an average of 5000 accounts per bucket. electricusage has 10 million rows, about 10 rows per premiseaccount.

Here is the query:

explain analyze
SELECT premiseaccount.id, SUM(electricusage.usage) AS total_kwh
FROM premiseaccount
LEFT OUTER JOIN electricusage
    ON premiseaccount.id = electricusage.premise_account_id
WHERE premiseaccount.bucket = 'XXX'  AND electricusage.from_date >= '2012-11-20 00:00:00'
GROUP BY premiseaccount.id
HAVING SUM(electricusage.usage) BETWEEN 3284 and 3769
LIMIT 50;


 Limit  (cost=0.00..1987.24 rows=50 width=8) (actual time=931.524..203631.435 rows=50 loops=1)
   ->  GroupAggregate  (cost=0.00..179487.78 rows=4516 width=8) (actual time=931.519..203631.275 rows=50 loops=1)
         Filter: ((sum(electricusage.usage) >= 3284::numeric) AND (sum(electricusage.usage) <= 3769::numeric))
         ->  Nested Loop  (cost=0.00..179056.87 rows=36317 width=8) (actual time=101.934..203450.761 rows=30711 loops=1)
               ->  Index Scan using premiseaccount_bucket_58c70392619aa36f on premiseaccount premiseaccount  (cost=0.00..14882.30 rows=4516 width=4) (actual time=77.620..7199.527 rows=3437 loops=1)
                     Index Cond: ((bucket)::text = 'XXX'::text)
               ->  Index Scan using electricusage_premise_account_id_36bc8999ced10059 on electricusage electricusage  (cost=0.00..36.24 rows=9 width=8) (actual time=8.607..57.055 rows=9 loops=3437)
                     Index Cond: ((premise_account_id = premiseaccount.id) AND (from_date >= '2012-11-20 00:00:00+00'::timestamp with time zone))
 Total runtime: 203631.666 ms

 (see online at: http://explain.depesz.com/s/zeC)

What am I missing here? It seems like this is a relatively straightforward foreign key join, using the correct indexes, that is just slow. Warming the OS cache seems like the only way to make this actually perform reasonably, but it seems like it's masking the underlying problem. I could probably do some denormalization, like putting the bucket field on the electricusage table, but that seems like a shoddy solution.

Before running my query, I clear the os and postgres cache. I know that in theory some subset of the data will be in the os cache and postgres cache. But in the real world, what we see is that a number of people get timeouts waiting for this query to finish, because it's not in the cache. e.g., running the query with where bucket='xxx' will be fast a second time, but where bucket='yyy' will not.


Here are things I've tried:
+ Clustering premiseaccount on premiseaccount_bucket_58c70392619aa36f and electricusage on electricusage_covered_id_from_date_usage. This provided modest improvement
+ Fit the whole DB in memory. Since this query is fast if the data is cached, try to fit everything into the cache. Bumping the ram to 8GBs, and warming up the os cache by taring the postgres data directory. On the 4GB machine, I still run into slow performance, but at 8GBs, the entire DB can fit in the OS cache.  This made a huge improvement, but will only work for a little while as the database grows.
+ Tried on other linode servers - same results.
+ Removing the from_date part of the query. It uses a different index but same performance characteristics.
+ Looked at kern, sys, and postgres logs. Nothing interesting.


I would really appreciate any help I could get! Thanks!

Bryce

 
--------------030907090101020008080708 Content-Type: image/jpeg; x-apple-mail-type=stationery; name="postbox-contact.jpg" Content-Transfer-Encoding: base64 Content-ID: Content-Disposition: inline; filename="postbox-contact.jpg" /9j/4AAQSkZJRgABAQAAAQABAAD/2wBDAAMCAgICAgMCAgIDAwMDBAYEBAQEBAgGBgUGCQgK CgkICQkKDA8MCgsOCwkJDRENDg8QEBEQCgwSExIQEw8QEBD/2wBDAQMDAwQDBAgEBAgQCwkL EBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBD/wAAR CAAZABkDAREAAhEBAxEB/8QAHwAAAQUBAQEBAQEAAAAAAAAAAAECAwQFBgcICQoL/8QAtRAA AgEDAwIEAwUFBAQAAAF9AQIDAAQRBRIhMUEGE1FhByJxFDKBkaEII0KxwRVS0fAkM2JyggkK FhcYGRolJicoKSo0NTY3ODk6Q0RFRkdISUpTVFVWV1hZWmNkZWZnaGlqc3R1dnd4eXqDhIWG h4iJipKTlJWWl5iZmqKjpKWmp6ipqrKztLW2t7i5usLDxMXGx8jJytLT1NXW19jZ2uHi4+Tl 5ufo6erx8vP09fb3+Pn6/8QAHwEAAwEBAQEBAQEBAQAAAAAAAAECAwQFBgcICQoL/8QAtREA AgECBAQDBAcFBAQAAQJ3AAECAxEEBSExBhJBUQdhcRMiMoEIFEKRobHBCSMzUvAVYnLRChYk NOEl8RcYGRomJygpKjU2Nzg5OkNERUZHSElKU1RVVldYWVpjZGVmZ2hpanN0dXZ3eHl6goOE hYaHiImKkpOUlZaXmJmaoqOkpaanqKmqsrO0tba3uLm6wsPExcbHyMnK0tPU1dbX2Nna4uPk 5ebn6Onq8vP09fb3+Pn6/9oADAMBAAIRAxEAPwD5++JurXmn+Mk1rx3qlrPPrdnZSSPq+n2r TywzbXeZC2ZC2WfG4AKRtAUAY0TTV0Cjbc8kv/FHizxTI1mf+JzeSy7bGBtGtpjLbKGyf9WS WGOB6A0WjFaaGjTlofRn7FCp4x8I+KfB/iHw7pcd7pWoW2q6dI+nxWjlmBRkWWNAY2GwFWAy Ceo6jzcdiHhZwmtnozswmE+tQmusdR//AA2B8eP7njH/AMGFv/8AGa29o/519xy/V5djyLw9 ovjrxv4G1X4yeIJPN0fw+unac1xdFXeSaWNAsa7ucZyTjgZro9rCE1S6vb5GkYSnF1Hsj7D+ Afweh8d+F7T4m/BR47DxNqENvY299cW8NwulvbM32h7ZWPyeaj4Pf5ufSvBx2YeyqywtaHMt 9Oqex6lLDw9nHERny9NT2a/+Avgv4DfDOXUJNWMnie+vopLq6uCvm3j5O5TtAAwCzADA615l PG1cxqfvFbl2j29TqwzhSk40ldNO7fVn54f8J7on/QQg/wC+xXvexkcHtodz1n9qHT9L+EH7 GHhrwB/Z72uoX+pWd3cyQMzCWaG3ZH3buUKlsEHowxTw/PWxk6r2SsjmnOMcOoLe5lfs7ftT H9m/wVZeHNC8D6tqd1bhLy/kWfKXEtwm5zEAMFY1VB+J571zY/LXjqjm58vTzVv8zqo4qFGl 7OUb9T2D4g6n8f8A9rfwNqPjLwhYWmlaboMTtZW97fxRPqMu0mbYqk+U6KAAJMbucGpwOFw2 Ak6d7zer/QK2IlOF4K0eh+eH/DPv7QH/AERrx1/4I7n/AOIr3eZHin1x/wAFRf8AkY/EH/Ya i/8ARArGl8UjR/AfKml/8ew/65L/AOg1rLcpbHvP7FH/ACPMv/Yd0z/0Ja5cR8URr4WftxWx gf/Z --------------030907090101020008080708 Content-Type: image/jpeg; x-apple-mail-type=stationery; name="compose-unknown-contact.jpg" Content-Transfer-Encoding: base64 Content-ID: Content-Disposition: inline; filename="compose-unknown-contact.jpg" /9j/4AAQSkZJRgABAQEARwBHAAD/2wBDAAEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEBAQEC AQEBAQEBAgICAgICAgICAgICAgICAgICAgICAgICAgICAgL/2wBDAQEBAQEBAQICAgICAgIC AgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgL/wAAR CAAZABkDAREAAhEBAxEB/8QAGAAAAwEBAAAAAAAAAAAAAAAABgcICQr/xAA0EAABAwMCAgUK BwAAAAAAAAACAQMEBQYRABITIQcUMUF2CBUXIjI2N0JRtVRWkZOV0dL/xAAYAQEAAwEAAAAA AAAAAAAAAAADAAEEAv/EACQRAAICAAQGAwAAAAAAAAAAAAABAhEDMrHREyExM0FxgfDx/9oA DAMBAAIRAxEAPwDuEt+gW/ULet6oVC3rfqNQqFv0OfPn1GhUqfOmzZtKZlS5UqZMaNwzNwiJ VIl7eXLCaZIGwBl3TY8epPx2+jy2ZNPjvkwc9uhW8j7nCPhvOsQliYIeS7cvCpp8o50qwrC4 v3lsNSDbdmTEhvs2tahxpfV3WnmbbozJEw/gwdadbYExVRXKEKoSdvJcaOSqxE7/AAiX0gXx +a69/JSf9alIlste0VzaNpeFrcT9KKymotyiaZ0KRCnzacoE7Kjzn4gi2KqUh3jqDHDHv4mR UfruTWlMzlVUKIVNp9GguEJnAh0+IZjyAiisgyRDnu5azS8miKqjOTVkKqS/psG37fo1Fbab eg25b8eZPeFJBBJSjMG5HjMeyihnaauZwe4OGiju13GAcpOwBeN+U8/IkGbsiS8b7ryogmbz hbyc9REROfZhERO5ETShjPtvpGqTUyLErytS4siSwx5x2tRH4hPOI0DkjZtaJtFxuVEbIUUi yeNujlBUJGbJN6nM/Cyf2Hf60YgjvKA+NPSP4gT7axpcPtr51YWJnYn9dnAQWl722p4ot37y zqnlfp6FrqbwawG8/9k= --------------030907090101020008080708-- --------------030903030801020808080600--