Bug #82524 Significant innodb load performance regression since version 5.5
Submitted: 10 Aug 2016 8:36 Modified: 25 Aug 2016 8:22
Reporter: Mark Kirkwood Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:5.6, 5.6.32, 5.7.14 OS:Ubuntu (16.04)
Assigned to: CPU Architecture:Any

[10 Aug 2016 8:36] Mark Kirkwood
Description:
Load performance for innodb tables in newer (>= 5.6) versions is almost halved compared to 5.5.

How to repeat:
Use LOAD command on a table, e.g:

mysql> CREATE TABLE accounts (
    aid integer NOT NULL,
    bid integer,
    abalance integer,
    filler character(84)
);

mysql> LOAD DATA INFILE '/tmp/accounts.dat'
       INTO TABLE accounts FIELDS TERMINATED BY ',';
(5.5)
Query OK, 1000000 rows affected (29.62 sec)
Records: 1000000  Deleted: 0  Skipped: 0  Warnings: 0

(5.6)
Query OK, 1000000 rows affected (54.97 sec)
Records: 1000000  Deleted: 0  Skipped: 0  Warnings: 0

Servers configured identically, running on same host:

$ cat my.cnf
...
default_storage_engine = innodb
innodb_data_file_path = ibdata1:12M:autoextend
innodb_buffer_pool_size = 256M
innodb_additional_mem_pool_size = 4M
innodb_log_file_size = 256M
innodb_log_buffer_size = 32M
innodb_file_per_table = 1

5.7 very similar to 5.6, i.e significant slower than 5.5.
[10 Aug 2016 8:46] Mark Kirkwood
Pref report output for mysql 5.5

Attachment: perf.out.5.5 (application/octet-stream, text), 156.73 KiB.

[10 Aug 2016 8:47] Mark Kirkwood
Perf output for mysql 5.6

Attachment: perf.out.5.6 (application/octet-stream, text), 524.01 KiB.

[11 Aug 2016 13:45] Umesh Shastry
Hello Mark,

Thank you for the bug report.
I'm not seeing the huge difference on my test box using the provided conf files. Could you please provide exact MySQL version details in 5.5, 5.6 and 5.7 along with the unaltered conf files to reproduce the issue at our end?

 -- Dummy data
 
 CREATE TABLE accounts (
    aid integer NOT NULL,
    bid integer,
    abalance integer,
    filler character(84)
);
- perl snippet to create load file

for(my $i=1; $i <= 1000000; $i++) {
  my $txt = 'x' x 83;
  print "$i,$i,$i,$txt\n";
}

3. Load the data into table
load data local infile '/tmp/accounts.dat' into table accounts fields terminated by ',';

--

#cat my.cnf/my_new.cnf
[mysqld]
default_storage_engine = innodb
innodb_data_file_path = ibdata1:12M:autoextend
innodb_buffer_pool_size = 256M
innodb_additional_mem_pool_size = 4M
innodb_log_file_size = 256M
innodb_log_buffer_size = 32M
innodb_file_per_table = 1

rm -rf 71039

scripts/mysql_install_db --defaults-file=./my.cnf --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.5.51 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.5.51/71039
bin/mysqld --defaults-file=./my.cnf --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.5.51 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.5.51/71039 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.5.51/71039/log.err 2>&1 &

5.5.51>load data local infile '/tmp/accounts.dat' into table accounts fields terminated by ',';
Query OK, 1000000 rows affected (4.93 sec)
Records: 1000000  Deleted: 0  Skipped: 0  Warnings: 0

5.5.51>\q
Bye

rm -rf 71039
scripts/mysql_install_db --defaults-file=./my.cnf  --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.6.32 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.6.32/71039 -v
bin/mysqld --defaults-file=./my.cnf --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.6.32 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.6.32/71039 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.6.32/71039/log.err  2>&1 &

-- 5.6.32 with/without p_s enabled

5.6.32>use test
Database changed
5.6.32> CREATE TABLE accounts (
    ->     aid integer NOT NULL,
    ->     bid integer,
    ->     abalance integer,
    ->     filler character(84)
    -> );
Query OK, 0 rows affected (0.00 sec)

5.6.32>load data local infile '/tmp/accounts.dat' into table accounts fields terminated by ',';
Query OK, 1000000 rows affected (5.04 sec)
Records: 1000000  Deleted: 0  Skipped: 0  Warnings: 0

