Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1exyZY-0003fb-3W for pgsql-performance@arkaria.postgresql.org; Mon, 19 Mar 2018 17:27:48 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1exyZW-0005bo-Ro for pgsql-performance@arkaria.postgresql.org; Mon, 19 Mar 2018 17:27:46 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1exyYS-0007q3-JJ for pgsql-performance@lists.postgresql.org; Mon, 19 Mar 2018 17:26:41 +0000 Received: from mail-lf0-x232.google.com ([2a00:1450:4010:c07::232]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1exyYO-0004AO-6Y for pgsql-performance@postgresql.org; Mon, 19 Mar 2018 17:26:38 +0000 Received: by mail-lf0-x232.google.com with SMTP id e5-v6so22632207lfb.7 for ; Mon, 19 Mar 2018 10:26:35 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=message-id:mime-version:to:cc:from:subject:date:importance :in-reply-to:references; bh=R0eM/5H3wLFe+8Qxc6GPmXUj0kUArAYDOKY9WXpL6CE=; b=OupfFOYd7DsEbQvfvQ2+RyDJtvy3QnSPsG9FNdoqbVNfo4rOOC07EJBVWbWRnpJuIB NrwzzzUC3yu12RI53NGVBx0PFBk+nrrLUJ2vwfUucoXMnsmyAJe+IAo7PbfhpW9F1XR1 pVAcAkCSEHVW07BTl2dyxvOrxPjQkniaJ8GtsZUgTRMk5ha/c/REgY8KaxWIf7Zwdd+Q r+lxF9Ont9fEY9ZFS8dcMbO+FleNtXgYkx5HOAEmnf5eSB9iD8nGFdWLMGhA6KgLVASe tHY6uJFDAnZDLF6aT4C9TAU9LLcGWeWwHaeSGwBnXftLrm6T1kAKFO3v5v4RZUUPtuIG XjZQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:message-id:mime-version:to:cc:from:subject:date :importance:in-reply-to:references; bh=R0eM/5H3wLFe+8Qxc6GPmXUj0kUArAYDOKY9WXpL6CE=; b=GU2jmH4uJ3Mw8mjPYiqk6/vuLxmNaEaKL5wu/NOFfWHCmsfvG7caB8FDRMnHpUng5F bdZksCJGDyub1gBS53cNE4FYiHBq7Iq7wJ9nXCWH+3pTamcmvalxho+Akzqy83u/6bRO /Fh0qJor01vgLvlKrl4g6BoUCe3pNM8JvmAsfgNx7VU0SbPLM/ZObo1T7nlauPwLnQ9Y iaA2+Qvtxy5KJbdLYCz0HLRgtXR/oS6r+ax9m4xB3mleBRQt59pQUA12OdoTMxkfYD+N EyM5pB+PTHDvkwyDkIKlPO6XhZ7NigqJWCOD2PAYWKJlSem+Co9xwVTTUMDDbRpsFDEY g19A== X-Gm-Message-State: AElRT7EhA0QhDVWmcUjw048f4eVvPt3SNmvbLBxNcUWyO48uDPnKV0h4 NB/j6kxVpXqCS773qpGeK0s= X-Google-Smtp-Source: AG47ELsN3EvhjmI45NWGIrWeZIpVqTTdWpNtOYxV+d1wvC0tSaN27BG+L6RGwqByvShjsWcQmWnXxA== X-Received: by 10.46.116.4 with SMTP id p4mr8912839ljc.101.1521480393459; Mon, 19 Mar 2018 10:26:33 -0700 (PDT) Received: from ?IPv6:::ffff:192.168.16.152? ([89.113.128.32]) by smtp.gmail.com with ESMTPSA id f9sm104256ljf.29.2018.03.19.10.26.32 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Mon, 19 Mar 2018 10:26:32 -0700 (PDT) Message-ID: <5aaff2c8.091f2e0a.ee235.0af0@mx.google.com> MIME-Version: 1.0 To: MichaelDBA Cc: "pgsql-performance@postgresql.org" From: Pavel Suderevsky Subject: RE: PG 9.6 Slow inserts with long-lasting LWLocks Date: Mon, 19 Mar 2018 20:26:32 +0300 Importance: normal X-Priority: 3 In-Reply-To: <5AABC9CA.1040709@sqlexec.com> References: <5aaa4b0d.cc562e0a.307ea.65eb@mx.google.com> <5AABC9CA.1040709@sqlexec.com> Content-Type: multipart/alternative; boundary="_2FED6C58-B5FC-4EC0-80DA-E66956AE1D12_" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --_2FED6C58-B5FC-4EC0-80DA-E66956AE1D12_ Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" Michael, thanks for your answer.=20 Looks like it is not my case because issue is reproducible also for table w= ith 100% single writer backend. Also as it was mentioned whole system gets = hung.=20 Regards, Pavel Suderevsky From: MichaelDBA Sent: Friday, March 16, 2018 16:42 To: Pavel Suderevsky Cc: pgsql-performance@postgresql.org Subject: Re: PG 9.6 Slow inserts with long-lasting LWLocks Sporadic insert slowness could be due to lock delays (locktype=3Dextend) du= e to many concurrent connections trying to insert into the same table at th= e same time. Each insert request may result in an extend lock (8k extension= ), which blocks other writers. What normally happens is the these extend lo= cks happen so fast that you hardly ever see them in the pg_locks table, exc= ept in the case where many concurrent connections are trying to do inserts = into the same table. The following query will show if this is the case if y= ou execute it during the time the problem is occurring. select * from pg_locks where granted =3D false and locktype =3D 'extend'; I don't know if this is your particular problem, but perhaps it is. Regards, Michael Vitale Pavel Suderevsky Thursday, March 15, 2018 6:29 AM Hi,=20 =C2=A0 Well, unfortunately I still need community help. =C2=A0 -- Environment OS: Centos CentOS Linux release 7.2.1511 Kernel:=C2=A0 3.10.0-327.36.3.el7.x86_64 PostgreSQL: 9.6.3 -- Hardware Server: Dell PowerEdge R430 CPU: Intel(R) Xeon(R) CPU E5-2680 v3 @ 2.50GHz Raid controller: PERC H730 Mini (1GB cache) Disks: 8 x 10K RPM SAS 12GB/s 2.5 (ST1200MM0088) in RAID 6 RAM: 192GB (M393A2G40DB0-CPB x 16) For more detailed hardware info please see attached configuration.txt -- postgresql.conf max_connections =3D 2048 shared_buffers =3D 48GB temp_buffers =3D 128MB work_mem =3D 256MB maintenance_work_mem =3D 512MB dynamic_shared_memory_type =3D posix wal_level =3D hot_standby min_wal_size =3D 4GB max_wal_size =3D 32GB huge_pages =3D on + numactl interleave=3Dall -- sysctl.conf=20 kernel.shmmax=3D64424509440 kernel.shmall=3D4294967296 kernel.sem =3D 1024 32767 128 16384 fs.aio-max-nr=3D3145728 fs.file-max =3D 6815744 net.core.rmem_default=3D262144 net.core.rmem_max=3D4194304 net.core.wmem_default=3D262144 net.core.wmem_max=3D1048586 vm.nr_hugepages=3D33000 vm.dirty_background_bytes=3D67108864 vm.dirty_bytes=3D536870912 vm.min_free_kbytes=3D1048576 zone_reclaim_mode=3D0 =C2=A0 Again: problem is the occasional long inserts that can happen 1-5 times per= day on OLTP system. No autovacuum performed during long inserts. WAL rate is 1-2Gb per hour, no= correlation spotted with this issue. Wait event "buffer_mapping" happen for appropriate transactions but not eve= ry time (maybe just not every time catched). I have two suspects for such behaviour: I/O system and high concurrency. There is a problem with one application that frequently recreates up to 90 = sessions but investigation shows that there is no direct correlation betwee= n such sessions and long transactions, at least it is not the root cause of= the issue (of course such app behaviour will be fixed). =C2=A0 The investigation and tracing with strace in particular showed that: 1. The only long event straced from postgres backends was <... semop resume= d>. 2. Seems the whole host gets hung during such events.=20 =C2=A0 Example: Java application located on separate host reports several long transactions= : 123336.943 - [1239588mks]: event.insert-table 123336.943 - [1240827mks]: event.insert-table 123337.019 - [1292534mks]: event.insert-table 143353.542 - [5467657mks]: event.insert-table 143353.543 - [5468884mks]: event.insert-table 152338.763 - [1264588mks]: event.insert-table 152338.765 - [2054887mks]: event.insert-table =C2=A0 Strace output for event happened at 14:33 with particular known pid: 119971 14:33:48.075375 epoll_wait(3,=C2=A0 119971 14:33:48.075696 <... epoll_wait resumed> {{EPOLLIN, {u32=3D27532016,= u64=3D27532016}}}, 1, -1) =3D 1 <0.000313> 119971 14:33:48.075792 recvfrom(9,=C2=A0 119971 14:33:48.075866 <... recvfrom resumed> "B\0\0\3\27\0S_21\0\0*\0\1\0\= 1\0\1\0\0\0\0\0\1\0\1\0\0\0\0\0"..., 8192, 0, NULL, NULL) =3D 807 <0.000066= > 119971 14:33:48.076243 semop(26706044, {{8, -1, 0}}, 1 120019 14:33:48.119971 recvfrom(9,=C2=A0 119971 14:33:53.491029 <... semop resumed> ) =3D 0 <5.414772>=20 119971 14:33:53.500356 lseek(18, 0, SEEK_END 119971 14:33:53.500436 <... lseek resumed> ) =3D 107790336 <0.000072> 119971 14:33:53.500514 lseek(20, 0, SEEK_END =C2=A0 Checking strace long semop calls for whole day: root@host [20180314 17:47:36]:/home/user$ egrep " <[1-9]." /tmp/strace | gr= ep semop 119991 12:33:36 <... semop resumed> )=C2=A0=C2=A0 =3D 0 <1.419394> 119942 12:33:36 <... semop resumed> )=C2=A0=C2=A0 =3D 0 <1.422554> 119930 12:33:36 <... semop resumed> )=C2=A0=C2=A0 =3D 0 <1.414916> 119988 12:33:36 <... semop resumed> )=C2=A0=C2=A0 =3D 0 <1.213309> 119966 12:33:36 <... semop resumed> )=C2=A0=C2=A0 =3D 0 <1.237492> 119958 14:33:53.489398 <... semop resumed> ) =3D 0 <5.455830> 120019 14:33:53.490613 <... semop resumed> ) =3D 0 <5.284505> 119997 14:33:53.490638 <... semop resumed> ) =3D 0 <5.111661> 120000 14:33:53.490649 <... semop resumed> ) =3D 0 <3.521992> 119991 14:33:53.490660 <... semop resumed> ) =3D 0 <2.522460> 119988 14:33:53.490670 <... semop resumed> ) =3D 0 <5.252485> 120044 14:33:53.490834 <... semop resumed> ) =3D 0 <1.718129> 119976 14:33:53.490852 <... semop resumed> ) =3D 0 <2.489563> 119974 14:33:53.490862 <... semop resumed> ) =3D 0 <1.520801> 119984 14:33:53.491011 <... semop resumed> ) =3D 0 <1.213411> 119971 14:33:53.491029 <... semop resumed> ) =3D 0 <5.414772> 119969 14:33:53.491039 <... semop resumed> ) =3D 0 <2.275608> 119966 14:33:53.491048 <... semop resumed> ) =3D 0 <2.526024> 119942 14:33:53.491058 <... semop resumed> ) =3D 0 <5.448506> 119964 15:23:38.746394 <... semop resumed> ) =3D 0 <2.034851> 119960 15:23:38.746426 <... semop resumed> ) =3D 0 <2.038321> 119966 15:23:38.752646 <... semop resumed> ) =3D 0 <1.252342> =C2=A0 Also it was spotted that WALWriter Postgres backend also spend time in during hangs. =C2=A0 Also I have application on db host that performs pg_stat_activity shapshots= every 500m and for example I can see that there were no snapshot between 1= 4:33:47 and 14:33:53. Separate simple script on db host every ~100ms checks ps output for this ap= plication and writes it into the txt file. And we can see that while it usu= ally performs about 7-8 times per second, between 14:33:47 and 14:33:53 it = couldn't even perform enough ps calls. Strace for this backend showed that = this process was hung in semop call. So it tells me that whole system gets = hung. 14:33:40 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:41 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:42 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:43 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:44 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:45 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:46 TOTAL=3D6 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:47 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:48 TOTAL=3D3 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:49 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:50 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:51 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:52 TOTAL=3D4 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:53 TOTAL=3D6 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:54 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 14:33:55 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_reques= t=3D0 sleep_on_buffer=3D0 =C2=A0 I understand that RAID-6 is not the best option, but I can't catch any evid= ence telling that system run out of 1GB RAID controller cache on writes. =C2=A0 Please assist in understanding meaning and nature of long semop calls appea= rances. =C2=A0 -- Regards, Pavel Suderevsky =C2=A0 =C2=A0 =C2=A0 From: Pavel Suderevsky Sent: Monday, January 22, 2018 21:43 To: pgsql-performance@postgresql.org Subject: PG 9.6 Slow inserts with long-lasting LWLocks =C2=A0 Hi, =C2=A0 I have an issue with sporadic slow insert operations with query duration mo= re than 1 sec while it takes about 50ms in average. =C2=A0 Configuration: OS: Centos 7.2.151 PostgreSQL: 9.6.3 CPU: Intel(R) Xeon(R) CPU E5-2680 v3 @ 2.50GHz Memory:=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0total=C2=A0 =C2=A0 =C2=A0 = =C2=A0 used=C2=A0 =C2=A0 =C2=A0 =C2=A0 free=C2=A0 =C2=A0 =C2=A0 shared=C2= =A0 =C2=A0 =C2=A0buff/cache=C2=A0 available =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 Mem:=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0193166=C2=A0 =C2=A0 = =C2=A0 =C2=A010324=C2=A0 =C2=A0 =C2=A0 =C2=A0 1856=C2=A0 =C2=A0 =C2=A0 4452= 2=C2=A0 =C2=A0 =C2=A0 180985=C2=A0 =C2=A0 =C2=A0 137444 =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 Swap:=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A00=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A00 Storage: Well,=C2=A0 about 4gb of BBU write cache. =C2=A0 shared_buffers =3D 32gb work_mem =3D 128mb max_pred_locks_per_transaction =3D 8192 =C2=A0 This can occur once a day or not happen for few days while system load is t= he same. "Inserts" are the prepared statement batches with 4-5 inserts. Neither excessive memory usage nor disk or cpu utilizations have been catch= ed. Wal writing rates, checkpoints, anything else from pg_stat_* tables were ch= ecked and nothing embarrassing was found. =C2=A0 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 =C2=A0snaphot time=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0 | state=C2=A0 | trx duration=C2=A0 =C2=A0 | query = duration=C2=A0 =C2=A0| wait_event_type | wait_event=C2=A0 =C2=A0 =C2=A0| qu= ery =C2=A02017-12-22 03:16:01.181014 | active | 00:00:00.535309 | 00:00:00.5247= 29=C2=A0 | LWLockTranche=C2=A0 =C2=A0| buffer_mapping | INSERT INTO table.. =C2=A02017-12-22 03:16:00.65814=C2=A0 | active | 00:00:00.012435 | 00:00:00= .001855=C2=A0 | LWLockTranche=C2=A0 =C2=A0| buffer_mapping | INSERT INTO ta= ble.. 3. Wait event is "SerializablePredicateLockListLock" (I believe the same ro= ot cause as previous case) 4. No any locks catched, but ~39 other backends in parallel are active=C2= =A0 =C2=A0 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 4= 4 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 4= 5 47 node 1 size: 65536 MB node 1 free: 42 MB node distances: node=C2=A0 =C2=A00=C2=A0 =C2=A01=C2=A0 =C2=A0 0:=C2=A0 10=C2=A0 21=C2=A0 =C2=A0 1:=C2=A0 21=C2=A0 10=C2=A0 =C2=A0=C2=A0 numastat -m =C2=A0 Per-node system memory usage (in MBs): =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 Node 0=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 Node 1=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Total =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-------------= -- --------------- --------------- MemTotal=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0130978.34=C2= =A0 =C2=A0 =C2=A0 =C2=A0 65536.00=C2=A0 =C2=A0 =C2=A0 =C2=A0196514.34 MemFree=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 1479.= 07=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 212.12=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A01691.20 MemUsed=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 129499.27=C2= =A0 =C2=A0 =C2=A0 =C2=A0 65323.88=C2=A0 =C2=A0 =C2=A0 =C2=A0194823.14 Active=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 72241.= 16=C2=A0 =C2=A0 =C2=A0 =C2=A0 37254.56=C2=A0 =C2=A0 =C2=A0 =C2=A0109495.73 Inactive=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 47936.24=C2= =A0 =C2=A0 =C2=A0 =C2=A0 24205.40=C2=A0 =C2=A0 =C2=A0 =C2=A0 72141.64 Active(anon)=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 21162.41=C2=A0 =C2=A0= =C2=A0 =C2=A0 18978.96=C2=A0 =C2=A0 =C2=A0 =C2=A0 40141.37 Inactive(anon)=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A01061.94=C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A07522.34=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A08584.27 Active(file)=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 51078.76=C2=A0 =C2=A0= =C2=A0 =C2=A0 18275.60=C2=A0 =C2=A0 =C2=A0 =C2=A0 69354.36 Inactive(file)=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 46874.30=C2=A0 =C2=A0 =C2= =A0 =C2=A0 16683.06=C2=A0 =C2=A0 =C2=A0 =C2=A0 63557.36 Unevictable=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A00.= 00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 =C2=A0 0.00 Mlocked=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A00.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00 Dirty=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A00.04=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.02=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.05 Writeback=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A00.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 0.00 FilePages=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 116511.36=C2=A0 = =C2=A0 =C2=A0 =C2=A0 60923.16=C2=A0 =C2=A0 =C2=A0 =C2=A0177434.52 Mapped=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 16507.= 29=C2=A0 =C2=A0 =C2=A0 =C2=A0 23912.82=C2=A0 =C2=A0 =C2=A0 =C2=A0 40420.11 AnonPages=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 3661.55=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 530.26=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0419= 1.81 Shmem=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A01= 8558.28=C2=A0 =C2=A0 =C2=A0 =C2=A0 25964.74=C2=A0 =C2=A0 =C2=A0 =C2=A0 4452= 3.02 KernelStack=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 16.98=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 5.77=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A022.75 PageTables=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A03943.56=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A01022.25=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0496= 5.81 NFS_Unstable=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 0.00 Bounce=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 0.00 WritebackTmp=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 0.00 Slab=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A02256.09=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A01291.53=C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A03547.61 SReclaimable=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A02108.29=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 889.85=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A02998.14 SUnreclaim=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 147.80=C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 401.68=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 54= 9.47 AnonHugePages=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 1824.00=C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0 284.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A02108.00 HugePages_Total=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A00.00=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 0.00 HugePages_Free=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 0.00 HugePages_Surp=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 0.00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 0.00 =C2=A0 $ cat /proc/62679/numa_maps | grep N0 | grep zero 7f92509d3000 prefer:0 file=3D/dev/zero\040(deleted) dirty=3D8419116 mapmax= =3D154 active=3D8193350 N0=3D3890534 N1=3D4528582 kernelpagesize_kB=3D4 =C2=A0 Could you advise what can cause such occasional long inserts with long-last= ing LWlocks? =C2=A0 =C2=A0 --_2FED6C58-B5FC-4EC0-80DA-E66956AE1D12_ Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset="utf-8"

Michael,= thanks for your answer.

Looks l= ike it is not my case because issue is reproducible also for table with 100= % single writer backend. Also as it was mentioned whole system gets hung. <= /p>

 

Regards,<= /p>

Pavel Suderevsky

 = ;

From: MichaelDBA
Sent: Friday, March 16, 2018 16:42
= To: Pavel Suderevsky
Cc: pgsql-performa= nce@postgresql.org
Subject: Re: PG 9.6 Slow inserts with long= -lasting LWLocks

 

Sp= oradic insert slowness could be due to lock delays (locktype=3Dextend) due = to many concurrent connections trying to insert into the same table at the = same time. Each insert request may result in an extend lock (8k extension),= which blocks other writers. What normally happens is the these extend lock= s happen so fast that you hardly ever see them in the pg_locks table, excep= t in the case where many concurrent connections are trying to do inserts in= to the same table. The following query will show if this is the case if you= execute it during the time the problem is occurring.

= 
select * from pg_locks where granted =3D false and locktype =3D '=
extend';


I don't know if this is your particular problem, but perhap= s it is.

Regards,
Michael Vitale

=

T= hursday, March 15, 2018 6:29 AM

Hi, =

 

Well, unfortunat= ely I still need community help.

=  

-- Environment

OS: Centos CentOS Linux relea= se 7.2.1511

Kernel:  3.10.0-327.36.3.el7.x86_64

PostgreSQL: 9.6.3=

-- Hardware

Serv= er: Dell PowerEdge R430

CPU: Intel(R) Xeon(R) CPU E5-2680 v3 @ 2.50GHz

Raid contr= oller: PERC H730 Mini (1GB cache)

Disks: 8 x 10K RPM SAS 12GB/s 2.5 (ST1200MM0= 088) in RAID 6

RAM: 192GB (M393A2G40DB0-CPB x 16)

For more detailed hardware info= please see attached configuration.txt

-- postgresql.conf

max_connections =3D 204= 8

s= hared_buffers =3D 48GB

temp_buffers =3D 128MB

work_mem =3D 256MB

maintenance_work_me= m =3D 512MB

dynamic_shared_memory_type =3D posix

wal_level =3D hot_standby

min_wal_s= ize =3D 4GB

max_wal_size =3D 32GB

huge_pages =3D on

+

numactl interleave=3Dall

-- sysctl.= conf

kernel.shmmax=3D64424509440

kernel.shmall=3D4294967296

kernel.sem =3D 1024 327= 67 128 16384

fs.aio-max-nr=3D3145728

fs.file-max =3D 6815744

net.core.rmem_default= =3D262144

net.core.rmem_max=3D4194304

net.core.wmem_default=3D262144

net.core.wmem_m= ax=3D1048586

vm.nr_hugepages=3D33000

vm.dirty_background_bytes=3D67108864

vm.dirty_b= ytes=3D536870912

vm.min_free_kbytes=3D1048576

zone_reclaim_mode=3D0

 

Again: probl= em is the occasional long inserts that can happen 1-5 times per day on OLTP= system.

No autovacuum performed during long inserts. WAL rate is 1-2Gb per ho= ur, no correlation spotted with this issue.

Wait event "buffer_mapping&= quot; happen for appropriate transactions but not every time (maybe just no= t every time catched).

I have two suspects for such behaviour: I/O system and = high concurrency.

There is a problem with one application that frequently recr= eates up to 90 sessions but investigation shows that there is no direct cor= relation between such sessions and long transactions, at least it is not th= e root cause of the issue (of course such app behaviour will be fixed).

 =

Th= e investigation and tracing with strace in particular showed that:

1. The only= long event straced from postgres backends was <... semop resumed>.

2. S= eems the whole host gets hung during such events.

 

Example:

Java application = located on separate host reports several long transactions:

123336.943 - [1239= 588mks]: event.insert-table

123336.943 - [1240827mks]: event.insert-table=

123337.= 019 - [1292534mks]: event.insert-table

143353.542 - [5467657mks]: event.insert= -table

143353.543 - [5468884mks]: event.insert-table

152338.763 - [1264588mks]: e= vent.insert-table

152338.765 - [2054887mks]: event.insert-table

 =

Strace output= for event happened at 14:33 with particular known pid:

119971 14:33:48.075375= epoll_wait(3,  <unfinished ...>

119971 14:33:48.075696 <... e= poll_wait resumed> {{EPOLLIN, {u32=3D27532016, u64=3D27532016}}}, 1, -1)= =3D 1 <0.000313>

119971 14:33:48.075792 recvfrom(9,  <unfinishe= d ...>

119971 14:33:48.075866 <... recvfrom resumed> "B\0\0\3\27= \0S_21\0\0*\0\1\0\1\0\1\0\0\0\0\0\1\0\1\0\0\0\0\0"..., 8192, 0, NULL, = NULL) =3D 807 <0.000066>

119971 14:33:48.076243 semop(26706044, {{8, -1,= 0}}, 1 <unfinished ...>

120019 14:33:48.119971 recvfrom(9,  <un= finished ...>

119971 14:33:53.491029 <... semop resumed> ) =3D 0 <= 5.414772>

119971 14:33:53.500356 lseek(18, 0, SEEK_END <unfinished ...&= gt;

119971 14:33:53.500436 <... lseek resumed> ) =3D 107790336 <0.000= 072>

119971 14:33:53.500514 lseek(20, 0, SEEK_END <unfinished ...>

 = ;

C= hecking strace long semop calls for whole day:

root@host [20180314 17:47:36]:/= home/user$ egrep " <[1-9]." /tmp/strace | grep semop

119991 12:33= :36 <... semop resumed> )   =3D 0 <1.419394>

119942 12:3= 3:36 <... semop resumed> )   =3D 0 <1.422554>

119930 12:= 33:36 <... semop resumed> )   =3D 0 <1.414916>

