Re: PG 9.6 Slow inserts with long-lasting LWLocks

[MichaelDBA]

Sporadic insert slowness could be due to lock delays (locktype=extend) 
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 locks happen so fast that you hardly ever see them in the 
pg_locks table, except 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 you execute it during the time the problem is 
occurring.


select * from pg_locks where granted = false and locktype = '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,

Well, unfortunately I still need community help.

-- Environment

OS: Centos CentOS Linux release 7.2.1511

Kernel:  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 = 2048

shared_buffers = 48GB

temp_buffers = 128MB

work_mem = 256MB

maintenance_work_mem = 512MB

dynamic_shared_memory_type = posix

wal_level = hot_standby

min_wal_size = 4GB

max_wal_size = 32GB

huge_pages = on

+

numactl interleave=all

-- sysctl.conf

kernel.shmmax=64424509440

kernel.shmall=4294967296

kernel.sem = 1024 32767 128 16384

fs.aio-max-nr=3145728

fs.file-max = 6815744

net.core.rmem_default=262144

net.core.rmem_max=4194304

net.core.wmem_default=262144

net.core.wmem_max=1048586

vm.nr_hugepages=33000

vm.dirty_background_bytes=67108864

vm.dirty_bytes=536870912

vm.min_free_kbytes=1048576

zone_reclaim_mode=0

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 every 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 between such sessions and long transactions, at least it 
is not the root cause of the issue (of course such app behaviour will 
be fixed).


The investigation and tracing with strace in particular showed that:

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


2. Seems the whole host gets hung during such events.

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

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

119971 14:33:48.075375 epoll_wait(3, 

119971 14:33:48.075696 <... epoll_wait resumed> {{EPOLLIN, 
{u32=27532016, u64=27532016}}}, 1, -1) = 1 <0.000313>


119971 14:33:48.075792 recvfrom(9, 

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) = 807 <0.66>


119971 14:33:48.076243 semop(26706044, {{8, -1, 0}}, 1 

120019 14:33:48.119971 recvfrom(9, 

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

119971 14:33:53.500356 lseek(18, 0, SEEK_END 

119971 14:33:53.500436 <... lseek resumed> ) = 107790336 <0.72>

119971 14:33:53.500514 lseek(20, 0, SEEK_END 

Checking 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> )   = 0 <1.419394>

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

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

119988 12:33:36 <... semop resumed> )   = 0 <1.213309>

119966 12:33:36 <... semop resumed> )   = 0 <1.237492>

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

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

119997 14:33:53.490638 <... semop resumed> ) = 0 <5.111661>

12 14:33:53.490649 <... semop resumed> ) = 0 <3.521992>

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

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

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

119976 14:33:53.490852 <... semop resumed> ) = 0 <2.489563>

119974 14:33:53.490862 <... semop resumed> ) =

Irrelevant columns cause massive performance change

[Craig James]

