MySQL Bugs: #38946: Inconsistent performance and potential bottlenecks in backup

Bug #38946	Inconsistent performance and potential bottlenecks in backup
Submitted:	21 Aug 2008 18:25	Modified:	9 Jul 2009 21:19
Reporter:	Chuck Bell	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Backup	Severity:	S3 (Non-critical)
Version:	6.0.8	OS:	Windows
Assigned to:	Hema Sridharan	CPU Architecture:	Any

Description:
The backup system is exhibiting several unexplained performance issues:

1) The first backup command issued on a cold boot takes many times longer than subsequent backups (running the same backup command).

2) When using compression, there is a huge performance slowdown while backing up MyISAM but not InnoDB.

These and other performance issues should be identified and repaired.

How to repeat:
Run backup on cold boot then repeat.
Run backup of MyISAM tables with compression then repeat with InnoDB.

Suggested fix:
Performance diagnostics should be run to determine bottlenecks and plans formed to eliminate them.

The following demonstrates how backup has some severe inconsistencies WRT execution times. 

Setup: This should be run from a cold boot server (one that was just started).

Note the disparities of the execution times for a small dataset.

mysql> CREATE DATABASE test_small;
Query OK, 1 row affected (0.02 sec)

mysql> CREATE TABLE test_small.t1 (a int);
Query OK, 0 rows affected (0.00 sec)

