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