119988 12= :33:36 <... semop resumed> )   =3D 0 <1.213309><= /o:p>

119966 1= 2:33:36 <... semop resumed> )   =3D 0 <1.237492>=

119958 = 14:33:53.489398 <... semop resumed> ) =3D 0 <5.455830>

120019 14:3= 3:53.490613 <... semop resumed> ) =3D 0 <5.284505>

119997 14:33:53= .490638 <... semop resumed> ) =3D 0 <5.111661>

120000 14:33:53.490= 649 <... semop resumed> ) =3D 0 <3.521992>

119991 14:33:53.490660 = <... semop resumed> ) =3D 0 <2.522460>

119988 14:33:53.490670 <= ... semop resumed> ) =3D 0 <5.252485>

120044 14:33:53.490834 <... = semop resumed> ) =3D 0 <1.718129>

119976 14:33:53.490852 <... semo= p resumed> ) =3D 0 <2.489563>

119974 14:33:53.490862 <... semop re= sumed> ) =3D 0 <1.520801>

119984 14:33:53.491011 <... semop resume= d> ) =3D 0 <1.213411>

119971 14:33:53.491029 <... semop resumed>= ; ) =3D 0 <5.414772>

119969 14:33:53.491039 <... semop resumed> ) = =3D 0 <2.275608>

