CODEWITHSUNDEEP
mysqlamazon-ec2innodbdatabase-performancepercona
Thomas Miller
Thomas Miller

Reputation: 99

AWS EC2 with MySQL not using anywhere near the resources available (Big INSERT..SELECT)

I have an EC2 (r5.2Xlarge) with MySql 8.0.22 installed and have 2 schemas with each around 1.3 TB. Tables contain between 300 million and 2 billion rows. For disks I use GP3 with 16,000 IOPS and 1000 MB/s. So this is quite good I would assume. All tables are InnoDB.

Now I run a query where i copy 830,000,000 rows from table 1 to table 2 that takes around 5 days to complete. This is just unbelievebably slow.

query that i run insert into table2 (id,value_id) Select id,value_id from table1;

This query starts off with 8000 inserts per second but then drops to an average of 2500 to 3000 after couple of minutes.

I can see on AWS performance monitoring that the cpu sits at around 5% and IO for read at around 20 and write at around 4000. write performance is hovering at around 100mb/s (see pic below). this for me is a sign that I am not using the hardware to its maximum as neither disks nor CPU is at capacity and one would assume in such a data heavy query as above, the disk should run at its maximum.

Can somebody have a look at the extract below and maybe see some values that are off the charts? I have spent a long time googling but the messages out there are very contradicting and I am afraid to change settings if the research has not given me a clear understanding of what it does.

extracts from innodb status

 -----------------
 BACKGROUND THREAD
 -----------------
 srv_master_thread loops: 139616 srv_active, 0 srv_shutdown, 16834 srv_idle
 srv_master_thread log flush and writes: 0
 ----------
 SEMAPHORES
 ----------
 OS WAIT ARRAY INFO: reservation count 3380537
 OS WAIT ARRAY INFO: signal count 5555711
 RW-shared spins 969285, rounds 1446597, OS waits 477320
 RW-excl spins 1510270, rounds 24745577, OS waits 740601
 RW-sx spins 2014, rounds 59331, OS waits 1966
 Spin rounds per wait: 1.49 RW-shared, 16.38 RW-excl, 29.46 RW-sx 

