[Rt-devel] PAINFUL: Update in sessions table

[Christian Loos]

Am 01.04.2010 17:40, schrieb 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
> _______________________________________________
> List info: http://lists.bestpractical.com/cgi-bin/mailman/listinfo/rt-devel
> 
Just look at sbin/rt-clean-sessions

Chris