119966 14:33:53.491048 <... semop resumed> ) =3D = 0 <2.526024>

119942 14:33:53.491058 <... semop resumed> ) =3D 0 &l= t;5.448506>

119964 15:23:38.746394 <... semop resumed> ) =3D 0 <2.= 034851>

119960 15:23:38.746426 <... semop resumed> ) =3D 0 <2.0383= 21>

119966 15:23:38.752646 <... semop resumed> ) =3D 0 <1.252342&g= t;

=  

Also it was spotted that WALWriter Postgres backend also spend time in = <semop resumed> during hangs.

 

Also I have application on db host tha= t performs pg_stat_activity shapshots every 500m and for example I can see = that there were no snapshot between 14:33:47 and 14:33:53.

Separate simple scr= ipt on db host every ~100ms checks ps output for this application and write= s it into the txt file. And we can see that while it usually performs about= 7-8 times per second, between 14:33:47 and 14:33:53 it couldn't even perfo= rm enough ps calls. Strace for this backend showed that this process was hu= ng in semop call. So it tells me that whole system gets hung.

14:33:40 TOTAL= =3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_on= _buffer=3D0

14:33:41 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 g= et_request=3D0 sleep_on_buffer=3D0

14:33:42 TOTAL=3D7 wait_transaction_locked= =3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0

