Received: from localhost (unknown [200.46.204.183]) by mail.postgresql.org (Postfix) with ESMTP id E03FD6334B4 for ; Mon, 2 Mar 2009 14:58:48 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 94941-02 for ; Mon, 2 Mar 2009 14:58:35 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from EXHUB018-4.exch018.msoutlookonline.net (exhub018-4.exch018.msoutlookonline.net [64.78.17.19]) by mail.postgresql.org (Postfix) with ESMTP id 3B4926335EB for ; Mon, 2 Mar 2009 14:58:34 -0400 (AST) Received: from EXVMBX018-1.exch018.msoutlookonline.net ([64.78.17.47]) by EXHUB018-4.exch018.msoutlookonline.net ([64.78.17.19]) with mapi; Mon, 2 Mar 2009 10:58:33 -0800 From: Scott Carey To: Brian Cox , "tgl@sss.pgh.pa.us" CC: "pgsql-performance@postgresql.org" Date: Mon, 2 Mar 2009 10:58:28 -0800 Subject: Re: "slow" queries Thread-Topic: [PERFORM] "slow" queries Thread-Index: AcmbZBZJMjvz7hQkR0iuMBFb8C8BVQABMjm5 Message-ID: In-Reply-To: <49AC23FF.9070103@ca.com> Accept-Language: en-US Content-Language: en X-MS-Has-Attach: X-MS-TNEF-Correlator: acceptlanguage: en-US Content-Type: multipart/alternative; boundary="_000_C5D16C542E42scottrichrelevancecom_" MIME-Version: 1.0 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.001 tagged_above=0 required=5 tests=HTML_MESSAGE=0.001 X-Spam-Level: X-Archive-Number: 200903/13 X-Sequence-Number: 32935 --_000_C5D16C542E42scottrichrelevancecom_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable In my experience, 13833, " in transaction" is your culprit. It is a = transaction that has been there for 10 hours longer than all others, and is= doing nothing at all. It has locks on a lot of objects in there. You'll = have to take the oid's in the lock table and look them up in the pg_class t= able to figure out what those are. Alternatively, the procpid (13833) may = be all you need to track down the user or program that needs to have a talk= ing-to. Something as dumb as: Open psql BEGIN; // do some stuff //.. Go home with the terminal open, get some dinner, go to sleep //.. Wake up, dorp the kids off at school //.. Arrive at work, get some coffee //.. Realize your psql terminal is open and close it Can be your culprit. Common culprits are applications that don't open and close their transactio= ns properly when errors occur and pool connections forever. Pg_locks, even on a really busy db, should not have that many locks in the = view. If there are a lot, and they aren't 'churning and changing' then you= have some long running transactions. The pid column in the locks table corresponds with procpid in the activity = table. The 'relation' column in the lock table corresponds with stuff in p= g_class. On 3/2/09 10:22 AM, "Brian Cox" wrote: Tom Lane [tgl@sss.pgh.pa.us] wrote: > [ shrug... ] You tell us. To me it sounds a whole lot like some client > program sitting on an open transaction that has a nonexclusive lock on > the table to be dropped. That transaction wasn't necessarily doing any > useful work; it might have just been waiting on the client. I wish I could... And, in any event, aren't all transactions listed in the pg_stat_activity select? > At this point I suppose arguing about it is moot because the evidence > is all gone. If it happens again, capture the contents of pg_locks and > pg_stat_activity while things are still stuck. This happened again last night. This time I'd added a lock (in the java code) to prevent inserts into other partitions of ts_defects while the drop is in progress. Below is the output from: select xact_start,datid,datname,procpid,usesysid,substring(current_query from 0 for 40),waiting,client_addr from pg_stat_activity order by xact_start; and select locktype,database,relation,virtualxid,virtualtransaction,pid,mode from pg_locks order by mode; As you can see there are only 3 transactions and 1 starts 1 hour after the drop begins. I'm still trying to figure out how to interpret the pg_locks output, but (presumably) you/others on this forum have more experience at this than I. Thanks, Brian cemdb=3D> select xact_start,datid,datname,procpid,usesysid,substring(current_query from 0 for 40),waiting,client_addr from pg_stat_activity order by xact_start; xact_start | datid | datname | procpid | usesysid | substring | waiting | client_addr -------------------------------+----------+---------+---------+----------+-= ----------------------------------------+---------+---------------- 2009-03-01 14:10:42.606592-08 | 26472437 | cemdb | 13833 | 16392 | in transaction | f | 130.200.164.15 2009-03-02 00:30:00.039977-08 | 26472437 | cemdb | 13842 | 16392 | drop table ts_defects_20090227 | t | 127.0.0.1 2009-03-02 00:30:00.066728-08 | 26472437 | cemdb | 13865 | 16392 | select transetdef0_.ts_id as ts1_85_0_, | t | 127.0.0.1 2009-03-02 01:01:00.992486-08 | 26472437 | cemdb | 13840 | 16392 | CREATE VIEW TranSetGroupSlaPerformanceA | t | 127.0.0.1 2009-03-02 10:16:21.252969-08 | 26472437 | cemdb | 29985 | 16392 | select xact_start,datid,datname,procpid | f | | 26472437 | cemdb | 13735 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13744 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13857 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13861 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13864 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13855 | 16392 | | f | 127.0.0.1 | 26472437 | cemdb | 13740 | 16392 | | f | 127.0.0.1 (12 rows) cemdb=3D> select locktype,database,relation,virtualxid,virtualtransaction,pid,mode from pg_locks order by mode; locktype | database | relation | virtualxid | virtualtransaction | pid | mode ---------------+----------+----------+------------+--------------------+---= ----+--------------------- relation | 26472437 | 26592616 | | 15/69749 | 13842 | AccessExclusiveLock relation | 26472437 | 26592608 | | 15/69749 | 13842 | AccessExclusiveLock relation | 26472437 | 26592615 | | 15/69749 | 13842 | AccessExclusiveLock relation | 26472437 | 26592613 | | 15/69749 | 13842 | AccessExclusiveLock relation | 26472437 | 26472508 | | 15/69749 | 13842 | AccessExclusiveLock relation | 26472437 | 26493706 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26473141 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 10969 | | 1/77414 | 29985 | AccessShareLock relation | 26472437 | 26473176 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493307 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493271 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493704 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493711 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 2674 | | 15/69749 | 13842 | AccessShareLock relation | 26472437 | 26493279 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26473227 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493705 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26472869 | | 14/70049 | 13840 | AccessShareLock relation | 26472437 | 26493306 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493712 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26472508 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493709 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26472508 | | 14/70049 | 13840 | AccessShareLock relation | 26472437 | 26472595 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493269 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493710 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 2702 | | 15/69749 | 13842 | AccessShareLock relation | 26472437 | 26493267 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493700 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26472508 | | 29/69612 | 13865 | AccessShareLock relation | 26472437 | 26493259 | | 11/131 | 13833 | AccessShareLock relation | 26472437 | 26493103 | | 11/131 | 13833 | AccessShareLock virtualxid | | | 14/70049 | 14/70049 | 13840 | ExclusiveLock transactionid | | | | 15/69749 | 13842 | ExclusiveLock virtualxid | | | 29/69612 | 29/69612 | 13865 | ExclusiveLock virtualxid | | | 15/69749 | 15/69749 | 13842 | ExclusiveLock virtualxid | | | 1/77414 | 1/77414 | 29985 | ExclusiveLock virtualxid | | | 11/131 | 11/131 | 13833 | ExclusiveLock relation | 26472437 | 2620 | | 15/69749 | 13842 | RowExclusiveLock relation | 26472437 | 2608 | | 15/69749 | 13842 | RowExclusiveLock (40 rows) -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance --_000_C5D16C542E42scottrichrelevancecom_ Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Re: [PERFORM] "slow" queries In my experience, 13833, “<IDLE> in transaction” is= your culprit.  It is a transaction that has been there for 10 hours l= onger than all others, and is doing nothing at all.  It has locks on a= lot of objects in there.  You’ll have to take the oid’s i= n the lock table and look them up in the pg_class table to figure out what = those are.  Alternatively, the procpid (13833) may be all you need to = track down the user or program that needs to have a talking-to.

