Re: "slow" queries

From: Scott Carey <scott(at)richrelevance(dot)com>
To: Brian Cox <brian(dot)cox(at)ca(dot)com>, "tgl(at)sss(dot)pgh(dot)pa(dot)us" <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: "pgsql-performance(at)postgresql(dot)org" <pgsql-performance(at)postgresql(dot)org>
Subject: Re: "slow" queries
Date: 2009-03-02 18:58:28
Message-ID: C5D16C54.2E42%scott@richrelevance.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

In my experience, 13833, "<IDLE> 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 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 transactions 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 pg_class.

On 3/2/09 10:22 AM, "Brian Cox" <brian(dot)cox(at)ca(dot)com> wrote:

Tom Lane [tgl(at)sss(dot)pgh(dot)pa(dot)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=> 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 | <IDLE> 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 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13744 |
16392 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13857 |
16392 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13861 |
16392 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13864 |
16392 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13855 |
16392 | <IDLE> | f | 127.0.0.1
| 26472437 | cemdb | 13740 |
16392 | <IDLE> | f | 127.0.0.1
(12 rows)

cemdb=> 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(at)postgresql(dot)org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

In response to

Browse pgsql-performance by date

  From Date Subject
Next Message Robert Haas 2009-03-02 19:04:34 Re: "slow" queries
Previous Message Brian Cox 2009-03-02 18:22:55 Re: "slow" queries