14:33:43 TOTAL=3D7 = wait_transaction_locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buff= er=3D0

14:33:44 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 get_re= quest=3D0 sleep_on_buffer=3D0

14:33:45 TOTAL=3D7 wait_transaction_locked=3D0 s= leep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0

<= p class=3DMsoNormal>14:33:46 TOTAL=3D6 wait_t= ransaction_locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0=

14= :33:47 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_request= =3D0 sleep_on_buffer=3D0

14:33:48 TOTAL=3D3 wait_transaction_locked=3D0 sleep_= on_page=3D0 get_request=3D0 sleep_on_buffer=3D0

14:33:49 TOTAL=3D2 wait_transa= ction_locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0=

14:33:5= 0 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_page=3D0 get_request=3D0 s= leep_on_buffer=3D0

14:33:51 TOTAL=3D2 wait_transaction_locked=3D0 sleep_on_pag= e=3D0 get_request=3D0 sleep_on_buffer=3D0

14:33:52 TOTAL=3D4 wait_transaction_= locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0=

14:33:53 TOTA= L=3D6 wait_transaction_locked=3D0 sleep_on_page=3D0 get_request=3D0 sleep_o= n_buffer=3D0

14:33:54 TOTAL=3D7 wait_transaction_locked=3D0 sleep_on_page=3D0 = get_request=3D0 sleep_on_buffer=3D0

