I have a performance riddle, hoping someone can point me in a
helpful direction. We have a pg 8.1.2 cluster using
Apache::Sessions and experiencing simple UPDATEs taking
sometimes 30+ seconds to do a very simply update, no foreign
keys, no triggers:
Table "public.sessions"
Column | Type | Modifiers
++
id | character(32) | not null
a_session | text |
Indexes:
"sessions_pkey" PRIMARY KEY, btree (id)
This is on an HP ia64 11.23 box with what appears to be gobs of
surplus CPU, I/ (it's on a SAN), and RAM, pretty high query
volume from 180 concurrent client connections.
Wondering if it is a locking issue, I set up logging to capture
existing locks every 10s with this query:
SELECT now(), dbu.usename as locker, l.mode as locktype, CASE
l.granted WHEN true THEN 'granted' ELSE 'pending' END as status,
pg_stat_get_backend_pid(S.backendid)
as pid, l.transaction as xid, db.datname||'.'||n.nspname||'.'||
r.relname as relation, case l.mode when 'AccessShareLock' then 1
when 'RowShareLock' then 2 when 'Row
ExclusiveLock' then 3 when 'ShareUpdateExclusiveLock' then 4 when
'ShareLock' then 5 when 'ShareRowExclusiveLock' then 6 when
'ExclusiveLock' then 7 else 100 end as
exclusivity, pg_stat_get_backend_activity(S.backendid) as query
FRM pg_user dbu,
(SELECT pg_stat_get_backend_idset() AS backendid) AS S,
pg_database db, pg_locks l, pg_class r, pg_namespace n
WHERE db.oid = pg_stat_get_backend_dbid(S.backendid)
AND dbu.usesysid = pg_stat_get_backend_userid(S.backendid)
AND l.pid = pg_stat_get_backend_pid(S.backendid)
AND l.relation = r.oid
AND l.database = db.oid
AND r.relnamespace = n.oid
RDER BY exclusivity DESC, db.datname, n.nspname, r.relname,
l.mode;"
I see what appear to be many single transactions holding
RowExclusiveLocks for sometimes 40-50 seconds while their query
shows "<IDLEin transaction".
2006-03-25 20:04:01.063873-08 | www | RowExclusiveLock | granted
| 17192 | 270205914 | db1.public.sessions | 3 | <IDLE
in transaction
2006-03-25 20:04:11.128632-08 | www | RowExclusiveLock | granted
| 17192 | 270205914 | db1.public.sessions | 3
| <IDLEin transaction
2006-03-25 20:04:21.215896-08 | www | RowExclusiveLock | granted
| 17192 | 270205914 | db1.public.sessions | 3
| <IDLEin transaction
I'm thinking that means the client is simply tweaking a row and
then failing to commit the change for 40-50 seconds. Is that
consistent? Is there something else obvious here to explain the
delays? Does this sound like a browser stop button issue where
they may be aborting the query that has the lock, and then
issuing another that waits on the first? suggestions?
Thanks,
Ed
(end of broadcast)
TIP 2: Don't 'kill -9' the postmaster

Saturday March 25 2006 9:36 pm, Ed L. wrote:
I have a performance riddle, hoping someone can point me in a
helpful direction. We have a pg 8.1.2 cluster using
Apache::Sessions and experiencing simple UPDATEs taking
sometimes 30+ seconds to do a very simply update, no foreign
keys, no triggers:

Table "public.sessions"
Column | Type | Modifiers
++
id | character(32) | not null
a_session | text |
Indexes:
"sessions_pkey" PRIMARY KEY, btree (id)

The table has 6800 rows over 18000 pages, and is getting a
minimum of many tens of thousands of updates per day with
queries like this:

UPDATE sessions SET a_session = ? WHERE id = ?

Ed

--
This is on an HP ia64 11.23 box with what appears to be gobs
of surplus CPU, I/ (it's on a SAN), and RAM, pretty high
query volume from 180 concurrent client connections.

Wondering if it is a locking issue, I set up logging to
capture existing locks every 10s with this query:

SELECT now(), dbu.usename as locker, l.mode as locktype, CASE
l.granted WHEN true THEN 'granted' ELSE 'pending' END as
status, pg_stat_get_backend_pid(S.backendid)
as pid, l.transaction as xid,
db.datname||'.'||n.nspname||'.'|| r.relname as relation, case
l.mode when 'AccessShareLock' then 1 when 'RowShareLock' then
2 when 'Row
ExclusiveLock' then 3 when 'ShareUpdateExclusiveLock' then 4
when 'ShareLock' then 5 when 'ShareRowExclusiveLock' then 6
when 'ExclusiveLock' then 7 else 100 end as
exclusivity, pg_stat_get_backend_activity(S.backendid) as
query FRM pg_user dbu,
(SELECT pg_stat_get_backend_idset() AS backendid) AS S,
pg_database db, pg_locks l, pg_class r, pg_namespace n
WHERE db.oid = pg_stat_get_backend_dbid(S.backendid)
AND dbu.usesysid = pg_stat_get_backend_userid(S.backendid)
AND l.pid = pg_stat_get_backend_pid(S.backendid)
AND l.relation = r.oid
AND l.database = db.oid
AND r.relnamespace = n.oid
RDER BY exclusivity DESC, db.datname, n.nspname, r.relname,
l.mode;"
--
I see what appear to be many single transactions holding
RowExclusiveLocks for sometimes 40-50 seconds while their
query shows "<IDLEin transaction".

2006-03-25 20:04:01.063873-08 | www | RowExclusiveLock |
granted

| 17192 | 270205914 | db1.public.sessions | 3 |
| <IDLE>

in transaction
2006-03-25 20:04:11.128632-08 | www | RowExclusiveLock |
granted

| 17192 | 270205914 | db1.public.sessions |
| 3 <IDLEin transaction

2006-03-25 20:04:21.215896-08 | www | RowExclusiveLock |
granted

| 17192 | 270205914 | db1.public.sessions |
| 3 <IDLEin transaction

I'm thinking that means the client is simply tweaking a row
and then failing to commit the change for 40-50 seconds. Is
that consistent? Is there something else obvious here to
explain the delays? Does this sound like a browser stop
button issue where they may be aborting the query that has the
lock, and then issuing another that waits on the first?
suggestions?

Thanks,
Ed

(end of broadcast)
TIP 3: Have you checked our extensive FAQ?

Saturday March 25 2006 9:49 pm, Ed L. wrote:
Saturday March 25 2006 9:36 pm, Ed L. wrote:
I have a performance riddle, hoping someone can point me in
a helpful direction. We have a pg 8.1.2 cluster using
Apache::Sessions and experiencing simple UPDATEs taking
sometimes 30+ seconds to do a very simply update, no foreign
keys, no triggers:

Table "public.sessions"
Column | Type | Modifiers
++
id | character(32) | not null
a_session | text |
Indexes:
"sessions_pkey" PRIMARY KEY, btree (id)

The table has 6800 rows over 18000 pages, and is getting a
minimum of many tens of thousands of updates per day with
queries like this:

UPDATE sessions SET a_session = ? WHERE id = ?

Sorry, it's getting late. Yes, the table has been analyzed and
explain shows an index scan is occurring.

Ed

(end of broadcast)
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Saturday March 25 2006 9:55 pm, chris smith wrote:
3/26/06, Ed L. <pgsql (AT) bluepolka (DOT) netwrote:
Saturday March 25 2006 9:36 pm, Ed L. wrote:
I have a performance riddle, hoping someone can point me
in a helpful direction. We have a pg 8.1.2 cluster using
Apache::Sessions and experiencing simple UPDATEs taking
sometimes 30+ seconds to do a very simply update, no
foreign keys, no triggers:

The table has 6800 rows over 18000 pages, and is getting a
minimum of many tens of thousands of updates per day with
queries like this:

If you're updating that much, how often are you running
'analyze'? Are you running autovacuum? How often?

I count on the built-in autovacuum to do do analyzes (per 8.1.2
docs). I'm running autovacuum with the following non-default
parameters:

autovacuum = on
autovacuum_naptime = 600 # 10 minutes

With our set of 4 DBs, that amounts to once every 40 minutes for
the given database. I see "LG: autovacuum: processing
database "xyz"" in the log, but I do not see any analyze/vacuum
commands being issued at all (does it log when it
analyzes/vacuums?).

Thanks,
Ed

(end of broadcast)
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Sunday March 26 2006 7:22 am, Ed L. wrote:
Saturday March 25 2006 9:55 pm, chris smith wrote:
3/26/06, Ed L. <pgsql (AT) bluepolka (DOT) netwrote:
Saturday March 25 2006 9:36 pm, Ed L. wrote:
I have a performance riddle, hoping someone can point me
in a helpful direction. We have a pg 8.1.2 cluster
using Apache::Sessions and experiencing simple UPDATEs
taking sometimes 30+ seconds to do a very simply update,
no foreign keys, no triggers:

The table has 6800 rows over 18000 pages, and is getting a
minimum of many tens of thousands of updates per day with
queries like this:

If you're updating that much, how often are you running
'analyze'? Are you running autovacuum? How often?

I count on the built-in autovacuum to do do analyzes (per
8.1.2 docs). I'm running autovacuum with the following
non-default parameters:

autovacuum = on
autovacuum_naptime = 600 # 10 minutes

I also have these non-default settings:

autovacuum_vacuum_cost_delay = 500
autovacuum_vacuum_cost_limit = 200

Thanks,
Ed

(end of broadcast)
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo (AT) postgresql (DOT) org so that your
message can get through to the mailing list cleanly

"Ed L." <pgsql (AT) bluepolka (DOT) netwrites:
With our set of 4 DBs, that amounts to once every 40 minutes for
the given database. I see "LG: autovacuum: processing
database "xyz"" in the log, but I do not see any analyze/vacuum
commands being issued at all (does it log when it
analyzes/vacuums?).

Not at the default logging level I think you have to go to DEBUG1
or DEBUG2 to get info about per-table actions. (This ought to be
rethought, likely, as that will also clutter your log with a ton of
extraneous info)

regards, tom lane

(end of broadcast)
TIP 5: don't forget to increase your free space map settings

"Ed L." <pgsql (AT) bluepolka (DOT) netwrites:
I see what appear to be many single transactions holding
RowExclusiveLocks for sometimes 40-50 seconds while their query
shows "<IDLEin transaction".

I'm thinking that means the client is simply tweaking a row and
then failing to commit the change for 40-50 seconds. Is that
consistent?

That's what it sounds like to me. You might consider logging all
commands from these clients for awhile so you can check that theory.

regards, tom lane

(end of broadcast)
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

The table has 6800 rows over 18000 pages, and is getting a
minimum of many tens of thousands of updates per day with
queries like this:
If you're updating that much, how often are you running
'analyze'? Are you running autovacuum? How often?
>I count on the built-in autovacuum to do do analyzes (per
>8.1.2 docs). I'm running autovacuum with the following
>non-default parameters:
>>
>autovacuum = on
>autovacuum_naptime = 600 # 10 minutes

I also have these non-default settings:

autovacuum_vacuum_cost_delay = 500
autovacuum_vacuum_cost_limit = 200

Not totally sure, but it sounds like the table isn't getting vacuumed
often enough. To help, you might reduce the naptime from 10 minutes to
5. But I think the cost_delay settings might be the larger problem. If
I remember correctly, even small values here tend to greatly increase
the time it takes vacuum commands to complete, so you might try backing
down those settings. Can you tell from the log files how often
autovacuum is actually taking actions, or how long those actions are taking?

Does anyone out there have any empirical data on good
autovacuumcost_* settings? I would be curious to hear about them.

(end of broadcast)
TIP 5: don't forget to increase your free space map settings