SpinLock Performance Decline
hslightdb opened this issue · 2 comments
hslightdb commented
When pg_show_plans is enable, it brings the performance down seriously:
Stress testing tool：benchmark （200 Client）
- before (shared_preload_libraries='')：
Measured tpmC = 315000
Measured tpmTOTAL = 694000 - after (shared_preload_libraries='pg_show_plans')：
Measured tpmC = 30400
Measured tpmTOTAL = 70300
We print the call stack with 'pstack'
#0 0x00007f644ccd0b3b in do_futex_wait.constprop.1 () from /lib64/libpthread.so.0
#1 0x00007f644ccd0bcf in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0
#2 0x00007f644ccd0c6b in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0
#3 0x0000000000707452 in PGSemaphoreLock (sema=0x7f53c6610c38) at pg_sema.c:327
#4 0x00000000007800ec in LWLockAcquire (lock=0x7f53c661e280, mode=mode@entry=LW_SHARED) at lwlock.c:1331
#5 0x00007f6441ddd4ec in entry_store (nested_level=0, plan=0x2d6d298 "Insert on bmsql_new_order (cost=0.00..0.01 rows=1 width=12)\n -> Result (cost=0.00..0.01 rows=1 width=12)") at pg_show_plans.c:555
#6 pgsp_ExecutorStart (queryDesc=<optimized out>, eflags=<optimized out>) at pg_show_plans.c:406
#7 0x0000000000792d46 in ProcessQuery (plan=<optimized out>, sourceText=0x2d36b78 "INSERT INTO bmsql_new_order ( no_o_id, no_d_id, no_w_id) VALUES ($1, $2, $3)", params=0x2d36c20, queryEnv=0x0, dest=0xa0cbe0 <donothingDR>, qc=0x7ffc98543370) at pquery.c:155
#8 0x0000000000792fb4 in PortalRunMulti (portal=portal@entry=0x2b84ac8, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=0xa0cbe0 <donothingDR>, dest@entry=0x2af3298, altdest=0xa0cbe0 <donothingDR>, altdest@entry=0x2af3298, qc=qc@entry=0x7ffc98543370) at pquery.c:1269
#9 0x00000000007939cd in PortalRun (portal=portal@entry=0x2b84ac8, count=count@entry=1, isTopLevel=isTopLevel@entry=true, run_once=<optimized out>, dest=dest@entry=0x2af3298, altdest=altdest@entry=0x2af3298, qc=qc@entry=0x7ffc98543370) at pquery.c:783
#10 0x0000000000791482 in exec_execute_message (max_rows=1, portal_name=0x2af2e88 "") at postgres.c:2282
#11 PostgresMain (argc=<optimized out>, argv=argv@entry=0x2b22128, dbname=0x2b22028 "benchmarksql300", username=<optimized out>) at postgres.c:4506
#12 0x0000000000488208 in BackendRun (port=<optimized out>, port=<optimized out>) at postmaster.c:4988
#13 BackendStartup (port=0x2b19410) at postmaster.c:4672
#14 ServerLoop () at postmaster.c:1959
#15 0x000000000071a6f2 in PostmasterMain (argc=argc@entry=1, argv=argv@entry=0x2aed9a0) at postmaster.c:1495
#16 0x00000000004891ed in main (argc=1, argv=0x2aed9a0) at main.c:231
#0 0x00007f644b569a13 in __select_nocancel () from /lib64/libc.so.6
#1 0x00000000008eb91a in pg_usleep (microsec=<optimized out>) at pgsleep.c:56
#2 0x00000000007874d5 in perform_spin_delay (status=status@entry=0x7ffc98542480) at s_lock.c:138
#3 0x0000000000787610 in s_lock (lock=0x7f643c56d610 "", file=file@entry=0x7f6441dde040 "pg_show_plans.c", line=line@entry=349, func=func@entry=0x7f6441dde360 <__func__.26729> "pgsp_ExecutorStart") at s_lock.c:99
#4 0x00007f6441ddd68b in pgsp_ExecutorStart (queryDesc=0x2c02738, eflags=16) at pg_show_plans.c:349
#5 0x0000000000668ee0 in _SPI_pquery (tcount=1, fire_triggers=false, queryDesc=<optimized out>) at spi.c:2509
#6 _SPI_execute_plan (plan=plan@entry=0x2c59dd8, paramLI=0x2c026a8, snapshot=snapshot@entry=0x0, crosscheck_snapshot=crosscheck_snapshot@entry=0x0, read_only=read_only@entry=false, fire_triggers=fire_triggers@entry=false, tcount=tcount@entry=1) at spi.c:2288
#7 0x0000000000669334 in SPI_execute_snapshot (plan=plan@entry=0x2c59dd8, Values=Values@entry=0x7ffc985426f0, Nulls=Nulls@entry=0x7ffc985426b0 " nX\177", snapshot=snapshot@entry=0x0, crosscheck_snapshot=crosscheck_snapshot@entry=0x0, read_only=read_only@entry=false, fire_triggers=fire_triggers@entry=false, tcount=tcount@entry=1) at spi.c:616
#8 0x000000000083f66a in ri_PerformCheck (riinfo=riinfo@entry=0x2bf8ee8, qkey=qkey@entry=0x7ffc98542970, qplan=0x2c59dd8, fk_rel=fk_rel@entry=0x7f644cf9f298, pk_rel=pk_rel@entry=0x7f644cf8af98, oldslot=oldslot@entry=0x0, newslot=newslot@entry=0x2d3e748, detectNewRows=detectNewRows@entry=false, expect_OK=expect_OK@entry=5) at ri_triggers.c:2277
#9 0x000000000083f913 in RI_FKey_check (trigdata=<optimized out>) at ri_triggers.c:392
#10 0x000000000060c09b in ExecCallTriggerFunc (trigdata=trigdata@entry=0x7ffc98542e20, tgindx=tgindx@entry=0, finfo=finfo@entry=0x2c79288, instr=instr@entry=0x0, per_tuple_context=per_tuple_context@entry=0x2c1f460) at trigger.c:2066
#11 0x000000000060cdce in AfterTriggerExecute (trigdesc=0x2c78d38, trigdesc=0x2c78d38, trig_tuple_slot2=0x0, trig_tuple_slot1=0x0, per_tuple_context=0x2c1f460, instr=0x0, finfo=0x2c79288, relInfo=0x2c78da8, event=0x2d63358, estate=0x2c78af8) at trigger.c:3955
#12 afterTriggerInvokeEvents (events=events@entry=0x2c68768, firing_id=6, estate=estate@entry=0x2c78af8, delete_ok=delete_ok@entry=false) at trigger.c:4169
#13 0x00000000006127c8 in AfterTriggerEndQuery (estate=estate@entry=0x2c78af8) at trigger.c:4505
#14 0x0000000000630417 in standard_ExecutorFinish (queryDesc=0x2d37600) at execMain.c:426
#15 0x00007f6441ddcf65 in pgsp_ExecutorFinish (queryDesc=0x2d37600) at pg_show_plans.c:493
#16 0x0000000000792d98 in ProcessQuery (plan=<optimized out>, sourceText=0x2d37398 "INSERT INTO bmsql_order_line ( ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9)", params=0x2d374c0, queryEnv=0x0, dest=0xa0cbe0 <donothingDR>, qc=0x7ffc98543370) at pquery.c:194
#17 0x0000000000792fb4 in PortalRunMulti (portal=portal@entry=0x2b84ac8, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=0xa0cbe0 <donothingDR>, dest@entry=0x2af3298, altdest=0xa0cbe0 <donothingDR>, altdest@entry=0x2af3298, qc=qc@entry=0x7ffc98543370) at pquery.c:1269
#18 0x00000000007939cd in PortalRun (portal=portal@entry=0x2b84ac8, count=count@entry=1, isTopLevel=isTopLevel@entry=true, run_once=<optimized out>, dest=dest@entry=0x2af3298, altdest=altdest@entry=0x2af3298, qc=qc@entry=0x7ffc98543370) at pquery.c:783
#19 0x0000000000791482 in exec_execute_message (max_rows=1, portal_name=0x2af2e88 "") at postgres.c:2282
#20 PostgresMain (argc=<optimized out>, argv=argv@entry=0x2b22128, dbname=0x2b22028 "benchmarksql300", username=<optimized out>) at postgres.c:4506
#21 0x0000000000488208 in BackendRun (port=<optimized out>, port=<optimized out>) at postmaster.c:4988
#22 BackendStartup (port=0x2b19410) at postmaster.c:4672
#23 ServerLoop () at postmaster.c:1959
#24 0x000000000071a6f2 in PostmasterMain (argc=argc@entry=1, argv=argv@entry=0x2aed9a0) at postmaster.c:1495
#25 0x00000000004891ed in main (argc=1, argv=0x2aed9a0) at main.c:231
and find that 'SpinLock' and 'LWLock' cause too many data-race
kovmir commented
@hslightdb, can you please show me the query you run?