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/
--
Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
