Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrGE9-0003dd-8A for pgsql-performance@arkaria.postgresql.org; Fri, 13 Dec 2013 00:03:33 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1VrGE8-00056E-KT for pgsql-performance@arkaria.postgresql.org; Fri, 13 Dec 2013 00:03:32 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrGE6-000541-10 for pgsql-performance@postgresql.org; Fri, 13 Dec 2013 00:03:30 +0000 Received: from mail.brycecovertoperations.com ([198.199.108.214]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VrGDw-0006JA-QC for pgsql-performance@postgresql.org; Fri, 13 Dec 2013 00:03:29 +0000 Received: from localhost (localhost [127.0.0.1]) by mail.brycecovertoperations.com (Postfix) with ESMTP id BBE361078CD for ; Fri, 13 Dec 2013 00:01:44 +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= 1386892904; x=1387756904; bh=fY+cwm/HVkjoE/sw+lQOEsoY+p6JhWXC/Zs 9li9FMjQ=; b=orOc46LCbqzVRr/SrAay82FlM4R8N6W39mxzBa0fa4Q7yo7A51z CCcnCNxFvwhygMDQs7Y+OFLC/fe565SOb9zPo1uKLWQcN+SXPg3IypBumKcpOuOo GcP9smerpm5aAZALeyC4/dPPjHaI/Qgy4wpUfBHLlgmvRqs14Z2pxqgo= 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 Ks5HidfHVyTu for ; Fri, 13 Dec 2013 00:01:44 +0000 (UTC) Received: from hulkbrogan-2.local (unknown [199.231.240.50]) by mail.brycecovertoperations.com (Postfix) with ESMTPSA id C35DE1078C7; Fri, 13 Dec 2013 00:01:36 +0000 (UTC) Message-ID: <52AA4EBD.1040800@brycecovertoperations.com> Date: Thu, 12 Dec 2013 16:03:09 -0800 From: Bryce Covert User-Agent: Postbox 3.0.8 (Macintosh/20130427) MIME-Version: 1.0 To: Jeff Janes CC: Claudio Freire , postgres performance list Subject: Re: Slow query due to slow I/O References: <52AA1836.6020208@brycecovertoperations.com> <52AA1AAA.1030901@brycecovertoperations.com> <52AA27AA.5040307@brycecovertoperations.com> <52AA40ED.50208@brycecovertoperations.com> In-Reply-To: Content-Type: multipart/alternative; boundary="------------010107080309090301070402" 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. --------------010107080309090301070402 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit It looks like you guys were right. I think vacuum analyzing this made it do an IOS. It seems like materialized views are going to be the best bet. I see how that would allow sequential reading. Thanks! Bryce > Jeff Janes > December 12, 2013 4:01 PM > On Thu, Dec 12, 2013 at 3:04 PM, Bryce Covert > > wrote: > > Not sure if this is helpful, but I tried upgrading to 9.2, and > here's what I got: > > --------- > Limit (cost=0.00..535.78 rows=50 width=8) (actual > time=1037.376..135043.945 rows=50 loops=1) > Output: premiseaccount.id , > (sum(electricusage.usage)) > Buffers: shared hit=4851 read=18718 > -> GroupAggregate (cost=0.00..198012.28 rows=18479 width=8) > (actual time=1037.369..135043.700 rows=50 loops=1) > Output: premiseaccount.id , > sum(electricusage.usage) > > Filter: ((sum(electricusage.usage) >= 3284::numeric) AND > (sum(electricusage.usage) <= 3769::numeric)) > Rows Removed by Filter: 1476 > Buffers: shared hit=4851 read=18718 > -> Nested Loop (cost=0.00..196247.46 rows=148764 > width=8) (actual time=107.092..134845.231 rows=15188 loops=1) > Output: premiseaccount.id > , electricusage.usage > Buffers: shared hit=4851 read=18718 > -> Index Only Scan using > premiseaccount_bucket_58c70392619aa36f on public.premiseaccount > premiseaccount (cost=0.00..43135.13 rows=18479 width=4) (actual > time=45.368..137.340 rows=1527 loops=1) > Output: premiseaccount.bucket, > premiseaccount.id > Index Cond: (premiseaccount.bucket = > '85375_single-family'::text) > Heap Fetches: 1527 > > You had to hit the heap for every row, meaning the index-only feature > was useless. Are you vacuuming enough? How fast does this table > change? What is relallvisible from pg_class for these tables? > > -> Index Scan using > electricusage_premise_account_id on public.electricusage > electricusage (cost=0.00..8.20 rows=9 width=8) (actual > time=22.306..88.136 rows=10 loops=1527) > Output: electricusage.id > , electricusage.created, > electricusage.modified, electricusage.from_date, > electricusage.to_date, electricusage.usage, electricusage.demand, > electricusage.bill_amount, electricusage.premise_account_id > Index Cond: (electricusage.premise_account_id > = premiseaccount.id ) > Filter: (electricusage.from_date >= > '2012-11-20 00:00:00+00'::timestamp with time zone) > Rows Removed by Filter: 2 > Buffers: shared hit=4850 read=18033 > Total runtime: 135044.256 ms > (23 rows) > > > Looks like it is doing an index only scan for the first table, but > not for the second. I tried creating two indexes that > theoretically should make it not have to go to the physical table.: > "electricusage_premise_account_id_36bc8999ced10059" btree > (premise_account_id, from_date, usage) > "ix_covered_2" btree (premise_account_id, from_date DESC, > usage, id) > > Any idea why it's not using that? > > > If the other IOS in this plan is anything to go by, then your table > doesn't have enough all-visible pages to make it worthwhile. So it > chooses the smaller index, instead of the bigger one that could > theoretically support an IOS. > > Cheers, > > Jeff > Bryce Covert > December 12, 2013 3:04 PM > Not sure if this is helpful, but I tried upgrading to 9.2, and here's > what I got: > > --------- > Limit (cost=0.00..535.78 rows=50 width=8) (actual > time=1037.376..135043.945 rows=50 loops=1) > Output: premiseaccount.id, (sum(electricusage.usage)) > Buffers: shared hit=4851 read=18718 > -> GroupAggregate (cost=0.00..198012.28 rows=18479 width=8) > (actual time=1037.369..135043.700 rows=50 loops=1) > Output: premiseaccount.id, sum(electricusage.usage) > Filter: ((sum(electricusage.usage) >= 3284::numeric) AND > (sum(electricusage.usage) <= 3769::numeric)) > Rows Removed by Filter: 1476 > Buffers: shared hit=4851 read=18718 > -> Nested Loop (cost=0.00..196247.46 rows=148764 width=8) > (actual time=107.092..134845.231 rows=15188 loops=1) > Output: premiseaccount.id, electricusage.usage > Buffers: shared hit=4851 read=18718 > -> Index Only Scan using > premiseaccount_bucket_58c70392619aa36f on public.premiseaccount > premiseaccount (cost=0.00..43135.13 rows=18479 width=4) (actual > time=45.368..137.340 rows=1527 loops=1) > Output: premiseaccount.bucket, premiseaccount.id > Index Cond: (premiseaccount.bucket = > '85375_single-family'::text) > Heap Fetches: 1527 > Buffers: shared hit=1 read=685 > -> Index Scan using electricusage_premise_account_id > on public.electricusage electricusage (cost=0.00..8.20 rows=9 > width=8) (actual time=22.306..88.136 rows=10 loops=1527) > Output: electricusage.id, electricusage.created, > electricusage.modified, electricusage.from_date, > electricusage.to_date, electricusage.usage, electricusage.demand, > electricusage.bill_amount, electricusage.premise_account_id > Index Cond: (electricusage.premise_account_id = > premiseaccount.id) > Filter: (electricusage.from_date >= '2012-11-20 > 00:00:00+00'::timestamp with time zone) > Rows Removed by Filter: 2 > Buffers: shared hit=4850 read=18033 > Total runtime: 135044.256 ms > (23 rows) > > > Looks like it is doing an index only scan for the first table, but not > for the second. I tried creating two indexes that theoretically > should make it not have to go to the physical table.: > "electricusage_premise_account_id_36bc8999ced10059" btree > (premise_account_id, from_date, usage) > "ix_covered_2" btree (premise_account_id, from_date DESC, usage, id) > > Any idea why it's not using that? > > Thanks! > Bryce > > Claudio Freire > December 12, 2013 1:35 PM > > On Thu, Dec 12, 2013 at 6:16 PM, Bryce Covert > > wrote: > > > Thanks a lot for the help. I'm not familiar with explain buffers, > but here's the results: > > Limit (cost=0.00..648.71 rows=50 width=8) (actual > time=653.681..52328.707 rows=50 loops=1) > Buffers: shared hit=7875 read=9870 > -> GroupAggregate (cost=0.00..55672.36 rows=4291 width=8) > (actual time=653.671..52328.480 rows=50 loops=1) > > Filter: ((sum(electricusage.usage) >= 3284::numeric) AND > (sum(electricusage.usage) <= 3769::numeric)) > Buffers: shared hit=7875 read=9870 > -> Nested Loop (cost=0.00..55262.93 rows=34506 width=8) > (actual time=432.129..52200.465 rows=30711 loops=1) > Buffers: shared hit=7875 read=9870 > -> Index Scan using > premiseaccount_bucket_58c70392619aa36f on premiseaccount > premiseaccount (cost=0.00..15433.71 rows=4291 width=4) (actual > time=338.160..10014.780 rows=3437 loops=1) > Index Cond: ((bucket)::text = > '85349_single-family'::text) > Buffers: shared hit=744 read=2692 > -> Index Scan using > electricusage_premise_account_id on electricusage electricusage > (cost=0.00..9.17 rows=9 width=8) (actual time=11.430..12.235 > rows=9 loops=3437) > Index Cond: (premise_account_id = > premiseaccount.id ) > Filter: (from_date >= '2012-11-20 > 00:00:00+00'::timestamp with time zone) > Buffers: shared hit=7131 read=7178 > Total runtime: 52329.028 ms > (15 rows) > > and the iostat results... > Linux 3.11.6-x86_64-linode35 (preview-aps-new) 12/12/2013 > _x86_64_ (8 CPU) > > ... > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 0.10 47.10 152.40 7.80 2.20 > 0.21 30.92 1.36 8.50 8.03 17.53 6.14 98.33 > xvdb 0.00 0.00 0.00 0.00 0.00 > 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 > > > > This means it's doing random I/O, and that your disk is a single > 7200RPM drive (152 r/s being typical for that hardware). > > You can improve this by either: > > 1 - Turning that random I/O pattern into sequential, or > 2 - Getting better I/O. > > I'll assume 2 isn't available to you on linode, so for 1, you could > try lowering effective_cache_size substantially. It seems you're not > getting nearly as much caching as you think (ie 2GB). However, I doubt > there's a plan that can get you significantly better performance given > your hardware. > > You may shave a few seconds, though, if you increase work_mem. It > seems it should have used a bitmap index scan for at least one of the > index scans there, and a low work_mem could be what's limiting the > planner's possibilities. What are your settings in that area? > > > Bryce Covert > December 12, 2013 1:16 PM > Hey Claudio, > > Thanks a lot for the help. I'm not familiar with explain buffers, but > here's the results: > > Limit (cost=0.00..648.71 rows=50 width=8) (actual > time=653.681..52328.707 rows=50 loops=1) > Buffers: shared hit=7875 read=9870 > -> GroupAggregate (cost=0.00..55672.36 rows=4291 width=8) (actual > time=653.671..52328.480 rows=50 loops=1) > Filter: ((sum(electricusage.usage) >= 3284::numeric) AND > (sum(electricusage.usage) <= 3769::numeric)) > Buffers: shared hit=7875 read=9870 > -> Nested Loop (cost=0.00..55262.93 rows=34506 width=8) > (actual time=432.129..52200.465 rows=30711 loops=1) > Buffers: shared hit=7875 read=9870 > -> Index Scan using > premiseaccount_bucket_58c70392619aa36f on premiseaccount > premiseaccount (cost=0.00..15433.71 rows=4291 width=4) (actual > time=338.160..10014.780 rows=3437 loops=1) > Index Cond: ((bucket)::text = > '85349_single-family'::text) > Buffers: shared hit=744 read=2692 > -> Index Scan using electricusage_premise_account_id > on electricusage electricusage (cost=0.00..9.17 rows=9 width=8) > (actual time=11.430..12.235 rows=9 loops=3437) > Index Cond: (premise_account_id = premiseaccount.id) > Filter: (from_date >= '2012-11-20 > 00:00:00+00'::timestamp with time zone) > Buffers: shared hit=7131 read=7178 > Total runtime: 52329.028 ms > (15 rows) > > and the iostat results... > Linux 3.11.6-x86_64-linode35 (preview-aps-new) 12/12/2013 > _x86_64_ (8 CPU) > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 6.94 65.68 12.16 7.64 0.36 0.29 > 67.06 0.44 22.11 3.56 51.66 1.15 2.28 > xvdb 0.00 0.00 0.00 0.00 0.00 0.00 > 10.61 0.00 1.82 1.82 0.00 1.82 0.00 > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 0.10 47.10 152.40 7.80 2.20 0.21 > 30.92 1.36 8.50 8.03 17.53 6.14 98.33 > xvdb 0.00 0.00 0.00 0.00 0.00 0.00 > 0.00 0.00 0.00 0.00 0.00 0.00 0.00 > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 0.20 2.30 212.10 0.70 3.22 0.01 > 31.09 1.47 6.88 6.90 2.86 4.63 98.62 > xvdb 0.00 0.00 0.00 0.00 0.00 0.00 > 0.00 0.00 0.00 0.00 0.00 0.00 0.00 > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 0.20 8.30 183.20 5.10 2.46 0.05 > 27.31 1.68 8.85 6.68 86.78 5.24 98.70 > xvdb 0.00 0.00 0.00 0.00 0.00 0.00 > 0.00 0.00 0.00 0.00 0.00 0.00 0.00 > > Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s > avgrq-sz avgqu-sz await r_await w_await svctm %util > xvda 0.10 0.00 165.70 0.00 2.36 0.00 > 29.20 1.46 8.86 8.86 0.00 5.95 98.63 > xvdb 0.00 0.00 0.00 0.00 0.00 0.00 > 0.00 0.00 0.00 0.00 0.00 0.00 0.00 > > I'm not sure how to process this except that 2.5MB/s seems really > slow, and it looks like it is using postgres' cache quite a bit. > > Thanks, > Bryce > > > Claudio Freire > December 12, 2013 12:48 PM > > > > Well, did you run benchmarks? How many IOPS do you get from the volumes? > > Try running "iostat -x -m -d 10" while the slow query is running and > pasting the results (or a relevant sample of them). > > Also, do run "explain (analyze, buffers)" instead of plain "explain > analyze". > --------------010107080309090301070402 Content-Type: multipart/related; boundary="------------000904060401090901030704" --------------000904060401090901030704 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit It looks like you guys were right. I think vacuum analyzing this made it do an IOS. It seems like materialized views are going to be the best bet. I see how that would allow sequential reading. Thanks!

Bryce

December 12, 2013 4:01 PM
On Thu, Dec 12, 2013 at 3:04 PM, Bryce Covert <bryce@brycecovertoperations.com> wrote:
Not sure if this is helpful, but I tried upgrading to 9.2, and here's what I got:

---------
 Limit  (cost=0.00..535.78 rows=50 width=8) (actual time=1037.376..135043.945 rows=50 loops=1)
   Output: premiseaccount.id, (sum(electricusage.usage))
   Buffers: shared hit=4851 read=18718
   ->  GroupAggregate  (cost=0.00..198012.28 rows=18479 width=8) (actual time=1037.369..135043.700 rows=50 loops=1)
         Output: premiseaccount.id, sum(electricusage.usage)

         Filter: ((sum(electricusage.usage) >= 3284::numeric) AND (sum(electricusage.usage) <= 3769::numeric))
         Rows Removed by Filter: 1476
         Buffers: shared hit=4851 read=18718
         ->  Nested Loop  (cost=0.00..196247.46 rows=148764 width=8) (actual time=107.092..134845.231 rows=15188 loops=1)
               Output: premiseaccount.id, electricusage.usage
               Buffers: shared hit=4851 read=18718
               ->  Index Only Scan using premiseaccount_bucket_58c70392619aa36f on public.premiseaccount premiseaccount  (cost=0.00..43135.13 rows=18479 width=4) (actual time=45.368..137.340 rows=1527 loops=1)
                     Output: premiseaccount.bucket, premiseaccount.id
                     Index Cond: (premiseaccount.bucket = '85375_single-family'::text)
                     Heap Fetches: 1527
 
You had to hit the heap for every row, meaning the index-only feature was useless.  Are you vacuuming enough?  How fast does this table change?  What is relallvisible from pg_class for these tables?

 
               ->  Index Scan using electricusage_premise_account_id on public.electricusage electricusage  (cost=0.00..8.20 rows=9 width=8) (actual time=22.306..88.136 rows=10 loops=1527)
                     Output: electricusage.id, electricusage.created, electricusage.modified, electricusage.from_date, electricusage.to_date, electricusage.usage, electricusage.demand, electricusage.bill_amount, electricusage.premise_account_id
                     Index Cond: (electricusage.premise_account_id = premiseaccount.id)
                     Filter: (electricusage.from_date >= '2012-11-20 00:00:00+00'::timestamp with time zone)
                     Rows Removed by Filter: 2
                     Buffers: shared hit=4850 read=18033
 Total runtime: 135044.256 ms
(23 rows)


Looks like it is doing an index only scan for the first table, but not for the second. I tried  creating two indexes that theoretically should make it not have to go to the physical table.:
    "electricusage_premise_account_id_36bc8999ced10059" btree (premise_account_id, from_date, usage)
    "ix_covered_2" btree (premise_account_id, from_date DESC, usage, id)

Any idea why it's not using that?

If the other IOS in this plan is anything to go by, then your table doesn't have enough all-visible pages to make it worthwhile.  So it chooses the smaller index, instead of the bigger one that could theoretically support an IOS.

Cheers,

Jeff
December 12, 2013 3:04 PM
Not sure if this is helpful, but I tried upgrading to 9.2, and here's what I got:

---------
 Limit  (cost=0.00..535.78 rows=50 width=8) (actual time=1037.376..135043.945 rows=50 loops=1)
   Output: premiseaccount.id, (sum(electricusage.usage))
   Buffers: shared hit=4851 read=18718
   ->  GroupAggregate  (cost=0.00..198012.28 rows=18479 width=8) (actual time=1037.369..135043.700 rows=50 loops=1)
         Output: premiseaccount.id, sum(electricusage.usage)
         Filter: ((sum(electricusage.usage) >= 3284::numeric) AND (sum(electricusage.usage) <= 3769::numeric))
         Rows Removed by Filter: 1476
         Buffers: shared hit=4851 read=18718
         ->  Nested Loop  (cost=0.00..196247.46 rows=148764 width=8) (actual time=107.092..134845.231 rows=15188 loops=1)
               Output: premiseaccount.id, electricusage.usage
               Buffers: shared hit=4851 read=18718
               ->  Index Only Scan using premiseaccount_bucket_58c70392619aa36f on public.premiseaccount premiseaccount  (cost=0.00..43135.13 rows=18479 width=4) (actual time=45.368..137.340 rows=1527 loops=1)
                     Output: premiseaccount.bucket, premiseaccount.id
                     Index Cond: (premiseaccount.bucket = '85375_single-family'::text)
                     Heap Fetches: 1527
                     Buffers: shared hit=1 read=685
               ->  Index Scan using electricusage_premise_account_id on public.electricusage electricusage  (cost=0.00..8.20 rows=9 width=8) (actual time=22.306..88.136 rows=10 loops=1527)
                     Output: electricusage.id, electricusage.created, electricusage.modified, electricusage.from_date, electricusage.to_date, electricusage.usage, electricusage.demand, electricusage.bill_amount, electricusage.premise_account_id
                     Index Cond: (electricusage.premise_account_id = premiseaccount.id)
                     Filter: (electricusage.from_date >= '2012-11-20 00:00:00+00'::timestamp with time zone)
                     Rows Removed by Filter: 2
                     Buffers: shared hit=4850 read=18033
 Total runtime: 135044.256 ms
(23 rows)


Looks like it is doing an index only scan for the first table, but not for the second. I tried  creating two indexes that theoretically should make it not have to go to the physical table.:
    "electricusage_premise_account_id_36bc8999ced10059" btree (premise_account_id, from_date, usage)
    "ix_covered_2" btree (premise_account_id, from_date DESC, usage, id)

Any idea why it's not using that?

Thanks!
Bryce

December 12, 2013 1:35 PM

On Thu, Dec 12, 2013 at 6:16 PM, Bryce Covert <bryce@brycecovertoperations.com> wrote:

Thanks a lot for the help. I'm not familiar with explain buffers, but here's the results:

 Limit  (cost=0.00..648.71 rows=50 width=8) (actual time=653.681..52328.707 rows=50 loops=1)
   Buffers: shared hit=7875 read=9870
   ->  GroupAggregate  (cost=0.00..55672.36 rows=4291 width=8) (actual time=653.671..52328.480 rows=50 loops=1)

         Filter: ((sum(electricusage.usage) >= 3284::numeric) AND (sum(electricusage.usage) <= 3769::numeric))
         Buffers: shared hit=7875 read=9870
         ->  Nested Loop  (cost=0.00..55262.93 rows=34506 width=8) (actual time=432.129..52200.465 rows=30711 loops=1)
               Buffers: shared hit=7875 read=9870
               ->  Index Scan using premiseaccount_bucket_58c70392619aa36f on premiseaccount premiseaccount  (cost=0.00..15433.71 rows=4291 width=4) (actual time=338.160..10014.780 rows=3437 loops=1)
                     Index Cond: ((bucket)::text = '85349_single-family'::text)
                     Buffers: shared hit=744 read=2692
               ->  Index Scan using electricusage_premise_account_id on electricusage electricusage  (cost=0.00..9.17 rows=9 width=8) (actual time=11.430..12.235 rows=9 loops=3437)
                     Index Cond: (premise_account_id = premiseaccount.id)
                     Filter: (from_date >= '2012-11-20 00:00:00+00'::timestamp with time zone)
                     Buffers: shared hit=7131 read=7178
 Total runtime: 52329.028 ms
(15 rows)

and the iostat results...
Linux 3.11.6-x86_64-linode35 (preview-aps-new)     12/12/2013     _x86_64_    (8 CPU)

...
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.10    47.10  152.40    7.80     2.20     0.21    30.92     1.36    8.50    8.03   17.53   6.14  98.33
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00


This means it's doing random I/O, and that your disk is a single 7200RPM drive (152 r/s being typical for that hardware).

You can improve this by either:

1 - Turning that random I/O pattern into sequential, or
2 - Getting better I/O.

I'll assume 2 isn't available to you on linode, so for 1, you could try lowering effective_cache_size substantially. It seems you're not getting nearly as much caching as you think (ie 2GB). However, I doubt there's a plan that can get you significantly better performance given your hardware.

You may shave a few seconds, though, if you increase work_mem. It seems it should have used a bitmap index scan for at least one of the index scans there, and a low work_mem could be what's limiting the planner's possibilities. What are your settings in that area?


December 12, 2013 1:16 PM
Hey Claudio,

Thanks a lot for the help. I'm not familiar with explain buffers, but here's the results:

 Limit  (cost=0.00..648.71 rows=50 width=8) (actual time=653.681..52328.707 rows=50 loops=1)
   Buffers: shared hit=7875 read=9870
   ->  GroupAggregate  (cost=0.00..55672.36 rows=4291 width=8) (actual time=653.671..52328.480 rows=50 loops=1)
         Filter: ((sum(electricusage.usage) >= 3284::numeric) AND (sum(electricusage.usage) <= 3769::numeric))
         Buffers: shared hit=7875 read=9870
         ->  Nested Loop  (cost=0.00..55262.93 rows=34506 width=8) (actual time=432.129..52200.465 rows=30711 loops=1)
               Buffers: shared hit=7875 read=9870
               ->  Index Scan using premiseaccount_bucket_58c70392619aa36f on premiseaccount premiseaccount  (cost=0.00..15433.71 rows=4291 width=4) (actual time=338.160..10014.780 rows=3437 loops=1)
                     Index Cond: ((bucket)::text = '85349_single-family'::text)
                     Buffers: shared hit=744 read=2692
               ->  Index Scan using electricusage_premise_account_id on electricusage electricusage  (cost=0.00..9.17 rows=9 width=8) (actual time=11.430..12.235 rows=9 loops=3437)
                     Index Cond: (premise_account_id = premiseaccount.id)
                     Filter: (from_date >= '2012-11-20 00:00:00+00'::timestamp with time zone)
                     Buffers: shared hit=7131 read=7178
 Total runtime: 52329.028 ms
(15 rows)

and the iostat results...
Linux 3.11.6-x86_64-linode35 (preview-aps-new)     12/12/2013     _x86_64_    (8 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              6.94    65.68   12.16    7.64     0.36     0.29    67.06     0.44   22.11    3.56   51.66   1.15   2.28
xvdb              0.00     0.00    0.00    0.00     0.00     0.00    10.61     0.00    1.82    1.82    0.00   1.82   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.10    47.10  152.40    7.80     2.20     0.21    30.92     1.36    8.50    8.03   17.53   6.14  98.33
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.20     2.30  212.10    0.70     3.22     0.01    31.09     1.47    6.88    6.90    2.86   4.63  98.62
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.20     8.30  183.20    5.10     2.46     0.05    27.31     1.68    8.85    6.68   86.78   5.24  98.70
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.10     0.00  165.70    0.00     2.36     0.00    29.20     1.46    8.86    8.86    0.00   5.95  98.63
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

I'm not sure how to process this except that 2.5MB/s seems really slow, and it looks like it is using postgres' cache quite a bit.

Thanks,
Bryce


December 12, 2013 12:48 PM



Well, did you run benchmarks? How many IOPS do you get from the volumes?

Try running "iostat -x -m -d 10" while the slow query is running and pasting the results (or a relevant sample of them).

Also, do run "explain (analyze, buffers)" instead of plain "explain analyze".

--------------000904060401090901030704 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= --------------000904060401090901030704 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 --------------000904060401090901030704-- --------------010107080309090301070402--