-- 5.7.14 with/without p_s enabled

rm -rf 71039
bin/mysqld   --defaults-file=./my_new.cnf --initialize-insecure --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.14 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.14/71039 -v
bin/mysqld --defaults-file=./my_new.cnf --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.14 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.14/71039 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.14/71039/log.err 2>&1 &

5.7.14>use test
Database changed
5.7.14> CREATE TABLE accounts (
    ->     aid integer NOT NULL,
    ->     bid integer,
    ->     abalance integer,
    ->     filler character(84)
    -> );
Query OK, 0 rows affected (0.01 sec)

5.7.14>load data local infile '/tmp/accounts.dat' into table accounts fields terminated by ',';
Query OK, 1000000 rows affected (7.44 sec)
Records: 1000000  Deleted: 0  Skipped: 0  Warnings: 0

Thanks,
Umesh
[17 Aug 2016 5:56] Mark Kirkwood
5.5 config

Attachment: my-5.5.cnf (application/octet-stream, text), 5.04 KiB.

[17 Aug 2016 5:57] Mark Kirkwood
5.7 config

Attachment: my-5.7.cnf (application/octet-stream, text), 5.17 KiB.

[17 Aug 2016 5:57] Mark Kirkwood
Data generation

Attachment: gendata.py (text/x-python), 1.82 KiB.

[17 Aug 2016 6:02] Mark Kirkwood
Thanks for taking a look!

My versions are: 5.5.47, 5.6.28 and 5.7.14. All a built from src (5.6 and 5.7 via cmake with whatever default compiler options are set).

Also I note you are doing LOAD DATA LOCAL INFILE whereas I'm doing LOAD DATA INFILE (I've got LOCAL disabled in the build - I'll try with it enabled to see if anything changes there).

Also I'm wondering if you have accidentally created your 'accounts' table as Myisam rather than Innodb with such a minimal config?
[17 Aug 2016 6:02] Umesh Shastry
Thanks for the conf files.
Also, please share exact MySQL version details in 5.5, 5.6 and 5.7 and output of SHOW CREATE TABLE <table_name>\G details for the all the tables involved.
[17 Aug 2016 6:04] Umesh Shastry
Looks like we posted our notes at the same time, pls ignore my previous note for versions as I see you ahve provided details(if possible provide output of SHOW CREATE TABLE <table_name>\G).
[17 Aug 2016 6:20] Mark Kirkwood
mysql> SHOW CREATE TABLE accounts\G
*************************** 1. row ***************************
       Table: accounts
Create Table: CREATE TABLE `accounts` (
  `aid` int(11) NOT NULL,
  `bid` int(11) DEFAULT NULL,
  `abalance` int(11) DEFAULT NULL,
  `filler` char(84) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)
[18 Aug 2016 8:59] Umesh Shastry
Thank you Mark, I'm not seeing the huge difference between 5.5.51 and 5.6.32(~5sec) but certainly noticing it in 5.7.14 build with provided conf file, table structure, and data.
[18 Aug 2016 9:00] Umesh Shastry
test results

Attachment: 82524.results (application/octet-stream, text), 12.77 KiB.

[24 Aug 2016 7:36] Mark Kirkwood
Very interesting. You are not seeing a very big difference. And even more interesting - you are seeing LOAD performance about 10x faster than I am (I've checked on a number of platforms, none are seeing results as fast as yours - most about similar to mine). I wonder if you are using some special compilation options? Or perhaps filesystem or mount options?
[25 Aug 2016 8:21] Mark Kirkwood
Arrg - I see the problem. I'm setting up cmake like:

cmake . -DWITH_ARCHIVE_STORAGE_ENGINE=1 \
        -DWITH_DEBUG=1 \                  <==============
        -DENABLED_LOCAL_INFILE=1 \
        -DCMAKE_INSTALL_PREFIX=/usr/local/mysql/5.5

not realizing that WITH_DEBUG disables optimization! Doh and apologies.

I am not seeing exactly what you are seeing (and LOAD DATA INFILE is same sort of times as you are posting for 10000000 rows). In particular:

- 5.5 and 5.6 about the same
- 5.7 approx 19% slower
[25 Aug 2016 8:22] Mark Kirkwood
I am *now* seeing the same as you I mean.