query looping? - Mailing list pgsql-performance

From Brian Cox
Subject query looping?
Date
Msg-id 4B42446A.1090005@ca.com
Whole thread Raw
Responses Re: query looping?
List pgsql-performance
The query shown below [select count(distinct...] seems to be looping
(99-101% CPU as shown by top for 11+ hours). This using postgres 8.3.5
on a dual quad core machine (Intel(R) Xeon(R) CPU X5460 @ 3.16GHz) with
32G RAM. Can I provide any other info to help investigate this issue? Or
any thoughts on how to prevent/avoid it?

Thanks,
Brian

top - 11:03:39 up 91 days, 22:39,  2 users,  load average: 3.73, 2.14, 1.42
Tasks: 135 total,   3 running, 132 sleeping,   0 stopped,   0 zombie
Cpu(s): 27.3% us,  7.7% sy,  0.0% ni, 54.0% id, 11.0% wa,  0.0% hi,  0.0% si
Mem:  33264272k total, 33247780k used,    16492k free,    17232k buffers
Swap:  4088532k total,   334264k used,  3754268k free, 26760304k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
24585 postgres  17   0  572m 494m 484m R   99  1.5 646:13.63 postmaster

cemdb=# select procpid,query_start,current_query from pg_stat_activity;
  procpid |          query_start          |
         current_query

---------+-------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    13210 | 2010-01-04 10:54:04.490107-08 | <IDLE>
    24496 | 2010-01-04 10:56:14.982997-08 | <IDLE>
    30636 | 2010-01-04 10:54:04.488569-08 | <IDLE>
     5309 | 2010-01-04 10:56:22.850159-08 | select
procpid,query_start,current_query from pg_stat_activity;
    30637 | 2010-01-04 10:54:04.490152-08 | <IDLE>
    24500 | 2010-01-04 10:56:14.98354-08  | <IDLE>
    13213 | 2010-01-04 10:54:04.491743-08 | <IDLE>
    13214 | 2010-01-04 10:56:04.197887-08 | <IDLE>
    24499 | 2010-01-04 10:56:14.981709-08 | <IDLE>
    24502 | 2010-01-04 10:56:14.985027-08 | <IDLE>
    13217 | 2010-01-04 10:54:04.487039-08 | <IDLE>
    24504 | 2010-01-04 10:56:14.984631-08 | <IDLE>
    24505 | 2010-01-04 10:56:14.985248-08 | <IDLE>
    27938 | 2010-01-04 10:54:04.485782-08 | <IDLE>
     1104 | 2010-01-04 10:54:04.489896-08 | <IDLE>
    27941 | 2010-01-04 10:54:04.491925-08 | <IDLE>
    24585 | 2010-01-04 00:16:52.764899-08 | select count(distinct
b.ts_id) from ts_stats_transetgroup_user_weekly b,
ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= $1 and c.ts_interval_start_time < $2 and
b.ts_interval_start_time >= $3 and b.ts_interval_start_time < $4
    24586 | 2010-01-04 10:56:14.986201-08 | <IDLE>
    13224 | 2010-01-04 10:54:04.487762-08 | <IDLE>
    24591 | 2010-01-04 10:56:14.98333-08  | <IDLE>
    24592 | 2010-01-04 10:56:14.98157-08  | <IDLE>
(21 rows)

cemdb=# select
locktype,database,relation,virtualtransaction,mode,granted from pg_locks
where pid=24585;
   locktype  | database | relation | virtualtransaction |      mode
   | granted
------------+----------+----------+--------------------+-----------------+---------
  relation   |    74755 |    76064 | 23/1037332         |
AccessShareLock | t
  virtualxid |          |          | 23/1037332         | ExclusiveLock
   | t
  relation   |    74755 |    75245 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76062 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76188 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    74822 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76187 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76186 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76189 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76057 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    75846 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76063 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76058 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76185 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    75874 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76061 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76191 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76059 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76363 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76364 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76192 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76362 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76190 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    75920 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    75343 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76193 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76060 | 23/1037332         |
AccessShareLock | t
  relation   |    74755 |    76065 | 23/1037332         |
AccessShareLock | t
(28 rows)

cemdb=> explain analyze select count(distinct b.ts_id) from
ts_stats_transetgroup_user_weekly b, ts_stats_transet_user_interval c,
ts_transetgroup_transets_map m where b.ts_transet_group_id =
m.ts_transet_group_id and m.ts_transet_incarnation_id =
c.ts_transet_incarnation_id and c.ts_user_incarnation_id =
b.ts_user_incarnation_id and c.ts_interval_start_time >= '2010-01-03
00:00' and c.ts_interval_start_time < '2010-01-03 08:00' and
b.ts_interval_start_time >= '2009-12-28 00:00' and
b.ts_interval_start_time < '2010-01-04 00:00';

                          QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Aggregate  (cost=1726281.28..1726281.29 rows=1 width=8) (actual
time=16690.541..16690.542 rows=1 loops=1)
    ->  Hash Join  (cost=43363.87..1725837.91 rows=354697 width=8)
(actual time=1343.960..14467.012 rows=1600000 loops=1)
          Hash Cond: ((b.ts_transet_group_id = m.ts_transet_group_id)
AND (c.ts_transet_incarnation_id = m.ts_transet_incarnation_id))
          ->  Hash Join  (cost=43362.03..1717697.04 rows=1697479
width=24) (actual time=1343.778..11432.270 rows=1600000 loops=1)
                Hash Cond: (c.ts_user_incarnation_id =
b.ts_user_incarnation_id)
                ->  Bitmap Heap Scan on ts_stats_transet_user_interval c
  (cost=19014.73..1666918.08 rows=844436 width=16) (actual
time=950.097..8125.102 rows=800000 loops=1)
                      Recheck Cond: ((ts_interval_start_time >=
'2010-01-03 00:00:00-08'::timestamp with time zone) AND
(ts_interval_start_time < '2010-01-03 08:00:00-08'::timestamp with time
zone))
                      ->  Bitmap Index Scan on
ts_stats_transet_user_interval_starttime  (cost=0.00..18909.17
rows=844436 width=0) (actual time=930.036..930.036 rows=800000 loops=1)
                            Index Cond: ((ts_interval_start_time >=
'2010-01-03 00:00:00-08'::timestamp with time zone) AND
(ts_interval_start_time < '2010-01-03 08:00:00-08'::timestamp with time
zone))
                ->  Hash  (cost=23787.37..23787.37 rows=89590 width=24)
(actual time=393.570..393.570 rows=89758 loops=1)
                      ->  Seq Scan on ts_stats_transetgroup_user_weekly
b  (cost=0.00..23787.37 rows=89590 width=24) (actual time=0.040..295.414
rows=89758 loops=1)
                            Filter: ((ts_interval_start_time >=
'2009-12-28 00:00:00-08'::timestamp with time zone) AND
(ts_interval_start_time < '2010-01-04 00:00:00-08'::timestamp with time
zone))
          ->  Hash  (cost=1.33..1.33 rows=67 width=16) (actual
time=0.156..0.156 rows=67 loops=1)
                ->  Seq Scan on ts_transetgroup_transets_map m
(cost=0.00..1.33 rows=67 width=16) (actual time=0.022..0.080 rows=67
loops=1)
  Total runtime: 16691.964 ms
(15 rows)

pgsql-performance by date:

Previous
From: Steve Crawford
Date:
Subject: Re: DB is slow until DB is reloaded
Next
From: Madison Kelly
Date:
Subject: Re: DB is slow until DB is reloaded