Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WXAf6-0002cg-4G for pgsql-performance@arkaria.postgresql.org; Mon, 07 Apr 2014 14:36:36 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1WXAf5-0003bA-45 for pgsql-performance@arkaria.postgresql.org; Mon, 07 Apr 2014 14:36:35 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WXAf3-0003b4-Vn for pgsql-performance@postgresql.org; Mon, 07 Apr 2014 14:36:34 +0000 Received: from bureau84.ns.utoronto.ca ([128.100.132.184]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WXAev-0008B0-MU for pgsql-performance@postgresql.org; Mon, 07 Apr 2014 14:36:33 +0000 Received: from [192.168.1.114] (76-10-136-105.dsl.teksavvy.com [76.10.136.105]) (authenticated bits=0) by bureau84.ns.utoronto.ca (8.13.8/8.13.8) with ESMTP id s37EaFpS023271 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO) for ; Mon, 7 Apr 2014 10:36:20 -0400 Message-ID: <5342B7DE.3020604@cs.utoronto.ca> Date: Mon, 07 Apr 2014 10:36:14 -0400 From: Ryan Johnson User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20130801 Thunderbird/17.0.8 MIME-Version: 1.0 To: pgsql-performance@postgresql.org Subject: Re: SSI slows down over time References: <5340BB09.5010101@cs.utoronto.ca> <13824.1396796137@sss.pgh.pa.us> In-Reply-To: <13824.1396796137@sss.pgh.pa.us> Content-Type: multipart/alternative; boundary="------------000409030806080409030006" X-Pg-Spam-Score: -2.1 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org This is a multi-part message in MIME format. --------------000409030806080409030006 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit On 06/04/2014 10:55 AM, Tom Lane wrote: > Ryan Johnson 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@mail.gmail.com Thoughts? Ryan --------------000409030806080409030006 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit
On 06/04/2014 10:55 AM, Tom Lane wrote:
Ryan Johnson <ryan.johnson@cs.utoronto.ca> 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@mail.gmail.com

Thoughts?
Ryan

--------------000409030806080409030006--