mysql> INSERT INTO test_small.t1 VALUES (1), (2), (3), (4), (5);
Query OK, 5 rows affected (0.01 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_small TO 'sm1.bak';
+-----------+
| backup_id |
+-----------+
| 520       |
+-----------+
1 row in set (0.19 sec)

mysql> BACKUP DATABASE test_small TO 'sm2.bak';
+-----------+
| backup_id |
+-----------+
| 521       |
+-----------+
1 row in set (4.91 sec)

mysql> BACKUP DATABASE test_small TO 'sm3.bak';
+-----------+
| backup_id |
+-----------+
| 522       |
+-----------+
1 row in set (0.14 sec)

mysql> BACKUP DATABASE test_small TO 'sm4.bak';
+-----------+
| backup_id |
+-----------+
| 523       |
+-----------+
1 row in set (5.49 sec)

mysql> BACKUP DATABASE test_small TO 'sm5.bak';
+-----------+
| backup_id |
+-----------+
| 524       |
+-----------+
1 row in set (0.11 sec)

mysql> BACKUP DATABASE test_small TO 'sm6.bak';
+-----------+
| backup_id |
+-----------+
| 525       |
+-----------+
1 row in set (0.16 sec)

mysql>

-----------------------------------------------------------

Setup: This should be run from a cold boot server (one that was just started).

Note the disparities of the execution times for a large dataset.

mysql> CREATE DATABASE test_large;
Query OK, 1 row affected (0.03 sec)

mysql> CREATE TABLE test_large.t1 (a int);
Query OK, 0 rows affected (0.02 sec)

mysql> CREATE PROCEDURE test_large.fill_table ()
    -> BEGIN
    -> declare table_size, max_table_size int default 0;
    -> select @@session.max_heap_table_size into max_table_size;
    -> delete from t1;
    -> insert into t1 values (repeat('a', 255));
    -> repeat
    ->   insert into t1 select * from t1;
    ->   select count(*)*255 from t1 into table_size;
    ->   until table_size > max_table_size*2
    -> end repeat;
    -> END |
Query OK, 0 rows affected (0.00 sec)

mysql> DELIMITER ;
mysql> call test_large.fill_table();
Query OK, 0 rows affected, 1 warning (2.43 sec)

mysql> SELECT count(*) FROM test_large.t1;
+----------+
| count(*) |
+----------+
|   262144 |
+----------+
1 row in set (0.00 sec)

mysql> BACKUP DATABASE test_large TO 'lg1.bak';
+-----------+
| backup_id |
+-----------+
| 531       |
+-----------+
1 row in set (0.17 sec)

mysql> BACKUP DATABASE test_large TO 'lg2.bak';
+-----------+
| backup_id |
+-----------+
| 532       |
+-----------+
1 row in set (0.16 sec)

mysql> BACKUP DATABASE test_large TO 'lg3.bak';
+-----------+
| backup_id |
+-----------+
| 533       |
+-----------+
1 row in set (0.14 sec)

mysql> BACKUP DATABASE test_large TO 'lg4.bak';
+-----------+
| backup_id |
+-----------+
| 534       |
+-----------+
1 row in set (0.16 sec)

mysql> BACKUP DATABASE test_large TO 'lg5.bak';
+-----------+
| backup_id |
+-----------+
| 535       |
+-----------+
1 row in set (0.13 sec)

mysql> RESTORE FROM 'lg3.bak';
+-----------+
| backup_id |
+-----------+
| 536       |
+-----------+
1 row in set (0.11 sec)

mysql> SELECT count(*) FROM test_large.t1;
+----------+
| count(*) |
+----------+
|   262144 |
+----------+
1 row in set (0.00 sec)

mysql>

Questions
---------
Why does the smaller database take so much longer to backup?
Why does the larger database not exhibit the same strange delays?

Using the same database from the last test, observe the difference in execution between backup executed with InnoDB and MyISAM and compression. 

mysql> ALTER TABLE test_large.t1 ENGINE=INNODB;
Query OK, 262144 rows affected (4.55 sec)
Records: 262144  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'lg6.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 537       |
+-----------+
1 row in set (2.09 sec)

mysql> BACKUP DATABASE test_large TO 'lg7.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 538       |
+-----------+
1 row in set (2.04 sec)

mysql> BACKUP DATABASE test_large TO 'lg8.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 539       |
+-----------+
1 row in set (2.08 sec)

mysql> ALTER TABLE test_large.t1 ENGINE=MYISAM;
Query OK, 262144 rows affected (1.45 sec)
Records: 262144  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'lg9.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 540       |
+-----------+
1 row in set (0.25 sec)

mysql> BACKUP DATABASE test_large TO 'lg10.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 541       |
+-----------+
1 row in set (0.23 sec)

mysql> BACKUP DATABASE test_large TO 'lg11.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 542       |
+-----------+
1 row in set (0.27 sec)

mysql>

---------------------------------------------------

Now the same using myisam and memory...

mysql> ALTER TABLE test_large.t1 ENGINE=MEMORY;
Query OK, 262144 rows affected (0.41 sec)
Records: 262144  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'lg12.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 543       |
+-----------+
1 row in set (1.25 sec)

mysql> BACKUP DATABASE test_large TO 'lg13.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 544       |
+-----------+
1 row in set (1.26 sec)

mysql> BACKUP DATABASE test_large TO 'lg14.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 545       |
+-----------+
1 row in set (1.26 sec)

mysql>

-----------------------------------------------

Now the same test on the smaller database:

mysql> SELECT count(*) FROM test_small.t1;
+----------+
| count(*) |
+----------+
|        5 |
+----------+
1 row in set (0.00 sec)

mysql> ALTER TABLE test_small.t1 ENGINE=MYISAM;
Query OK, 5 rows affected (0.01 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'sm11.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 546       |
+-----------+
1 row in set (1.31 sec)

mysql> BACKUP DATABASE test_large TO 'sm12.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 547       |
+-----------+
1 row in set (1.28 sec)

mysql> BACKUP DATABASE test_large TO 'sm13.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 548       |
+-----------+
1 row in set (1.25 sec)

mysql> ALTER TABLE test_small.t1 ENGINE=INNODB;
Query OK, 5 rows affected (0.03 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'sm14.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 549       |
+-----------+
1 row in set (1.20 sec)

mysql> BACKUP DATABASE test_large TO 'sm15.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 550       |
+-----------+
1 row in set (1.22 sec)

mysql> BACKUP DATABASE test_large TO 'sm16.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 551       |
+-----------+
1 row in set (1.22 sec)

mysql> ALTER TABLE test_small.t1 ENGINE=MEMORY;
Query OK, 5 rows affected (0.03 sec)
Records: 5  Duplicates: 0  Warnings: 0

mysql> BACKUP DATABASE test_large TO 'sm17.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 552       |
+-----------+
1 row in set (1.28 sec)

mysql> BACKUP DATABASE test_large TO 'sm18.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 553       |
+-----------+
1 row in set (1.29 sec)

mysql> BACKUP DATABASE test_large TO 'sm19.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 554       |
+-----------+
1 row in set (1.29 sec)

mysql>

Questions
---------
Given MyISAM is using a native driver (which may explain its superior performance -- which should be documented at the least if true), why is there such a discrepency between the large database and the small one?

I used Windows Vista 32-bit and Ubuntu 64-bit. Problem is much more obvious on Windows (naturally) but does exist on both platforms.

Version used is 6.0.8-alpha-debug in the mysql-6.0-backup tree.

Replayed issue described regarding compression:

mysql> alter table test_large.t1 engine=myisam;
Query OK, 262144 rows affected (1.44 sec)
Records: 262144  Duplicates: 0  Warnings: 0

mysql> select count(*) from test_large.t1;
+----------+
| count(*) |
+----------+
|   262144 |
+----------+
1 row in set (0.01 sec)

mysql> BACKUP DATABASE test_large TO 'l01.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 585       |
+-----------+
1 row in set (0.30 sec)

mysql> BACKUP DATABASE test_large TO 'l02.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 586       |
+-----------+
1 row in set (0.28 sec)

mysql> BACKUP DATABASE test_large TO 'l03.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 587       |
+-----------+
1 row in set (0.27 sec)

mysql> BACKUP DATABASE test_large TO 'l04.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 588       |
+-----------+
1 row in set (0.20 sec)

mysql> alter table test_large.t1 engine=INNODB;
Query OK, 262144 rows affected (4.04 sec)
Records: 262144  Duplicates: 0  Warnings: 0

mysql> select count(*) from test_large.t1;
+----------+
| count(*) |
+----------+
|   262144 |
+----------+
1 row in set (0.95 sec)

mysql> BACKUP DATABASE test_large TO 'l05.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 589       |
+-----------+
1 row in set (2.31 sec)

mysql> BACKUP DATABASE test_large TO 'l06.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 590       |
+-----------+
1 row in set (2.15 sec)

mysql> BACKUP DATABASE test_large TO 'l07.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 591       |
+-----------+
1 row in set (2.21 sec)

mysql> BACKUP DATABASE test_large TO 'l08.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 592       |
+-----------+
1 row in set (2.25 sec)

mysql>

Questions still apply: why is myisam so much faster?

I executed the following tests in windows(Win 2008 64bit) and Linux after cold boot.

1. Run backup on cold boot and check the times.
2. Run backup with compression using MyISAM and InnoDB storage engines.

I am not able to see any performance bottlenecks for both the scenarios mentioned above. In such case, I shall go ahead and change the status of the bug to Can't Repeat.

Results:

Part 1
======
The time taken for backup immediately after coldboot is not inconsistent. I constantly see the backup times for small DB as 0.14 and 0.15 secs. Even when I use larger database the time taken for backup is not significantly different than smaller database. The times for large database is 0.19secs

mysql> BACKUP DATABASE test_small TO 'sm11.bak';
+-----------+
| backup_id |
+-----------+
| 300       |
+-----------+
1 row in set (0.15 sec)

mysql> BACKUP DATABASE test_small TO 'sm12.bak';
+-----------+
| backup_id |
+-----------+
| 301       |
+-----------+
1 row in set (0.14 sec)

mysql> BACKUP DATABASE test_large TO 'lg111.bak';
+-----------+
| backup_id |
+-----------+
| 307       |
+-----------+
1 row in set (0.19 sec)

mysql> BACKUP DATABASE test_large TO 'lg113.bak';
+-----------+
| backup_id |
+-----------+
| 308       |
+-----------+
1 row in set (0.19 sec)

Part 2
======
Performing backup of MyISAM tables with compression for small database does not take long time than for large database. 
a. Backup time of MyISAM table with compression for small database is 0.14secs

mysql> BACKUP DATABASE test_small TO 'sm122.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 313       |
+-----------+
1 row in set (0.14 sec)

mysql> BACKUP DATABASE test_small TO 'sm125.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 314       |
+-----------+
1 row in set (0.14 sec)

b. Backup time of MyISAM table with compression for larger database is 0.21secs

mysql> BACKUP DATABASE test_large TO 'lg99.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 311       |
+-----------+
1 row in set (0.21 sec)

mysql> BACKUP DATABASE test_large TO 'lg90.bak' WITH COMPRESSION;
+-----------+
| backup_id |
+-----------+
| 312       |
+-----------+
1 row in set (0.20 sec)

NOTE: Infact there is not much of difference in backup time with and without compression.

The performance enhancements and the refinements of the backup code have rendered this bug no longer repeatable.

The only observance once can see from the tests is that Innodb runs about 5 times faster when doing a backup. But with less than a second backup times, it's not an issue any longer.