Something as dumb as:

Open psql
BEGIN;
// do some stuff

//.. Go home with the terminal open, get some dinner, go to sleep
//.. Wake up, dorp the kids off at school
//.. Arrive at work, get some coffee
//.. Realize your psql terminal is open and close it

Can be your culprit.  
Common culprits are applications that don’t open and close their tran= sactions properly when errors occur and pool connections forever.

Pg_locks, even on a really busy db, should not have that many locks in the = view.  If there are a lot, and they aren’t ‘churning and c= hanging’ then you have some long running transactions.  
The pid column in the locks table corresponds with procpid in the activity = table.  The ‘relation’ column in the lock table correspond= s with stuff in pg_class.



On 3/2/09 10:22 AM, "Brian Cox" <= brian.cox@ca.com> wrote:

Tom Lane [tgl= @sss.pgh.pa.us] wrote:
> [ shrug... ]  You tell us.  To me it sounds a whole lot like= some client
> program sitting on an open transaction that has a nonexclusive lock on=
> the table to be dropped.  That transaction wasn't necessarily doi= ng any
> useful work; it might have just been waiting on the client.

I wish I could... And, in any event, aren't all transactions listed in
the pg_stat_activity select?

> At this point I suppose arguing about it is moot because the evidence<= BR> > is all gone.  If it happens again, capture the contents of pg_loc= ks and
> pg_stat_activity while things are still stuck.

This happened again last night. This time I'd added a lock (in the java
code) to prevent inserts into other partitions of ts_defects while the
drop is in progress. Below is the output from:
select xact_start,datid,datname,procpid,usesysid,substring(current_query from 0 for 40),waiting,client_addr from  pg_stat_activity order by
xact_start;

and

select locktype,database,relation,virtualxid,virtualtransaction,pid,mode from pg_locks order by mode;

