Re: BUG #15609: synchronous_commit=off insert performance regression with secondary indexes

From: "Saul, Jean Paolo" <paolo(dot)saul(at)verizonconnect(dot)com>
To: Peter Geoghegan <pg(at)bowt(dot)ie>
Cc: Andrew Gierth <andrew(at)tao11(dot)riddles(dot)org(dot)uk>, PostgreSQL mailing lists <pgsql-bugs(at)lists(dot)postgresql(dot)org>
Subject: Re: BUG #15609: synchronous_commit=off insert performance regression with secondary indexes
Date: 2019-02-05 04:39:18
Message-ID: CA+73ANe8ha7X7B8qNr7xkJ-T+WrU-m-7rAt0Y1ejpoFArUe8Sw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

Hi Peter,

I did some additional testing using perf (I'm not a perf expert) and on AWS
there seemed to be a lot of calls to the hypervisor.
So I got hold of a real server from our inventory (
https://www.dell.com/en-nz/work/shop/povw/poweredge-r640).

Initial tests still show the same behavior for PG11 (see below).
I ran perf during pgbench testing for the two PG versions and pasted the
top calls below.
It looks like PG11 with low cardinality index is waiting for a futex on
_bt_search
and a semaphore lock on _bt_relandgetbuf.
Again I'm no perf expert and my analysis is possibly wrong.
Running pgbench using hashes instead shows no futex usage on pg11.

------------------------------------------
r640.tx $ head /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 85
model name : Intel(R) Xeon(R) Gold 5120 CPU @ 2.20GHz
stepping : 4
microcode : 0x2000050
cpu MHz : 2200.000
cache size : 19712 KB
physical id : 0
r640.tx $ grep cores /proc/cpuinfo |wc -l
56
r640.tx $ free -m
total used free shared buff/cache
available
Mem: 515376 4154 508564 313 2657
509310
Swap: 4095 0 4095
r640.tx $ psql -Upostgres -p9500 -c "create table lowc_test (id bigserial,
int_data int, primary key(id)); create index on lowc_test using btree
(int_data)";
CREATE INDEX
r640.tx $ psql -Upostgres -p11000 -c "create table lowc_test (id bigserial,
int_data int, primary key(id)); create index on lowc_test using btree
(int_data)";
CREATE INDEX
r640.tx $ echo 'insert into lowc_test (int_data) select random()*100000;' >
/home/postgres/insert_lowc.sql
r640.tx $ psql -Upostgres -p9500 -c "truncate lowc_test";
/usr/pgsql-11/bin/pgbench -n -Upostgres -f /home/postgres/insert_lowc.sql
-c50 -j60 -T10 -p 9500|grep tps
TRUNCATE TABLE
tps = 131279.163871 (including connections establishing)
tps = 131730.404978 (excluding connections establishing)
r640.tx $ psql -Upostgres -p11000 -c "truncate lowc_test";
/usr/pgsql-11/bin/pgbench -n -Upostgres -f /home/postgres/insert_lowc.sql
-c50 -j60 -T10 -p 11000|grep tps
TRUNCATE TABLE
tps = 144822.892940 (including connections establishing)
tps = 145296.472528 (excluding connections establishing)
r640.tx $
r640.tx $ echo 'insert into lowc_test (int_data) select 42;' >
/home/postgres/insert_lowc.sql
r640.tx $
r640.tx $ psql -Upostgres -p9500 -c "truncate lowc_test";
/usr/pgsql-11/bin/pgbench -n -Upostgres -f /home/postgres/insert_lowc.sql
-c50 -j60 -T10 -p 9500|grep tps
TRUNCATE TABLE
tps = 20137.416962 (including connections establishing)
tps = 20204.697353 (excluding connections establishing)
r640.tx $ psql -Upostgres -p11000 -c "truncate lowc_test";
/usr/pgsql-11/bin/pgbench -n -Upostgres -f /home/postgres/insert_lowc.sql
-c50 -j60 -T10 -p 11000|grep tps
TRUNCATE TABLE
tps = 17361.186258 (including connections establishing)
tps = 17420.454363 (excluding connections establishing)

---------------------------

PERF PG95

+ 26.19% 0.18% postgres /proc/kcore k [k]
system_call_fastpath
+ 26.13% 0.23% postgres /usr/lib64/libc-2.17. B [.]
__GI___semop
+ 17.42% 0.18% postgres /proc/kcore k [k]
sys_semop
+ 17.24% 0.06% postgres /proc/kcore k [k]
sys_semtimedop
+ 15.38% 2.06% postgres /proc/kcore k [k]
SYSC_semtimedop
+ 11.62% 0.00% postgres [unknown] ! [k]
0000000000000000
+ 8.02% 0.00% postgres [unknown] ! [k]
0x00007ffef3e98d30
+ 6.13% 0.34% postgres /proc/kcore k [k]
schedule
+ 5.95% 1.84% postgres /proc/kcore k [k]
try_to_wake_up
+ 5.45% 0.87% postgres /proc/kcore k [k]
__schedule
+ 5.41% 0.06% postgres /proc/kcore k [k]
wake_up_sem_queue_do
+ 5.34% 0.02% postgres /proc/kcore k [k]
wake_up_process

---------------------------

PERF PG11

+ 16.90% 0.08% postgres [kernel.kallsyms] [k]
system_call_fastpath
+ 12.18% 0.15% postgres [kernel.kallsyms] [k] sys_futex
+ 12.03% 0.13% postgres [kernel.kallsyms] [k] do_futex
+ 8.95% 0.00% postgres [unknown] [k]
0x0000000000000080
+ 8.80% 0.13% postgres libpthread-2.17.so [.]
do_futex_wait.constprop.1
+ 7.76% 0.29% postgres libpthread-2.17.so [.] sem_post@
@GLIBC_2.2.5
+ 6.44% 0.29% postgres [kernel.kallsyms] [k] futex_wait
+ 5.27% 0.33% postgres [kernel.kallsyms] [k] futex_wake

--------------------------------------------------------------------------------------------------------------------------------------------
PLEASE CONSIDER THE ENVIRONMENT BEFORE PRINTING THIS EMAIL

VERIZON CONNECT CONFIDENTIALITY NOTICE
This message is intended for the addressee only and may contain confidential and/or privileged material. Any review, re-transmission, dissemination, reliance upon or other use of this information by persons or entities other than the addressee is prohibited. If you receive this in error, please contact the sender and delete this message. Thank you.

In response to

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message Peter Eisentraut 2019-02-05 11:28:44 Re: BUG #15511: Drop table error "invalid argument"
Previous Message Tom Lane 2019-02-05 01:44:39 Re: BUG #15602: pg_dump archive items not in correct section order