14:33:55 TOTAL=3D7 wait_transaction_locked= =3D0 sleep_on_page=3D0 get_request=3D0 sleep_on_buffer=3D0

 

I understand th= at RAID-6 is not the best option, but I can't catch any evidence telling th= at system run out of 1GB RAID controller cache on writes.=

 

Please assist in= understanding meaning and nature of long semop calls appearances.

 =

--=

Regards= ,

P= avel Suderevsky

 

 

 

From: Pavel SuderevskySent: Monday, January 22, 2018 21:43
To: pgsql-performance@postgresql.orgSubject: 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 i= n 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    &nbs= p; shared     buff/cache  available

  = ;            &n= bsp; Mem:         193166       = ;10324        1856      44522  &nbs= p;   180985      137444

    = ;            Swap:&n= bsp;            0        =    0           0<= /p>

Storage: W= ell,  about 4gb of BBU write cache.

 

shared_buff= ers =3D 32gb

work_mem =3D 128mb

max_pred_locks_per_transact= ion =3D 8192

 

This can occur once a day or not happen= for few days while system load is the same. "Inserts" are the pr= epared 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 no= thing embarrassing was found.

 

There are several scen= arious of such long inserts were spotted:

<= p class=3DMsoNormal>1. No any locks catched (= 500ms check intervals)

