Re: SSI slows down over time

[Ryan Johnson <ryan.johnson@xxxxxxxxxxxxxx>]

On 06/04/2014 10:55 AM, Tom Lane wrote:

Ryan Johnson <ryan.johnson@xxxxxxxxxxxxxx> writes:

I get a strange behavior across repeated runs: each 100-second run is a 
bit slower than the one preceding it, when run with SSI (SERIALIZABLE). 
... So the question: what should I look for to diagnose/triage this problem? 

In the past I've seen behaviors like this that traced to the range of
"interesting" transaction IDs getting wider as time went on, so that
more pages of pg_clog were hot, leading to more I/O traffic in the
clog SLRU buffers.  Possibly this is some effect like that.

The effect disappears completely if I run under SI instead of SSI, though. That makes me suspect strongly that the problem lurks in SSI-specific infrastrucure.

However, I did notice that the SLRU buffer that holds "old" SSI transactions sometimes spikes from hundreds to millions of entries (by annotating the source to ereport a warning whenever the difference between head and tail is at least 10% higher than the previous record). Not sure if that's related, though: I'm pretty sure SSI never scans SLRU, it's only used for random lookups.

I've tried linux perf, but all it says is that lots of time is going to 
LWLock (but callgraph tracing doesn't work in my not-bleeding-edge 
kernel).

You could recompile with -DLWLOCK_STATS to enable gathering stats on
which LWLocks are heavily contended.  That would be a starting point
for localizing the cause.

Here are the offenders (100-second run, 24 clients, ~2.2ktps):

lwlock        7 shacq         0 exacq 7002810 blk  896235 spindelay  213
lwlock       28 shacq  94984166 exacq   3938085 blk 572762 spindelay  163
lwlock       65 shacq   3347000 exacq   2933440 blk 255927 spindelay   90
lwlock       79 shacq   1742574 exacq   3009663 blk 216178 spindelay   41
lwlock       76 shacq   2293386 exacq   2892242 blk 205199 spindelay   70
lwlock       66 shacq    498909 exacq   2987485 blk 171508 spindelay   48
lwlock       80 shacq    512107 exacq   3181753 blk 165772 spindelay   43
lwlock       71 shacq    815733 exacq   3088157 blk 165579 spindelay   48
lwlock       74 shacq    603321 exacq   3065391 blk 159953 spindelay   56
lwlock       67 shacq    695465 exacq   2918970 blk 149339 spindelay   28
lwlock       69 shacq    411203 exacq   3044007 blk 148655 spindelay   34
lwlock       72 shacq    515260 exacq   2973321 blk 147533 spindelay   43
lwlock       30 shacq  41628636 exacq      8799 blk 143889 spindelay  186
lwlock       75 shacq    409472 exacq   2987227 blk 143196 spindelay   38
lwlock       77 shacq    409401 exacq   2946972 blk 139507 spindelay   34
lwlock       73 shacq    402544 exacq   2943467 blk 139380 spindelay   43
lwlock       78 shacq    404220 exacq   2912665 blk 137625 spindelay   21
lwlock       70 shacq    603643 exacq   2816730 blk 135851 spindelay   37
lwlock       68 shacq    403533 exacq   2862017 blk 131946 spindelay   30
lwlock       29 shacq         0 exacq    255302 blk 75838 spindelay    1
lwlock        0 shacq         0 exacq    561508 blk 12445 spindelay    3
lwlock       11 shacq   1245499 exacq    219717 blk 5501 spindelay   10
lwlock        4 shacq    381211 exacq    209146 blk 1273 spindelay    4
lwlock        3 shacq        16 exacq    209081 blk 522 spindelay    0
lwlock        8 shacq         0 exacq    137961 blk 50 spindelay    0
lwlock  2097366 shacq         0 exacq    384586 blk 1 spindelay    0
lwlock  2097365 shacq         0 exacq    370176 blk 1 spindelay    0
lwlock  2097359 shacq         0 exacq    363845 blk 1 spindelay    0

The above aggregates the per-lock stats from all processes, filters out locks with fewer than 10000 accesses (shared+exclusive) or with zero blk, then sorts by highest blk first.

According to [1], locks {28, 29, 30} are {SerializableXactHashLock, SerializableFinishedListLock, SerializablePredicateLockListLock}, all SSI-related; locks 65-80 are the sixteen PredicateLockMgrLocks that the post mentions. Looking in lwlock.h, lock 7 (which tops the list) is the WALInsertLock. That lock was *not* mentioned in the pgsql-hackers post.

Re-running the same analysis for SI instead of SSI gives 4.6ktps and a much shorter list:

lwlock        7 shacq         0 exacq 14050121 blk  3429384 spindelay  347
lwlock       11 shacq   3133994 exacq    450325 blk 23456 spindelay   29
lwlock        0 shacq         0 exacq    684775 blk 19158 spindelay    3
lwlock        4 shacq    780846 exacq    428771 blk 4539 spindelay    6
lwlock        3 shacq        19 exacq    428705 blk 1147 spindelay    0
lwlock       59 shacq         0 exacq    125943 blk 203 spindelay    0
lwlock        8 shacq         0 exacq    287629 blk 116 spindelay    0
lwlock  2097358 shacq         0 exacq    752361 blk 1 spindelay    0
lwlock  2097355 shacq         0 exacq    755086 blk 1 spindelay    0
lwlock  2097352 shacq         0 exacq    760232 blk 1 spindelay    0

However, all of this only confirms that SSI has a lock bottleneck; it doesn't say why the bottleneck gets worse over time.

[1] http://www.postgresql.org/message-id/CA+TgmoYAiSM2jWEndReY5PL0sKbhgg7dbDH6r=oXKYzi9B7KJA@xxxxxxxxxxxxxx

Thoughts?
Ryan