MySQL Bugs: #32784: Timeout in test "innodb_charset": InnoDB much slower than other handlers

Bug #32784	Timeout in test "innodb_charset": InnoDB much slower than other handlers
Submitted:	27 Nov 2007 18:22	Modified:	6 May 2009 14:46
Reporter:	Joerg Bruehe	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Tests	Severity:	S5 (Performance)
Version:	5.0.51-54	OS:	Other (see bug text)
Assigned to:	Patrick Crews	CPU Architecture:	Any

Description:
This occurred in a build of 5.0.51 (community tree):

Of the "funcs2" suite, all 4 tests were taken 
(innodb_charset, memory_charset, myisam_charset, ndb_charset).

The latter 3 failed with bug#31556,
as did the first (innodb_charset) on most platforms;
but on some this test (and *only* this one, of the 4) ran into a timeout.

As the test case timeout is set at 900 seconds
and the total run time of this suite on these hosts ranges from 1206 to 1501 seconds,
it seems the InnoDB test takes much longer than the three others.

All tests execute exactly the same commands (using include files), the only difference is the handler used for the test table.

=====
innodb_charset                 [ fail ]  timeout

Stopping All Servers
=====

Affected platforms:
   AIX 5.2 (both 32 + 64 bit)
   Solaris 10 Sparc (both 32 + 64 bit)
   Linux IA64 using ICC (both tar.gz and RPM build)