As you can see there are only 3 transactions and 1 starts 1 hour after
the drop begins. I'm still trying to figure out how to interpret the
pg_locks output, but (presumably) you/others on this forum have more
experience at this than I.

Thanks,
Brian



cemdb=3D> select
xact_start,datid,datname,procpid,usesysid,substring(current_query from 0 for 40),waiting,client_addr from  pg_stat_activity order by xact_start= ;
           xact_star= t           |  datid=   | datname | procpid |
usesysid |           &nbs= p;    substring       &nb= sp;        | waiting |  client= _addr
-------------------------------+----------+---------+---------+----------+-= ----------------------------------------+---------+----------------
  2009-03-01 14:10:42.606592-08 | 26472437 | cemdb   | =   13833 |
16392 | <IDLE> in transaction       &nb= sp;           | f &n= bsp;     | 130.200.164.15
  2009-03-02 00:30:00.039977-08 | 26472437 | cemdb   | =   13842 |
16392 | drop table ts_defects_20090227       =    | t       | 127.0.0.1
  2009-03-02 00:30:00.066728-08 | 26472437 | cemdb   | =   13865 |
16392 | select transetdef0_.ts_id as ts1_85_0_, | t     = ;  | 127.0.0.1
  2009-03-02 01:01:00.992486-08 | 26472437 | cemdb   | =   13840 |
16392 | CREATE VIEW TranSetGroupSlaPerformanceA | t     = ;  | 127.0.0.1
  2009-03-02 10:16:21.252969-08 | 26472437 | cemdb   | =   29985 |
16392 | select xact_start,datid,datname,procpid | f     = ;  |
            &nb= sp;            =        | 26472437 | cemdb   | =   13735 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13744 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13857 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13861 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13864 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13855 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
            &nb= sp;            =        | 26472437 | cemdb   | =   13740 |
16392 | <IDLE>          =             &nb= sp;           | f &n= bsp;     | 127.0.0.1
(12 rows)

cemdb=3D> select
locktype,database,relation,virtualxid,virtualtransaction,pid,mode from
pg_locks order by mode;
locktype    | database | relation | virtualxid | virtualtran= saction |
pid  |        mode
---------------+----------+----------+------------+--------------------+---= ----+---------------------
  relation      | 26472437 | 26592616 | =            | 15/6974= 9
| 13842 | AccessExclusiveLock
  relation      | 26472437 | 26592608 | =            | 15/6974= 9
| 13842 | AccessExclusiveLock
  relation      | 26472437 | 26592615 | =            | 15/6974= 9
| 13842 | AccessExclusiveLock
  relation      | 26472437 | 26592613 | =            | 15/6974= 9
| 13842 | AccessExclusiveLock
  relation      | 26472437 | 26472508 | =            | 15/6974= 9
| 13842 | AccessExclusiveLock
  relation      | 26472437 | 26493706 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26473141 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 |   = ; 10969 |           =  | 1/77414
| 29985 | AccessShareLock
  relation      | 26472437 | 26473176 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493307 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493271 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493704 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493711 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 |   = ;  2674 |          &= nbsp; | 15/69749
| 13842 | AccessShareLock
  relation      | 26472437 | 26493279 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26473227 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493705 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26472869 | =            | 14/7004= 9
| 13840 | AccessShareLock
  relation      | 26472437 | 26493306 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493712 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26472508 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493709 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26472508 | =            | 14/7004= 9
| 13840 | AccessShareLock
  relation      | 26472437 | 26472595 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493269 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493710 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 |   = ;  2702 |          &= nbsp; | 15/69749
| 13842 | AccessShareLock
  relation      | 26472437 | 26493267 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493700 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26472508 | =            | 29/6961= 2
| 13865 | AccessShareLock
  relation      | 26472437 | 26493259 | =            | 11/131<= BR> | 13833 | AccessShareLock
  relation      | 26472437 | 26493103 | =            | 11/131<= BR> | 13833 | AccessShareLock
  virtualxid    |      &n= bsp;   |         &nb= sp;| 14/70049   | 14/70049
| 13840 | ExclusiveLock
  transactionid |         = ; |          |  &nbs= p;         | 15/69749
| 13842 | ExclusiveLock
  virtualxid    |      &n= bsp;   |         &nb= sp;| 29/69612   | 29/69612
| 13865 | ExclusiveLock
  virtualxid    |      &n= bsp;   |         &nb= sp;| 15/69749   | 15/69749
| 13842 | ExclusiveLock
  virtualxid    |      &n= bsp;   |         &nb= sp;| 1/77414    | 1/77414
| 29985 | ExclusiveLock
  virtualxid    |      &n= bsp;   |         &nb= sp;| 11/131     | 11/131
| 13833 | ExclusiveLock
  relation      | 26472437 |   = ;  2620 |          &= nbsp; | 15/69749
| 13842 | RowExclusiveLock
  relation      | 26472437 |   = ;  2608 |          &= nbsp; | 15/69749
| 13842 | RowExclusiveLock
(40 rows)

--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www= .postgresql.org/mailpref/pgsql-performance

--_000_C5D16C542E42scottrichrelevancecom_--