query looping?

From: Brian Cox <brian(dot)cox(at)ca(dot)com>
To: "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org>
Subject: query looping?
Date: 2010-01-04 19:41:30
Message-ID: 4B42446A.1090005@ca.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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)

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Madison Kelly 2010-01-04 20:30:46 Re: DB is slow until DB is reloaded
Previous Message Steve Crawford 2010-01-04 19:31:33 Re: DB is slow until DB is reloaded