Here's a weird one I can't figure out: the definitions of several columns
of a view, which are not used in a query at all, have a massive effect on
the query planner, causing it to choose a seqscan over the largest table in
our database when it should be using the primary key for the join.
Background: We've redesigned the tables that hold our primary data, but
need to create views that mimic the old design so that our applications
will continue working. The largest table ("chemaxon.sdf") holds the bulk of
the data, and we've changed it from raw text to gzipped bytea. To mimic the
old schema, I created a short Perl function that does a simple gunzip
operation, and used that in the definition of the view "str_conntab". (This
gzip reduces our total database size to about a third of the original --
it's very effective).

Here are two query plans. The first is horrible. For the second, I removed
the gunzip functions and replaced them with constant values. But notice
that these pseudo columns are not used anywhere in the query. (Even if they
were, I don't understand why this should affect the planner.)

The tables VERSION and VERSION_PROPERTIES are also views; I've included
their definitions and the underlying actual tables below.

Postgres 9.6.7 running on Ubuntu 16.04.

emolecules=> drop view str_conntab;
DROP VIEW
emolecules=> create view str_conntab as
emolecules->  (select
emolecules(>id,
emolecules(>length(gunzip(sdf_gzip)) as contab_len,
emolecules(>gunzip(sdf_gzip) as contab_data,
emolecules(>''::text as normalized
emolecules(>   from chemaxon.sdf);
CREATE VIEW

emolecules=> explain analyze
select VERSION.VERSION_ID, VERSION.ISOSMILES,
VERSION_PROPERTIES.MOLECULAR_WEIGHT, VERSION_PROPERTIES.MOLECULAR_FORMULA
 from VERSION
 join VERSION_PROPERTIES on (VERSION.VERSION_ID =
VERSION_PROPERTIES.VERSION_ID)
 join STR_CONNTAB on (VERSION.VERSION_ID = STR_CONNTAB.ID)
 where VERSION.VERSION_ID in
(1485909,1485889,1485903,1485887,1485892,1485900,1485895,1485898,1485906,1485884);

 QUERY PLAN

-
 Nested Loop  (cost=62.99..162425.77 rows=5 width=60) (actual
time=34.718..152828.351 rows=10 loops=1)
   Join Filter: (s.id = p_1.id)
   ->  Nested Loop  (cost=62.56..162422.84 rows=6 width=55) (actual
time=34.701..152828.289 rows=10 loops=1)
 Join Filter: (s.id = parent.id)
 ->  Nested Loop  (cost=62.14..162419.48 rows=7 width=51) (actual
time=34.694..152828.250 rows=10 loops=1)
   Join Filter: (s.id = p.id)
   ->  Hash Join  (cost=61.72..162415.16 rows=9 width=47)
(actual time=34.663..152828.110 rows=10 loops=1)
 Hash Cond: (sdf.id = s.id)
 ->  Seq Scan on sdf  (cost=0.00..158488.50 rows=281080
width=72) (actual time=33.623..152630.514 rows=281080 loops=1)
 ->  Hash  (cost=61.59..61.59 rows=10 width=43) (actual
time=0.028..0.028 rows=10 loops=1)
   Buckets: 1024  Batches: 1  Memory Usage: 9kB
   ->  Index Scan using smiles_pkey on smiles s
(cost=0.42..61.59 rows=10 width=43) (actual time=0.010..0.022 rows=10
loops=1)
 Index Cond: (id = ANY
('{1485909,1485889,1485903,1485887,1485892,1485900,1485895,1485898,1485906,1485884}'::integer[]))
   ->  Index Only Scan using parent_pkey on parent p
(cost=0.42..0.47 rows=1 width=4) (actual time=0.011..0.011 rows=1 loops=10)
 Index Cond: (id = sdf.id)
 Heap Fetches: 10
 ->  Index Only Scan using parent_pkey on parent  (cost=0.42..0.47
rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=10)
   Index Cond: (id = sdf.id)
   Heap Fetches: 10
   ->  Index Scan using properties_pkey on properties p_1  (cost=0.42..0.48
rows=1 width=21) (actual time=0.003..0.004 rows=1 loops=10)
 Index Cond: (id = sdf.id)
 Planning time: 1.330 ms
 Execution time: 152828.506 ms
(23 rows)

emolecules=> drop view str_conntab;
DROP VIEW
emolecules=> create view str_conntab as
emolecules->  (select
emolecules(>id,
emolecules(>0::integer contab_len,
emolecules(>null::text as contab_data,
emolecules(>''::text as normalized
emolecules(>   from chemaxon.sdf);
CREATE VIEW
emolecules=> explain analyze
select VERSION.VERSION_ID, VERSION.ISOSMILES,
VERSION_PROPERTIES.MOLECULAR_WEIGHT, VERSION_PROPERTIES.MOLECULAR_FORMULA
 from VERSION
 join VERSION_PROPERTIES on (VERSION.VERSION_ID =
VERSION_PROPERTIES.VERSION_ID)
 join STR_CONNTAB on (VERSION.VERSION_ID = STR_CONNTAB.ID)
 where VERSION.VERSION_ID in
(1485909,1485889,1485903,1485887,1485892,1485900,1485895,1485898,1485906,1485884);
QUERY
PLAN
-

Re: Irrelevant columns cause massive performance change

[Andres Freund]

Hi,

On 2018-03-16 13:37:05 -0700, Craig James wrote:
> The timing of the second query is excellent, and is what I expected. I
> don't understand why including a function-defined column in the view would
> have such a dramatic effect on the planner's ability to choose the sdf_pkey
> index for the join.

> create or replace function gunzip(bytea) returns text as
> $gunzip$
>   use IO::Uncompress::Gunzip qw(gunzip $GunzipError);
>   my $compressed = decode_bytea($_[0]);
>   my $uncompressed;
>   if (!gunzip(\$compressed, \$uncompressed)) {
> return $GunzipError;
>   }
>   return $uncompressed;
> $gunzip$
> language plperlu;

I suspect at least part of the problem here is that the function is
declared volatile (the default). That means it can have arbitrary
sideeffects, which in turn means there's several places in the planner
that forgo optimizations if volatile functions are involved.  If you
declare the function as immutable, does the problem persist?

Greetings,

Andres Freund

Re: Irrelevant columns cause massive performance change

[Craig James]

On Fri, Mar 16, 2018 at 1:50 PM, Andres Freund  wrote:

> Hi,
>
> On 2018-03-16 13:37:05 -0700, Craig James wrote:
> > The timing of the second query is excellent, and is what I expected. I
> > don't understand why including a function-defined column in the view
> would
> > have such a dramatic effect on the planner's ability to choose the
> sdf_pkey
> > index for the join.
>
> > create or replace function gunzip(bytea) returns text as
> > $gunzip$
> >   use IO::Uncompress::Gunzip qw(gunzip $GunzipError);
> >   my $compressed = decode_bytea($_[0]);
> >   my $uncompressed;
> >   if (!gunzip(\$compressed, \$uncompressed)) {
> > return $GunzipError;
> >   }
> >   return $uncompressed;
> > $gunzip$
> > language plperlu;
>
> I suspect at least part of the problem here is that the function is
> declared volatile (the default). That means it can have arbitrary
> sideeffects, which in turn means there's several places in the planner
> that forgo optimizations if volatile functions are involved.  If you
> declare the function as immutable, does the problem persist?
>

Yes, perfect. That fixed the problem.

Thanks,
Craig


>
> Greetings,
>
> Andres Freund
>



-- 
-
Craig A. James
Chief Technology Officer
eMolecules, Inc.
-