Percona 8 - LOAD DATA 600+ times slower after creating specific secondary index

MySQL & MariaDB Percona Server for MySQL 8.0
1

I’m using Percona 8.1.0-1 and I’m experiencing an issue with LOAD DATA getting 600+ times slower after creating a specific secondary index.

I’m migrating a database with a single table from Percona 5.7. The table is quite big with 30 billion rows. I exported the data with --tab option and moved the file to another server.

I initially created the table without any indexes and started importing with LOAD DATA.

CREATE TABLE `smtp_logs` (
  `id` bigint NOT NULL AUTO_INCREMENT,
  `record_type` varchar(255) DEFAULT NULL,
  `time_logged` datetime DEFAULT NULL,
  `time_queued` datetime DEFAULT NULL,
  `orig` varchar(255) DEFAULT NULL,
  `rcpt` varchar(255) DEFAULT NULL,
  `dlv_source_ip` varchar(255) DEFAULT NULL,
  `dlv_destination_ip` varchar(255) DEFAULT NULL,
  `account_id` int DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci ROW_FORMAT=COMPRESSED

This is a dedicated hardware and only Percona is running. I got an average of 30.000 inserts/s.

I still had to import around 100 million new rows ( added in the live server after the initial import ). Before that, I decided to create the secondary indexes which are required for this table:

  KEY `index_smtp_logs_on_time_logged_and_dlv_source_ip` (`time_logged`,`dlv_source_ip`),
  KEY `index_smtp_logs_on_rcpt` (`rcpt`),
  KEY `index_smtp_logs_on_account_id_and_time_logged` (`account_id`,`time_logged`)

When importing the file with 100 million rows, it was very slow with 50 inserts/s.

I did some tests with Percona 5.7 at the same server and LOAD DATA + secondary indexes. It works as expected and I’m getting around 26.000 inserts/s.

Back to Percona 8. After some debugging, I found out that if I remove index_smtp_logs_on_rcpt, the speeds are back to acceptable levels ( 20.000 inserts/s ).

Is there something different in Percona 8 that might explain this issue?

My cmd flags looks like this:

--character-set-server=utf8mb4 --collation-server=utf8mb4_general_ci --innodb-flush-log-at-trx-commit=0 --innodb-flush-log-at-timeout=120 --innodb-redo-log-capacity=10737418240 --innodb-buffer-pool-instances=8 --innodb-buffer-pool-size=25769803776 --innodb-autoinc-lock-mode=2 --local-infile=1 --disable-log-bin --max-allowed-packet=256M --skip-name-resolve --optimizer-search-depth=0
2

Have you tried this on 8.0.35? 8.1 is considered an “innovation release” and is more of a public beta in my opinion. 8.1 isn’t even an option anymore on MySQL’s official downloads page; they have moved to 8.3-innovation.

3

Hi,

I’m very sorry about the delay but I was only able to test this again now. I’ve tried with version 8.0.35 and the issue is the same.

When the index is present, I’m getting 50-70 inserts/s.

I also noticed that CPU usage is very slow ( 10-15% ) and so is the disk usage ( 1-2MB/s read/write ).

In case it helps, there is the innodb engine status:

mysql> show engine innodb status \G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-01-27 17:44:19 139696428545600 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 86751 srv_active, 0 srv_shutdown, 89861 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 864433
OS WAIT ARRAY INFO: signal count 959186
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 3051
Purge done for trx's n:o < 3048 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421172609024200, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421172609023352, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421172609022504, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421172609021656, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 3050, ACTIVE 75001 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 4214322
MySQL thread id 28, OS thread handle 139696229000768, query id 372 127.0.0.1 root executing
LOAD DATA INFILE '/var/lib/mysql-files/smtp_logs.txt' INTO TABLE test.smtp_logs
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests ((null))
I/O thread 1 state: waiting for completed aio requests (insert buffer 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)
Pending normal aio reads: [0, 1, 1, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
141055454 OS file reads, 34985884 OS file writes, 38017 OS fsyncs
76.34 reads/s, 8192 avg bytes/read, 107.31 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 262138 merges
merged operations:
 insert 262226, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 5312557, node heap has 0 buffer(s)
Hash table size 5312557, node heap has 1 buffer(s)
Hash table size 5312557, node heap has 0 buffer(s)
Hash table size 5312557, node heap has 0 buffer(s)
Hash table size 5312557, node heap has 1 buffer(s)
Hash table size 5312557, node heap has 0 buffer(s)
Hash table size 5312557, node heap has 0 buffer(s)
Hash table size 5312557, node heap has 0 buffer(s)
62.73 hash searches/s, 316.42 non-hash searches/s
---
LOG
---
Log sequence number          46494012
Log buffer assigned up to    46494012
Log buffer completed up to   46494012
Log written up to            46494012
Log flushed up to            46494012
Added dirty pages up to      46494012
Pages flushed up to          44387061
Last checkpoint at           44387061
Log minimum file id is       0
Log maximum file id is       0
Modified age no less than    2106951
Checkpoint age               2106951
Max checkpoint age           10846166016
3727 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 645519
Buffer pool size   1834784
Buffer pool size, bytes 30061101056
Free buffers       8111
Database pages     3041779
Old database pages 1122721
Modified db pages  2273737
Pending reads      2
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1481231, not young 27832548
15.36 youngs/s, 133.78 non-youngs/s
Pages read 130944788, created 16727717, written 22081989
76.11 reads/s, 29.55 creates/s, 107.31 writes/s
Buffer pool hit rate 962 / 1000, young-making rate 7 / 1000 not 67 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 3041779, unzip_LRU len: 304284
I/O sum[57024]:cur[1184], unzip sum[47400]:cur[928]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1010
Database pages     380200
Old database pages 140329
Modified db pages  284211
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 179007, not young 3312795
1.65 youngs/s, 12.76 non-youngs/s
Pages read 16365518, created 2092079, written 2755763
7.33 reads/s, 14.89 creates/s, 19.15 writes/s
Buffer pool hit rate 916 / 1000, young-making rate 19 / 1000 not 146 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380200, unzip_LRU len: 38040
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 1
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1018
Database pages     380198
Old database pages 140329
Modified db pages  281037
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 179068, not young 3228948
1.42 youngs/s, 16.31 non-youngs/s
Pages read 16364524, created 2090034, written 2754813
9.93 reads/s, 8.75 creates/s, 25.53 writes/s
Buffer pool hit rate 949 / 1000, young-making rate 7 / 1000 not 84 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380198, unzip_LRU len: 38029
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 2
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1005
Database pages     380216
Old database pages 140340
Modified db pages  280942
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 179142, not young 3356651
2.84 youngs/s, 17.73 non-youngs/s
Pages read 16378919, created 2090427, written 2756525
10.16 reads/s, 0.24 creates/s, 10.64 writes/s
Buffer pool hit rate 891 / 1000, young-making rate 30 / 1000 not 190 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380216, unzip_LRU len: 38041
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 3
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1019
Database pages     380199
Old database pages 140328
Modified db pages  282692
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 178317, not young 3378998
2.36 youngs/s, 8.04 non-youngs/s
Pages read 16387109, created 2088692, written 2761695
5.44 reads/s, 0.24 creates/s, 8.51 writes/s
Buffer pool hit rate 927 / 1000, young-making rate 32 / 1000 not 109 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380199, unzip_LRU len: 38031
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 4
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1019
Database pages     380198
Old database pages 140330
Modified db pages  283689
Pending reads      2
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 178749, not young 3147362
0.95 youngs/s, 18.91 non-youngs/s
Pages read 16358462, created 2092068, written 2755440
10.16 reads/s, 3.55 creates/s, 9.93 writes/s
Buffer pool hit rate 932 / 1000, young-making rate 6 / 1000 not 126 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380198, unzip_LRU len: 38034
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 5
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1018
Database pages     380230
Old database pages 140340
Modified db pages  291353
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 227253, not young 4773664
1.89 youngs/s, 23.40 non-youngs/s
Pages read 16354900, created 2091729, written 2764688
12.76 reads/s, 0.00 creates/s, 16.07 writes/s
Buffer pool hit rate 986 / 1000, young-making rate 2 / 1000 not 27 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380230, unzip_LRU len: 38035
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 6
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1021
Database pages     380273
Old database pages 140360
Modified db pages  285021
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 179763, not young 3345193
3.07 youngs/s, 17.25 non-youngs/s
Pages read 16361075, created 2090635, written 2761581
9.69 reads/s, 0.00 creates/s, 8.98 writes/s
Buffer pool hit rate 896 / 1000, young-making rate 33 / 1000 not 186 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380273, unzip_LRU len: 38030
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
---BUFFER POOL 7
Buffer pool size   229348
Buffer pool size, bytes 3757637632
Free buffers       1001
Database pages     380265
Old database pages 140365
Modified db pages  284792
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 179932, not young 3288937
1.18 youngs/s, 19.38 non-youngs/s
Pages read 16374281, created 2092053, written 2771484
10.64 reads/s, 1.89 creates/s, 8.51 writes/s
Buffer pool hit rate 976 / 1000, young-making rate 2 / 1000 not 45 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 380265, unzip_LRU len: 38044
I/O sum[7128]:cur[148], unzip sum[5925]:cur[116]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
1 RW transactions active inside InnoDB
Process ID=1, Main thread ID=139673752757824 , state=sleeping
Number of rows inserted 4218361, updated 0, deleted 0, read 133663755
66.48 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 132, updated 332, deleted 73, read 10467
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)
4

Hello @fernandomm,
After raising your issue with our team, they have requested you create a flamegraph for each of your various tests so they can compare the execution paths of the code.

5

Hi,

Is the generated image of the flamegraph enough? I’m attaching two images: one with and another without the index.

This captured several minutes but not the full import since it takes a long time to complete.

With index:

With index
With index1200×953 146 KB

Without index:

Without index
Without index1200×774 119 KB

Thanks!

6

Thank you for that. Can you upload the SVGs? For transparency, there’s no guarantee of a quick solution. Many in the MySQL community overall are complaining about poor performance from core 8.0 vs 5.7 (ie: it’s not just Percona MySQL, it’s Community version as well). I will pass this info along to our engineers and maybe they can discern what’s not working well.

7

Hi,

Thanks for your quick replies.

I’m not able to upload the svg files here but they are available at Filebin | vnjlwpfek81xoa90

I understand the performance issues in 8.0, but in this case, the performance drops significantly, to the point that we have to stick with 5.7 for now.

Since it looks like it’s happening when the index includes a varchar column, I’m wondering if it’s related to charset conversion or something like that.

8

Thanks. I’ve downloaded them and will provide to engineering. In my n00b view, there is certainly a lot more IO activity on the graph with index.
Have you tried without the page compression? I see a fair amount of the graphs dealing with zip compress/decompress/IO. (Just a thought)

I was looking in the flamegraph for something that might relate to that, but again, n00b here, and I didn’t see anything immediate. Another test would be to make everything latin1 and see.