Re: Why is this query running slowly?

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/