--------
 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: complete io for buf page (write thread)
 I/O thread 7 state: complete io for buf page (write thread)
 I/O thread 8 state: complete io for buf page (write thread)
 I/O thread 9 state: complete io for buf page (write thread)
 Pending normal aio reads: [0, 0, 0, 0] , aio writes: [4, 0, 0, 0] ,
  ibuf aio reads:, log i/o's:, sync i/o's:
 Pending flushes (fsync) log: 0; buffer pool: 293064
 12836396 OS file reads, 705785528 OS file writes, 251455455 OS fsyncs
 1 pending preads, 1 pending pwrites
 6085.06 reads/s, 16383 avg bytes/read, 4331.99 writes/s, 1156.48 fsyncs/s
 -------------------------------------
 INSERT BUFFER AND ADAPTIVE HASH INDEX
 -------------------------------------
 Ibuf: size 133, free list len 957047, seg size 957181, 145190 merges
 merged operations:
  insert 422868, delete mark 0, delete 0
 discarded operations:
  insert 0, delete mark 0, delete 0
 Hash table size 13546877, node heap has 208 buffer(s)
 Hash table size 13546877, node heap has 618 buffer(s)
 Hash table size 13546877, node heap has 1 buffer(s)
 Hash table size 13546877, node heap has 1 buffer(s)
 Hash table size 13546877, node heap has 1 buffer(s)
 Hash table size 13546877, node heap has 1 buffer(s)
 Hash table size 13546877, node heap has 1 buffer(s)
 Hash table size 13546877, node heap has 773 buffer(s)
 3259.31 hash searches/s, 3153.10 non-hash searches/s
 ---
 LOG
 ---
 Log sequence number          10458893569770
 Log buffer assigned up to    10458893569770
 Log buffer completed up to   10458893569770
 Log written up to            10458893569381
 Log flushed up to            10458893152041
 Added dirty pages up to      10458893569770
 Pages flushed up to          10458813503591
 Last checkpoint at           10458813500688
 34272162 log i/o's done, 881.10 log i/o's/second
 ----------------------
 BUFFER POOL AND MEMORY
 ----------------------
 Total large memory allocated 56044290048
 Dictionary memory allocated 891577
 Buffer pool size   3342336
 Free buffers       6583
 Database pages     3316993
 Old database pages 1224525
 Modified db pages  294704
 Pending reads      0
 Pending writes: LRU 0, flush list 28, single page 0
 Pages made young 91169767, not young 2409531454
 0.00 youngs/s, 0.01 non-youngs/s
 Pages read 12621539, created 5829939, written 536293398
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 987 / 1000, young-making rate 1 / 1000 not 499 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 3316993, unzip_LRU len: 0
 I/O sum[1425272]:cur[21320], unzip sum[0]:cur[0]
 ----------------------
 INDIVIDUAL BUFFER POOL INFO
 ----------------------
 ---BUFFER POOL 0
 Buffer pool size   417792
 Free buffers       953
 Database pages     414480
 Old database pages 153021
 Modified db pages  36907
 Pending reads      0
 Pending writes: LRU 0, flush list 6, single page 0
 Pages made young 11324843, not young 305126547
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1576101, created 729712, written 66959369
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 988 / 1000, young-making rate 1 / 1000 not 493 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414480, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 1
 Buffer pool size   417792
 Free buffers       946
 Database pages     414488
 Old database pages 153019
 Modified db pages  36836
 Pending reads      0
 Pending writes: LRU 0, flush list 10, single page 0
 Pages made young 11180965, not young 302072441
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1568195, created 728393, written 66790908
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 516 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414488, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 2
 Buffer pool size   417792
 Free buffers       1017
 Database pages     414457
 Old database pages 152972
 Modified db pages  36608
 Pending reads      0
 Pending writes: LRU 0, flush list 6, single page 0
 Pages made young 11651343, not young 296801601
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1580150, created 729267, written 67338866
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 509 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414457, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 3
 Buffer pool size   417792
 Free buffers       946
 Database pages     414513
 Old database pages 153026
 Modified db pages  37064
 Pending reads      0
 Pending writes: LRU 0, flush list 6, single page 0
 Pages made young 11549266, not young 300684452
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1596663, created 728153, written 67299820
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 491 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414513, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 4
 Buffer pool size   417792
 Free buffers       726
 Database pages     414705
 Old database pages 153101
 Modified db pages  36600
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 11279236, not young 300731632
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1569208, created 728718, written 66867473
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 515 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414705, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 5
 Buffer pool size   417792
 Free buffers       603
 Database pages     414855
 Old database pages 153155
 Modified db pages  36645
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 11634232, not young 299370124
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1581611, created 728918, written 67297635
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 987 / 1000, young-making rate 1 / 1000 not 470 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414855, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 6
 Buffer pool size   417792
 Free buffers       726
 Database pages     414706
 Old database pages 153100
 Modified db pages  37179
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 11385018, not young 300961163
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1571483, created 728056, written 67087236
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 495 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414706, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 ---BUFFER POOL 7
 Buffer pool size   417792
 Free buffers       666
 Database pages     414789
 Old database pages 153131
 Modified db pages  36865
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 11164864, not young 303783494
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1578128, created 728722, written 66652091
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 Buffer pool hit rate 986 / 1000, young-making rate 1 / 1000 not 507 / 1000
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 414789, unzip_LRU len: 0
 I/O sum[178159]:cur[2665], unzip sum[0]:cur[0]
 --------------
 ROW OPERATIONS
 --------------
 0 queries inside InnoDB, 0 queries in queue
 0 read views open inside InnoDB
 Process ID=16686, Main thread ID=140092498769664 , state=sleeping
 Number of rows inserted 468088646, updated 10678363, deleted 0, read 890691733
 3056.35 inserts/s, 127.56 updates/s, 0.00 deletes/s, 403057.39 reads/s
 Number of system rows inserted 248, updated 420, deleted 707, read 33861
 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
 ----------------------------
 END OF INNODB MONITOR OUTPUT
 ============================

write bandwith screenshot

Upvotes: 2

Views: 239

Answers (1)

Jean Jung
Jean Jung

Reputation: 1210

Your problem seems to be related to Checkpointing Age. As you are running a huge query, InnoDB is not able to checkpoint the modifications written to the relay log, causing the HLL (History List Length) to increase indefinitely. As time passes by, each read will be slower and slower. That's because MySQL needs to undo the changes that were committed after the transaction started, guaranteeing the data read is consistent with the transaction's start time.

By checking the InnoDB status report, you can see your current list length is 80M (Log written up to - Last checkpoint at), which is quite huge.

I would suggest switching to a batch approach, copying the data in chunks, using an indexed access key to partition the batches, and avoiding long-running queries.

And always remember, databases are designed to be really efficient and reliable applications. Efficiency here does not necessarily mean all the available resources will be consumed. The key to databases' sustainable performance success is to balance resource usage, maximizing availability without prejudicing performance.

References

  1. Percona - InnoDB transaction history often hides dangerous ‘debt’

  2. Percona - InnoDB Flushing in Action for Percona Server for MySQL

  3. Percona - Chasing a Hung MySQL Transaction: InnoDB History Length Strikes Back

Upvotes: 2

Related Questions