2. Wait event is "buffer_mapping" = - looks like the most common case

 snaphot time  &n= bsp;            = ;            &n= bsp;            = ;            | state=   | trx duration    | query duration   | wait_even= t_type | wait_event     | query

<= div>

 2017-12-22 03:= 16:01.181014 | active | 00:00:00.535309 | 00:00:00.524729  | LWLockTra= nche   | buffer_mapping | INSERT INTO table..

 2017-= 12-22 03:16:00.65814  | active | 00:00:00.012435 | 00:00:00.001855&nbs= p; | LWLockTranche   | buffer_mapping | INSERT INTO table..<= /o:p>

3. Wait event is "SerializablePredicateLockListLock" (I believ= e the same root cause as previous case)

4. No any locks catched, bu= t ~39 other backends in parallel are active 

 =

I = assumed that it can be somehow related to enabled NUMA, but it looks like m= emory is allocated evenly, zone_reclaim_mode is 0.

numactl --hardwa= re

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: 13097= 8 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  &n= bsp;0   1 

  0:  10  21 

  1:  21  10 

  

numastat -m=

 

Per-node system memory usage (in MBs):

&nbs= p;                     &n= bsp;   Node 0          Node 1    &n= bsp;      Total

          &= nbsp;      --------------- --------------- ---------------

