Poor performance on inserts MariaDB
We are running MariaDB Community Edition 10.1.11. We are benchmarking inserts for an application that requires high volume inserts. With MariaDB, we can insert about 476 rows for second. The same job is able to load 2,500 rows/ second on Oracle. Both environments are VMware with RedHat Linux. We have the same number of vCPUs and memory. Overall performance declines if we try multiple jobs. I tried increasing innodb_autoinc_lock_mode from 1 to 2 and bouncing without seeing improvement. I see a of processes waiting on system locks such as this one: SQL thread id 14, OS thread handle 0x7f9237bff700, query id 6743478 zlx70603.vci.att.com 130.9.221.47 pedadba System lock.
I see lots of WRITES for each insert:
20160509 09:16:29,zlx70756,pedadba,zlx70603.vci.att.com,32,11812785,QUERY,ped,'insert into ped_location_load (SRC_CPL_ID, STR_ADDR, CITY_NM, ST_CD, ZIP_CD, LAT_COORD, LONG_COORD, CLLI_8, FIBR_LIT_IND, FIBR_LIT_BLDG_IND, EGIS_FIBR_LIT_BLDG_IND, SRVG_WC_CLLI_8, LEIS_WC_CD, DA_PSA_NAME, DA_PSA_ID, DSTNC_TO_FIBR_FEET_MSRMT, DSTNC_TO_FIBR_MILE_MSRMT, GIS_LAT_COORD, GIS_LONG_COORD, SAG_HSE_NBR, SAG_STR_PRFX, SAG_STR_NM, SAG_CITY_NM, SAG_ST_CD, SAG_ZIP_CD, SAG_MTCH_CD, SITE_STS_CD, AREA_MGR_PLNG_NM, AREA_MGR_DSGN_NM, RGN_CD, SUB_TURF_CD, TERR_TYPE_CD, LATA_CD, BUS_UNIT_CNT, PRRTY_NBR, PRRTY_YR, ALT_SRVG_WC_CLLI_8, PROJ_MGT_TOOL_NBR, BLDG_NM, PROJ_ACTVN_DT, REACTVN_DT, UVERSE_GREEN_AREA_IND, CELL_SITE_IN_BLDG_IND, CELL_SITE_N_BLDG_FXD_ASSET_NBR, VCNTY_CELL_SITE_FXD_ASSET_NBR, EXSTG_ORD_NBR, SMALL_CELL_PLAN_FOR_BLDG_IND, LOC_CMNT_TXT, CRTD_DT, CRTD_BY, LAST_UPDTD_DT, LAST_UPDTD_BY, SVC_ORD_NBR, MKTG_STR_PRFX, MKTG_STR_DRCTN, RVISD_BUS_UNIT_CNT, BUS_JSTFCN, BLD_YR, BLDG_PASSED, BLDG_ON_NET, FAP_STS, FAP_LOC, FDA_NM, FAA_NM, FAP_JOB_NBR, CLDS_REQUEST_ID, CLDS_STATUS, FIBR_RISER_RQRD, SAG_MTCH_MSG,',0 20160509 09:16:29,zlx70756,pedadba,zlx70603.vci.att.com,32,11812788,QUERY,ped,'SELECT FLOOR(RAND()*(50-1)+50) into st_rand',0 20160509 09:16:29,zlx70756,pedadba,zlx70603.vci.att.com,32,11812789,QUERY,ped,'SELECT FLOOR(RAND()*(6-1)+6) into reg_rand',0 20160509 09:16:29,zlx70756,isaac_all,%,32,11812791,WRITE,ped,ped_location_load, 20160509 09:16:29,zlx70756,isaac_all,%,32,11812791,WRITE,ped,ped_location_load, < many more WRITES>
Here is the full innodb engine status: to shorten it, I put the full statement only once:
-------------- SHOW ENGINE INNODB STATUS -------------- *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2016-05-09 08:43:37 7f92323ff700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 34 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 2785 srv_active, 0 srv_shutdown, 461 srv_idle srv_master_thread log flush and writes: 3246 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 8038 OS WAIT ARRAY INFO: signal count 9256 Mutex spin waits 5940, rounds 76361, OS waits 1957 RW-shared spins 2417, rounds 70030, OS waits 2234 RW-excl spins 5242, rounds 133769, OS waits 3264 Spin rounds per wait: 12.86 mutex, 28.97 RW-shared, 25.52 RW-excl ------------ TRANSACTIONS ------------ Trx id counter 88326197 Purge done for trx's n:o < 88326196 undo n:o < 0 state: running but idle History list length 180 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0, not started MySQL thread id 20, OS thread handle 0x7f92323ff700, query id 6743576 zlx70603.vci.att.com 130.9.221.47 isaac_all init SHOW ENGINE INNODB STATUS ---TRANSACTION 88325944, not started MySQL thread id 5, OS thread handle 0x7f92781db700, query id 955255 vpn-135-70-5-32.vpn.west.att.com 135.70.5.32 isaac_all cleaning up ---TRANSACTION 0, not started MySQL thread id 4, OS thread handle 0x7f9281962700, query id 955574 vpn-135-70-5-32.vpn.west.att.com 135.70.5.32 isaac_all cleaning up ---TRANSACTION 88322307, not started MySQL thread id 1, OS thread handle 0x7f92b3d84700, query id 0 Waiting for background binlog tasks ---TRANSACTION 88326196, ACTIVE 52 sec mysql tables in use 131, locked 131 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 2238 MySQL thread id 13, OS thread handle 0x7f92459f3700, query id 6743448 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, STR_ADDR, CITY_NM, ST_CD, ZIP_CD, LAT_COORD, LONG_COORD, CLLI_8, FIBR_LIT_IND, FIBR_LIT_BLDG_IND, EGIS_FIBR_LIT_BLDG_IND, SRVG_WC_CLLI_8, LEIS_WC_CD, DA_PSA_NAME, DA_PSA_ID, DSTNC_TO_FIBR_FEET_MSRMT, DSTNC_TO_FIBR_MILE_MSRMT, GIS_LAT_COORD, GIS_LONG_COORD, SAG_HSE_NBR, SAG_STR_PRFX, SAG_STR_NM, SAG_CITY_NM, SAG_ST_CD, SAG_ZIP_CD, SAG_MTCH_CD, SITE_STS_CD, AREA_MGR_PLNG_NM, AREA_MGR_DSGN_NM, RGN_CD, SUB_TURF_CD, TERR_TYPE_CD, LATA_CD, BUS_UNIT_CNT, PRRTY_NBR, PRRTY_YR, ALT_SRVG_WC_CLLI_8, PROJ_MGT_TOOL_NBR, BLDG_NM, PROJ_ACTVN_DT, REACTVN_DT, UVERSE_GR Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326191, ACTIVE 83 sec mysql tables in use 52, locked 52 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 3584 MySQL thread id 16, OS thread handle 0x7f9235fff700, query id 6743430 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, STR_ADDR, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326190, ACTIVE 83 sec mysql tables in use 5, locked 5 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 3658 MySQL thread id 19, OS thread handle 0x7f92333ff700, query id 6743606 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326188, ACTIVE 86 sec mysql tables in use 59, locked 59 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 3697 MySQL thread id 15, OS thread handle 0x7f9236fff700, query id 6743327 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326187, ACTIVE 98 sec mysql tables in use 66, locked 66 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 4320 MySQL thread id 12, OS thread handle 0x7f924ddee700, query id 6743575 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326186, ACTIVE 99 sec mysql tables in use 33, locked 33 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 4506 MySQL thread id 17, OS thread handle 0x7f92353ff700, query id 6743630 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326185, ACTIVE 116 sec mysql tables in use 59, locked 59 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 5086 MySQL thread id 11, OS thread handle 0x7f9281a63700, query id 6743446 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326184, ACTIVE 172 sec mysql tables in use 7, locked 7 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 7919 MySQL thread id 18, OS thread handle 0x7f92343ff700, query id 6743538 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326183, ACTIVE 203 sec mysql tables in use 52, locked 52 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 9102 MySQL thread id 8, OS thread handle 0x7f92393ff700, query id 6743600 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC ---TRANSACTION 88326178, ACTIVE 212 sec mysql tables in use 75, locked 75 1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 9706 MySQL thread id 14, OS thread handle 0x7f9237bff700, query id 6743478 zlx70603.vci.att.com 130.9.221.47 pedadba System lock insert into ped_location_load (SRC_CPL_ID, <complete statement same as above> Trx #rec lock waits 0 #table lock waits 0 Trx total rec lock wait time 0 SEC Trx total table lock wait time 0 SEC -------- FILE I/O -------- I/O thread 0 state: waiting for completed aio requests (insert buffer thread) I/O thread 1 state: waiting for completed aio requests (log thread) I/O thread 2 state: waiting for completed aio requests (read thread) I/O thread 3 state: waiting for completed aio requests (read thread) I/O thread 4 state: waiting for completed aio requests (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] , ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 4272 OS file reads, 78139 OS file writes, 20899 OS fsyncs 0.00 reads/s, 0 avg bytes/read, 21.68 writes/s, 4.32 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 62, seg size 64, 0 merges merged operations: insert 0, delete mark 0, delete 0 discarded operations: insert 0, delete mark 0, delete 0 5981.97 hash searches/s, 406.66 non-hash searches/s --- LOG --- Log sequence number 375449925793 Log flushed up to 375449653000 Pages flushed up to 375438050350 Last checkpoint at 375435460923 Max checkpoint age 84223550 Checkpoint age target 81591565 Modified age 11875443 Checkpoint age 14464870 0 pending log writes, 0 pending chkp writes 6332 log i/o's done, 1.91 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 553648128; in additional pool allocated 0 Total memory allocated by read views 288 Internal hash tables (constant factor + variable factor) Adaptive hash index 8888016 (8851048 + 36968) Page hash 553976 (buffer pool 0 only) Dictionary cache 46879130 (2214224 + 44664906) File system 1307376 (812272 + 495104) Lock system 1334216 (1329176 + 5040) Recovery system 0 (0 + 0) Dictionary memory allocated 44664906 Buffer pool size 32767 Buffer pool size, bytes 536854528 Free buffers 1014 Database pages 31748 Old database pages 11699 Modified db pages 500 Percent of dirty pages(LRU & free pages): 1.526 Max dirty pages percent: 75.000 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 3251, not young 49414 0.06 youngs/s, 0.00 non-youngs/s Pages read 2853, created 52673, written 60872 0.00 reads/s, 16.56 creates/s, 18.56 writes/s Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 31748, unzip_LRU len: 0 I/O sum[982]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 0 read views open inside InnoDB 10 RW transactions active inside InnoDB 0 RO transactions active inside InnoDB 10 out of 1000 descriptors used Main thread process no. 2676, id 140266283443968, state: sleeping Number of rows inserted 1123943, updated 0, deleted 0, read 20 423.72 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s Number of system rows inserted 0, updated 0, deleted 0, read 0 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================
Answer Answered by Jan Lindström in this comment.
Did you use xtradb (default) or innodb_plugin (needs to be configured) ? At least on my performance testing in many cases innodb_plugin offers better performance.