From: | Yang Zhang <yanghatespam(at)gmail(dot)com> |
---|---|
To: | pgsql-general(at)postgresql(dot)org |
Subject: | Re: Why is this query running slowly? |
Date: | 2011-09-15 07:58:45 |
Message-ID: | CAKxBDU9vinpBL8-t25uC5i-g6VBWY82BeKoPwVMmDL00qeWZiA@mail.gmail.com |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-general |
If it matters, the client is a JDBC app doing:
con = DriverManager.getConnection("jdbc:postgresql://localhost:5434/mydb",
"yang", password)
con.setAutoCommit(false)
val st = con.prepareStatement("""
select user_id from den where user_id not in (select duid from
user_mappings)
and timestamp between '2009-04-01'::date and '2010-04-01'::date;
""", ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY)
st.setFetchSize(8192)
rs = st.executeQuery()
On Thu, Sep 15, 2011 at 12:53 AM, Yang Zhang <yanghatespam(at)gmail(dot)com> wrote:
> I have a simple query that's been running for a while, which is fine,
> but it seems to be running very slowly, which is a problem:
>
> mydb=# explain select user_id from den where user_id not in (select
> duid from user_mappings) and timestamp between '2009-04-01' and
> '2010-04-01';
>
> QUERY PLAN
> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> Seq Scan on den (cost=711.58..66062724212.74 rows=22634720 width=4)
> Filter: (("timestamp" >= '2009-04-01 00:00:00'::timestamp without
> time zone) AND ("timestamp" <= '2010-04-01 00:00:00'::timestamp
> without time zone) AND (NOT (SubPlan 1)))
> SubPlan 1
> -> Materialize (cost=711.58..1223.38 rows=36780 width=4)
> -> Seq Scan on user_mappings (cost=0.00..530.80 rows=36780 width=4)
>
> user_mappings is fairly small:
>
> mydb=# select count(*) from user_mappings;
> count
> -------
> 36780
> (1 row)
>
> The client is on the same LAN, but only sees packets trickling in:
>
> $ sudo tcpdump -i lo port 5434
> tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
> listening on lo, link-type EN10MB (Ethernet), capture size 96 bytes
> 00:44:05.475584 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 3757958746:3757966938, ack 3697417382, win 265, options [nop,nop,TS
> val 194791416 ecr 194791044], length 8192
> 00:44:05.475684 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 8192, win 771, options [nop,nop,TS val 194791416 ecr 194791416],
> length 0
> 00:44:08.867976 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 8192:15779, ack 1, win 265, options [nop,nop,TS val 194791756 ecr
> 194791416], length 7587
> 00:44:08.868019 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 15779, win 771, options [nop,nop,TS val 194791756 ecr 194791756],
> length 0
> 00:44:08.870336 IP nuthouse.40349 > nuthouse.5434: Flags [P.], seq
> 1:19, ack 15779, win 771, options [nop,nop,TS val 194791756 ecr
> 194791756], length 18
> 00:44:08.870343 IP nuthouse.5434 > nuthouse.40349: Flags [.], ack 19,
> win 265, options [nop,nop,TS val 194791756 ecr 194791756], length 0
> 00:44:12.578220 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 15779:23971, ack 19, win 265, options [nop,nop,TS val 194792127 ecr
> 194791756], length 8192
> 00:44:12.618116 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 23971, win 771, options [nop,nop,TS val 194792131 ecr 194792127],
> length 0
> 00:44:16.664645 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 23971:32163, ack 19, win 265, options [nop,nop,TS val 194792535 ecr
> 194792131], length 8192
> 00:44:16.664755 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 32163, win 771, options [nop,nop,TS val 194792535 ecr 194792535],
> length 0
> 00:44:20.465773 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 32163:40355, ack 19, win 265, options [nop,nop,TS val 194792915 ecr
> 194792535], length 8192
> 00:44:20.465878 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 40355, win 720, options [nop,nop,TS val 194792915 ecr 194792915],
> length 0
> 00:44:24.115273 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 40355:48547, ack 19, win 265, options [nop,nop,TS val 194793280 ecr
> 194792915], length 8192
> 00:44:24.115380 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 48547, win 720, options [nop,nop,TS val 194793280 ecr 194793280],
> length 0
> 00:44:27.749084 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 48547:56739, ack 19, win 265, options [nop,nop,TS val 194793644 ecr
> 194793280], length 8192
> 00:44:27.749192 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 56739, win 720, options [nop,nop,TS val 194793644 ecr 194793644],
> length 0
> 00:44:31.618124 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 56739:64931, ack 19, win 265, options [nop,nop,TS val 194794031 ecr
> 194793644], length 8192
> 00:44:31.618166 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 64931, win 720, options [nop,nop,TS val 194794031 ecr 194794031],
> length 0
> 00:44:35.349958 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 64931:73123, ack 19, win 265, options [nop,nop,TS val 194794404 ecr
> 194794031], length 8192
> 00:44:35.350054 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 73123, win 720, options [nop,nop,TS val 194794404 ecr 194794404],
> length 0
> 00:44:39.311627 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 73123:81315, ack 19, win 265, options [nop,nop,TS val 194794800 ecr
> 194794404], length 8192
> 00:44:39.311734 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 81315, win 771, options [nop,nop,TS val 194794800 ecr 194794800],
> length 0
> 00:44:43.178319 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 81315:89507, ack 19, win 265, options [nop,nop,TS val 194795187 ecr
> 194794800], length 8192
> 00:44:43.178429 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 89507, win 771, options [nop,nop,TS val 194795187 ecr 194795187],
> length 0
> 00:44:46.798511 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 89507:97699, ack 19, win 265, options [nop,nop,TS val 194795549 ecr
> 194795187], length 8192
> 00:44:46.798622 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 97699, win 720, options [nop,nop,TS val 194795549 ecr 194795549],
> length 0
> 00:44:50.430346 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 97699:105891, ack 19, win 265, options [nop,nop,TS val 194795912 ecr
> 194795549], length 8192
> 00:44:50.430455 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 105891, win 720, options [nop,nop,TS val 194795912 ecr 194795912],
> length 0
> 00:44:54.211644 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 105891:114083, ack 19, win 265, options [nop,nop,TS val 194796290 ecr
> 194795912], length 8192
> 00:44:54.211792 IP nuthouse.40349 > nuthouse.5434: Flags [.], ack
> 114083, win 720, options [nop,nop,TS val 194796290 ecr 194796290],
> length 0
> 00:44:57.948539 IP nuthouse.5434 > nuthouse.40349: Flags [P.], seq
> 114083:122275, ack 19, win 265, options [nop,nop,TS val 194796664 ecr
> 194796290], length 8192
> ...
>
> And I verified that the query is not blocked:
>
> mydb=# select * from pg_stat_activity;
> datid | datname | procpid | usesysid | usename |
> current_query |
> waiting | xact_start | query_start
> | backend_start | client_addr | client_port
> -------+---------+---------+----------+---------+---------------------------------------------------------------------------------------+---------+-------------------------------+-------------------------------+-------------------------------+-------------+-------------
> 55244 | mydb | 5128 | 16384 | yang |
> | f
> | 2011-09-14 15:44:46.586014-07 | 2011-09-15 00:46:22.878715-07 |
> 2011-09-14 15:44:46.549151-07 | ::1 | 56791
> : select user_id
> from den where user_id not in (select duid from user_mappings)
> : and timestamp
> between '2009-04-01'::date and '2010-04-01'::date
> 55244 | mydb | 28142 | 16384 | yang | select * from
> pg_stat_activity;
> | f | 2011-09-15 00:46:40.100652-07 | 2011-09-15
> 00:46:40.100652-07 | 2011-09-15 00:46:35.913309-07 | |
> -1
> (2 rows)
>
> (The ports don't match up since this is tunneled via ssh. `pv <
> /dev/zero | ssh nuthouse 'cat>/dev/null'` shows sustained bandwidth at
> ~30-40MB/s.)
>
> I know that `den` is large but things seem to be running much slower
> than I'd expect. Nothing in the logs. Is there any way to inspect
> what's going on? Hesitant to kill the query in case it's almost done,
> though I doubt it (didn't have the foresight to expose this
> information in the client process - wasn't expecting to run into
> this). Thanks in advance.
>
> --
> Yang Zhang
> http://yz.mit.edu/
>
--
Yang Zhang
http://yz.mit.edu/
From | Date | Subject | |
---|---|---|---|
Next Message | Yang Zhang | 2011-09-15 08:07:11 | Re: Why is this query running slowly? |
Previous Message | Yang Zhang | 2011-09-15 07:53:59 | Why is this query running slowly? |