PG 9.6 Slow inserts with long-lasting LWLocks

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?