PAINFUL: Update in sessions table

Folks,

we’ve installed a new RT instance a few days ago and encounter a
painful! slowness in creating tickets.

We are running 3.8.4 on Linux 2.6.18-128.1.10.el5xen #1 SMP Wed Apr
29 14:24:51 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux, Redhat,

Memory
total used free shared buffers cached
Mem: 2883584 2641640 241944 0 23448 474552
-/+ buffers/cache: 2143640 739944
Swap: 524280 0 524280

iostat not worth mentioning

CPU: 2 x Quad-Core AMD Opteron™ Processor 8376 HE

Here’s my pain point:

LOG: duration: 2343.904 ms statement: EXECUTE [PREPARE:
UPDATE sessions SET a_session = $1 WHERE id = $2]
LOG: duration: 999.986 ms statement: EXECUTE [PREPARE:
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]

rt3=# select count(id) from sessions;
count
4739
(1 row)

= nothing in that table…

The table has an index:
sessions_pkey CREATE UNIQUE INDEX sessions_pkey ON sessions USING
btree (id) Primary key

If I do the thing manually, results are a bit better:

rt3=# EXPLAIN ANALYZE select * from sessions where
id=‘014a8b48caa04bcc1538ba91535dddfe’;
QUERY PLAN
Index Scan using sessions_pkey on sessions (cost=0.00…6.01 rows=1
width=172) (actual time=0.034…0.036 rows=1 loops=1)
Index Cond: (id = ‘014a8b48caa04bcc1538ba91535dddfe’::bpchar)
Total runtime: 0.080 ms
(3 rows)

Updating a session is reasonable as well on the db:

rt3=# EXPLAIN ANALYZE UPDATE sessions SET a_session =
'BQcDAAAAAgQRD1JUOjpDdXJyZW50VXNlcgMAAAAEBBEMUlQ6OkkxOE46OmVuAwAAAAAAAAAKTGFu\012Z0hhbmRsZQoFVXNlcnMAAAAFdGFibGUEAwAAAAAAAAAGdmFsdWVzBAMAAAACCIEAAAAEbGFuZwiB\012AAAABG5hbWUAAAAHZmV0Y2hlZAAAAAtDdXJyZW50VXNlcgogMDE0YThiNDhjYWEwNGJjYzE1Mzhi\012YTkxNTM1ZGRkZmUAAAALX3Nlc3Npb25faWQ=\012’
WHERE id=‘014a8b48caa04bcc1538ba91535dddfe’;
QUERY PLAN
Index Scan using sessions_pkey on sessions (cost=0.00…6.01 rows=1
width=146) (actual time=0.042…0.044 rows=1 loops=1)
Index Cond: (id = ‘014a8b48caa04bcc1538ba91535dddfe’::bpchar)
Total runtime: 0.138 ms
(3 rows)

This is from a “clean” test setup, eg no users; I put postgres into
full log mode to get all queries.

grep a_session postgresql-Thu.log_single_creation
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]

During the creation the sessions table gets accessed 6 times, each
taking 1-2 seconds…which accounts 100% for the slowness we are
experiencing.

I’m a bit surprised as I have not seen this behaviour before (ever,
that means “not since 1995” or so ;-)) and wonder what’s going wrong
here.

I did my bit of googling around and could not find the rtfm to fix
that, but if anybody has one, please let me know.

Thanks
Alex

Folks,

we’ve installed a new RT instance a few days ago and encounter a
painful! slowness in creating tickets.

We are running 3.8.4 on Linux 2.6.18-128.1.10.el5xen #1 SMP Wed Apr
29 14:24:51 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux, Redhat,

Memory
total used free shared buffers cached
Mem: 2883584 2641640 241944 0 23448 474552
-/+ buffers/cache: 2143640 739944
Swap: 524280 0 524280

iostat not worth mentioning

CPU: 2 x Quad-Core AMD Opteron™ Processor 8376 HE

Here’s my pain point:

LOG: duration: 2343.904 ms statement: EXECUTE [PREPARE:
UPDATE sessions SET a_session = $1 WHERE id = $2]
LOG: duration: 999.986 ms statement: EXECUTE [PREPARE:
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]

rt3=# select count(id) from sessions;
count

4739
(1 row)

= nothing in that table…

The table has an index:
sessions_pkey CREATE UNIQUE INDEX sessions_pkey ON sessions USING
btree (id) Primary key

If I do the thing manually, results are a bit better:

rt3=# EXPLAIN ANALYZE select * from sessions where
id=‘014a8b48caa04bcc1538ba91535dddfe’;
QUERY PLAN

Index Scan using sessions_pkey on sessions (cost=0.00…6.01 rows=1
width=172) (actual time=0.034…0.036 rows=1 loops=1)
Index Cond: (id = ‘014a8b48caa04bcc1538ba91535dddfe’::bpchar)
Total runtime: 0.080 ms
(3 rows)

Updating a session is reasonable as well on the db:

rt3=# EXPLAIN ANALYZE UPDATE sessions SET a_session =
'BQcDAAAAAgQRD1JUOjpDdXJyZW50VXNlcgMAAAAEBBEMUlQ6OkkxOE46OmVuAwAAAAAAAAAKTGFu\012Z0hhbmRsZQoFVXNlcnMAAAAFdGFibGUEAwAAAAAAAAAGdmFsdWVzBAMAAAACCIEAAAAEbGFuZwiB\012AAAABG5hbWUAAAAHZmV0Y2hlZAAAAAtDdXJyZW50VXNlcgogMDE0YThiNDhjYWEwNGJjYzE1Mzhi\012YTkxNTM1ZGRkZmUAAAALX3Nlc3Npb25faWQ=\012’
WHERE id=‘014a8b48caa04bcc1538ba91535dddfe’;
QUERY PLAN

Index Scan using sessions_pkey on sessions (cost=0.00…6.01 rows=1
width=146) (actual time=0.042…0.044 rows=1 loops=1)
Index Cond: (id = ‘014a8b48caa04bcc1538ba91535dddfe’::bpchar)
Total runtime: 0.138 ms
(3 rows)

This is from a “clean” test setup, eg no users; I put postgres into
full log mode to get all queries.

grep a_session postgresql-Thu.log_single_creation
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]
SELECT a_session FROM sessions WHERE id = $1 FOR UPDATE]
UPDATE sessions SET a_session = $1 WHERE id = $2]

During the creation the sessions table gets accessed 6 times, each
taking 1-2 seconds…which accounts 100% for the slowness we are
experiencing.

I’m a bit surprised as I have not seen this behaviour before (ever,
that means “not since 1995” or so ;-)) and wonder what’s going wrong
here.

I did my bit of googling around and could not find the rtfm to fix
that, but if anybody has one, please let me know.

Thanks
Alex


List info: http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-devel

Just look at sbin/rt-clean-sessions

Chris