[Rt-devel] PAINFUL: Update in sessions table

[Alexander Finger]

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(tm) Processor 8376 HE


Here's my pain point:

LOG:  duration: 2343.904 ms  statement: EXECUTE <unnamed>  [PREPARE:
                        UPDATE sessions SET a_session = $1 WHERE id = $2]
LOG:  duration: 999.986 ms  statement: EXECUTE <unnamed>  [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