The other "*_charset" tests fail, so their run time is not available,
and this test's run time on other hosts is also not logged due to it failing
(bug#31556).

Bug#31556 is pushed into 5.0.52, so tests in that version may provide more info about the run time.

How to repeat:
Run the "funcs_2" suite.

Vasil,

please investigate.

--Heikki

With the 5.0 BK as of Nov 30 2007, configured with

./configure --with-plugins=innobase --with-extra-charsets=all

I get these results on FreeBSD-7.0/amd64:

Logging: ./mysql-test-run.pl --suite=funcs_2
MySQL Version 5.0.54
Skipping ndbcluster, mysqld not compiled with ndbcluster
Skipping SSL, mysqld not compiled with SSL
Using MTR_BUILD_THREAD      = 0
Using MASTER_MYPORT         = 9306
Using MASTER_MYPORT1        = 9307
Using SLAVE_MYPORT          = 9308
Using SLAVE_MYPORT1         = 9309
Using SLAVE_MYPORT2         = 9310
Using IM_PORT               = 9312
Using IM_MYSQLD1_PORT       = 9313
Using IM_MYSQLD2_PORT       = 9314
Killing Possible Leftover Processes
Removing Stale Files
Creating Directories
Installing Master Database
=======================================================
Starting Tests in the 'funcs_2' suite

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

innodb_charset                 [ pass ]          20371
memory_charset                 [ pass ]           5533
myisam_charset                 [ pass ]           6748
ndb_charset                    [ skipped ]   No ndbcluster support
-------------------------------------------------------
Stopping All Servers
All 3 tests were successful.
The servers were restarted 1 times
Spent 32.652 of 38 seconds executing testcases

So you used sources which included the fix for bug#31556, the test passed, and you got timing information - good !

We now know that using the InnoDB storage engine the test was about 3 to 4 times slower than using MyISAM or Memory,
and this explains why the timeouts are limited ot using the InnoDB engine.

I do not know whether the test does so many data changes that writing this info to disk in a recoverable way explains the factor of 3 to 4.

With the 5.0 BK as of Dec 04 2007, configured with

./configure --with-plugins=innobase --with-extra-charsets=all

I get these results on Solaris 10 (SunOS 5.10)/i386:

Logging: ./mysql-test-run.pl --suite=funcs_2
MySQL Version 5.0.54
Skipping ndbcluster, mysqld not compiled with ndbcluster
Skipping SSL, mysqld not compiled with SSL
Using MTR_BUILD_THREAD      = 0
Using MASTER_MYPORT         = 9306
Using MASTER_MYPORT1        = 9307
Using SLAVE_MYPORT          = 9308
Using SLAVE_MYPORT1         = 9309
Using SLAVE_MYPORT2         = 9310
Using IM_PORT               = 9312
Using IM_MYSQLD1_PORT       = 9313
Using IM_MYSQLD2_PORT       = 9314
Killing Possible Leftover Processes
Removing Stale Files
Creating Directories
Installing Master Database
=======================================================
Starting Tests in the 'funcs_2' suite

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

innodb_charset                 [ pass ]         302810
memory_charset                 [ pass ]           6932
myisam_charset                 [ pass ]           8310
ndb_charset                    [ skipped ]   No ndbcluster support
-------------------------------------------------------
Stopping All Servers
All 3 tests were successful.
The servers were restarted 1 times
Spent 318.052 of 331 seconds executing testcases

After applying this patch:

--- patch begins here ---
--- mysql-test/suite/funcs_2/charset/charset_master.test.orig   Tue Dec  4 04:26:12 2007
+++ mysql-test/suite/funcs_2/charset/charset_master.test        Tue Dec  4 04:22:54 2007
@@ -13,6 +13,10 @@
 let $check_ucs2_csets= 1;
 let $check_utf8_csets= 1;
 
+--disable_query_log
+SET autocommit=0;
+--enable_query_log
+
 #
 # Check all charsets/collation combinations
 #
--- patch ends here ---

I get these results on the same Solaris machine:

Logging: ./mysql-test-run.pl --suite=funcs_2
MySQL Version 5.0.54
Skipping ndbcluster, mysqld not compiled with ndbcluster
Skipping SSL, mysqld not compiled with SSL
Using MTR_BUILD_THREAD      = 0
Using MASTER_MYPORT         = 9306
Using MASTER_MYPORT1        = 9307
Using SLAVE_MYPORT          = 9308
Using SLAVE_MYPORT1         = 9309
Using SLAVE_MYPORT2         = 9310
Using IM_PORT               = 9312
Using IM_MYSQLD1_PORT       = 9313
Using IM_MYSQLD2_PORT       = 9314
Killing Possible Leftover Processes
Removing Stale Files
Creating Directories
Installing Master Database
=======================================================
Starting Tests in the 'funcs_2' suite

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

innodb_charset                 [ pass ]          21902
memory_charset                 [ pass ]          11703
myisam_charset                 [ pass ]          21857
ndb_charset                    [ skipped ]   No ndbcluster support
-------------------------------------------------------
Stopping All Servers
All 3 tests were successful.
The servers were restarted 1 times
Spent 55.462 of 99 seconds executing testcases

Probably it is differently loaded now, but the important thing is that now innodb test takes as much time as the myisam test.

Changing category to "tests", please set autocommit to 0 as in the included patch.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/71873

2748 Patrick Crews	2009-04-10
      Bug#32784: Timeout in test "innodb_charset": InnoDB much slower than other handlers
      
      Using the Innobase-supplied patch to correct this issue.
      Noted that the run-times for MyISAM and Memory variants are increased slightly,
      but the innodb_charset variant has significantly improved run time.

My experiments:
Data for test:  innodb_charset
Number of runs:  100
Total time:  3804588.0
Average run time:  38045.88
Data for test:  memory_charset
Number of runs:  100
Total time:  408587.0
Average run time:  4085.87
Data for test:  myisam_charset
Number of runs:  100
Total time:  473084.0
Average run time:  4730.84
****************************** patch_run*******************************
Data for test:  innodb_charset
Number of runs:  100
Total time:  1247664.0
Average run time:  12476.64
Data for test:  memory_charset
Number of runs:  100
Total time:  465244.0
Average run time:  4652.44
Data for test:  myisam_charset
Number of runs:  100
Total time:  568863.0
Average run time:  5688.63

Ok to push

OK to push.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/72792

2733 Patrick Crews	2009-04-24
      Bug#32784: Timeout in test "innodb_charset": InnoDB much slower than other handlers
      
      Turned off autocommit at the start of this test per Innobase recommendation.
      Noted significant reduction in run time for this test w/ a minor increase in other tests' run-times.

Pushed into 5.0.82 (revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (version source revid:davi.arnaut@sun.com-20090505184158-dvmedh8n472y8np5) (merge vers: 5.0.82) (pib:6)

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Test case changes. No changelog entry needed.

Setting report to NDI pending push into 6.0.x.

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:patrick.crews@sun.com-20090424170240-avba0k4i350scb9q) (merge vers: 6.0.11-alpha) (pib:6)

Test case changes. No changelog entry needed.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)