pg.ddx.io  pgsql-performance@postgresql.org mailing list archive  
help / color / mirror / Atom feed
From: Brian Cox <brian.cox@ca.com>
To: pgsql-performance@postgresql.org <pgsql-performance@postgresql.org>
Subject: query looping?
Date: Mon, 04 Jan 2010 11:41:30 -0800
Message-ID: <4B42446A.1090005@ca.com> (raw)

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)



view thread (9+ messages)  latest in thread

Message-ID: <4B42446A.1090005@ca.com>
Permalink:  ../4B42446A.1090005@ca.com/
Also on:    postgresql.org/message-id/4B42446A.1090005@ca.com

 · 

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: pgsql-performance@postgresql.org
  Cc: brian.cox@ca.com
  Subject: Re: query looping?
  In-Reply-To: <4B42446A.1090005@ca.com>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox