Re: Why is this query running slowly?

Should also add that while the client is under no load (CPU<1%, load
~0.1, mem ~20%), the server looks pretty busy (CPU 90-100% of 1 core,
load ~1.5, mem ~70-80%), but PG is the only thing using resources.

On Thu, Sep 15, 2011 at 12:58 AM, Yang Zhang <yanghatespam@gmail.com> wrote:
> 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@gmail.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/
>



--
Yang Zhang
http://yz.mit.edu/