MemTotal               13097= 8.34        65536.00       196514.3= 4

MemFree                &n= bsp; 1479.07          212.12      &= nbsp;  1691.20

MemUsed           = ;     129499.27        65323.88    =    194823.14

Active          &nb= sp;       72241.16        37254.56 =      109495.73

Inactive        =         47936.24        24205.40&nb= sp;       72141.64

Active(anon)     =       21162.41        18978.96  &n= bsp;     40141.37

Inactive(anon)      &nbs= p;    1061.94         7522.34  &nbs= p;      8584.27

Active(file)      &nb= sp;     51078.76        18275.60   =     69354.36

Inactive(file)        &= nbsp; 46874.30        16683.06      &nbs= p; 63557.36

Unevictable            &n= bsp;    0.00            0.00  =           0.00

Mlocked     =                0.00    &= nbsp;       0.00            0.= 00

Dirty                &nb= sp;      0.04            0.02&= nbsp;           0.05

Writeback   = ;                0.00    =         0.00            0= .00

FilePages              11651= 1.36        60923.16       177434.5= 2

Mapped                &nb= sp; 16507.29        23912.82       = 40420.11

AnonPages             = ;   3661.55          530.26    &nbs= p;    4191.81

Shmem          &nb= sp;        18558.28        25964.74=         44523.02

