PG 9.6 Slow inserts with long-lasting LWLocks

From: Pavel Suderevsky <psuderevsky(at)gmail(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: PG 9.6 Slow inserts with long-lasting LWLocks
Date: 2018-01-22 18:43:32
Message-ID: CAEBTBzuK-zyUXDMvn+Xfh38ZS60-uEFtTomDDFGXahTSoHqQgA@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi,

I have an issue with sporadic slow insert operations with query duration
more than 1 sec while it takes about 50ms in average.

Configuration:
OS: Centos 7.2.151
PostgreSQL: 9.6.3
CPU: Intel(R) Xeon(R) CPU E5-2680 v3 @ 2.50GHz
Memory: total used free shared buff/cache
available
Mem: 193166 10324 1856 44522 180985
137444
Swap: 0 0 0
Storage: Well, about 4gb of BBU write cache.

shared_buffers = 32gb
work_mem = 128mb
max_pred_locks_per_transaction = 8192

This can occur once a day or not happen for few days while system load is
the same. "Inserts" are the prepared statement batches with 4-5 inserts.
Neither excessive memory usage nor disk or cpu utilizations have been
catched.
Wal writing rates, checkpoints, anything else from pg_stat_* tables were
checked and nothing embarrassing was found.

There are several scenarious of such long inserts were spotted:
1. No any locks catched (500ms check intervals)
2. Wait event is "buffer_mapping" - looks like the most common case
snaphot time | state | trx duration | query duration |
wait_event_type | wait_event | query
2017-12-22 03:16:01.181014 | active | 00:00:00.535309 | 00:00:00.524729 |
LWLockTranche | buffer_mapping | INSERT INTO table..
2017-12-22 03:16:00.65814 | active | 00:00:00.012435 | 00:00:00.001855 |
LWLockTranche | buffer_mapping | INSERT INTO table..
3. Wait event is "SerializablePredicateLockListLock" (I believe the same
root cause as previous case)
4. No any locks catched, but ~39 other backends in parallel are active

I assumed that it can be somehow related to enabled NUMA, but it looks like
memory is allocated evenly, zone_reclaim_mode is 0.
numactl --hardware
available: 2 nodes (0-1)
node 0 cpus: 0 2 4 6 8 10 12 14 16 18 20 22 24 26 28 30 32 34 36 38 40 42
44 46
node 0 size: 130978 MB
node 0 free: 1251 MB
node 1 cpus: 1 3 5 7 9 11 13 15 17 19 21 23 25 27 29 31 33 35 37 39 41 43
45 47
node 1 size: 65536 MB
node 1 free: 42 MB
node distances:
node 0 1
0: 10 21
1: 21 10

numastat -m

Per-node system memory usage (in MBs):
Node 0 Node 1 Total
--------------- --------------- ---------------
MemTotal 130978.34 65536.00 196514.34
MemFree 1479.07 212.12 1691.20
MemUsed 129499.27 65323.88 194823.14
Active 72241.16 37254.56 109495.73
Inactive 47936.24 24205.40 72141.64
Active(anon) 21162.41 18978.96 40141.37
Inactive(anon) 1061.94 7522.34 8584.27
Active(file) 51078.76 18275.60 69354.36
Inactive(file) 46874.30 16683.06 63557.36
Unevictable 0.00 0.00 0.00
Mlocked 0.00 0.00 0.00
Dirty 0.04 0.02 0.05
Writeback 0.00 0.00 0.00
FilePages 116511.36 60923.16 177434.52
Mapped 16507.29 23912.82 40420.11
AnonPages 3661.55 530.26 4191.81
Shmem 18558.28 25964.74 44523.02
KernelStack 16.98 5.77 22.75
PageTables 3943.56 1022.25 4965.81
NFS_Unstable 0.00 0.00 0.00
Bounce 0.00 0.00 0.00
WritebackTmp 0.00 0.00 0.00
Slab 2256.09 1291.53 3547.61
SReclaimable 2108.29 889.85 2998.14
SUnreclaim 147.80 401.68 549.47
AnonHugePages 1824.00 284.00 2108.00
HugePages_Total 0.00 0.00 0.00
HugePages_Free 0.00 0.00 0.00
HugePages_Surp 0.00 0.00 0.00

$ cat /proc/62679/numa_maps | grep N0 | grep zero
7f92509d3000 prefer:0 file=/dev/zero\040(deleted) dirty=8419116 mapmax=154
active=8193350 N0=3890534 N1=4528582 kernelpagesize_kB=4

Could you advise what can cause such occasional long inserts with
long-lasting LWlocks?

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message pavan95 2018-01-23 07:04:52 Re: 8.2 Autovacuum BUG ?
Previous Message Andreas Kretschmer 2018-01-22 11:47:10 Re: 8.2 Autovacuum BUG ?