KernelStack     = ;           16.98         = ;   5.77           22.75

PageTab= les               3943.56  &nb= sp;      1022.25         4965.81

NFS_Unstable                0= .00            0.00       = ;     0.00

<= span style=3D'color:#909AA4'>Bounce           = ;           0.00         =   0.00            0.00

Writebac= kTmp                0.00  &nbs= p;         0.00           = ; 0.00

Slab                =      2256.09         1291.53  =        3547.61

SReclaimable     =        2108.29          889.8= 5         2998.14

=

SUnreclaim    =             147.80       =   401.68          549.47

AnonHugePag= es            1824.00      &nb= sp;   284.00         2108.00

HugePage= s_Total             0.00    &n= bsp;       0.00            0.0= 0

HugePages_Free              0.= 00            0.00       =     0.00

HugePages_Surp         = ;     0.00            0.00  &n= bsp;         0.00

 

<= /div>

$ cat /proc/62= 679/numa_maps | grep N0 | grep zero

7f92509d3000 prefer:0 file=3D/d= ev/zero\040(deleted) dirty=3D8419116 mapmax=3D154 active=3D8193350 N0=3D389= 0534 N1=3D4528582 kernelpagesize_kB=3D4

 

Could you ad= vise what can cause such occasional long inserts with long-lasting LWlocks?=

 

 

 

 

= --_2FED6C58-B5FC-4EC0-80DA-E66956AE1D12_--