Bug #19071 Serious performance degradation in 5.0.20 comparing to 5.0.16
Submitted: 13 Apr 2006 7:36 Modified: 10 May 2006 10:00
Reporter: Vadim Tkachenko Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:5.0.20 OS:Linux (RedHat AS 3.0)
Assigned to: Marko Mäkelä CPU Architecture:Any

[13 Apr 2006 7:36] Vadim Tkachenko
Description:
I tested select-range queries 
SELECT c FROM sbtest WHERE id BETWEEN N AND M
against table

CREATE TABLE `sbtest` (
  `id` int(10) unsigned NOT NULL auto_increment,
  `k` int(10) unsigned NOT NULL default '0',
  `c` char(120) NOT NULL default '',
  `pad` char(60) NOT NULL default '',
  PRIMARY KEY  (`id`),
  KEY `k` (`k`) Engine=InnoDB;

5.0.16
clients results (queries per sec)
1   2401.46
4   6380.62
16  7624.88
64  4916.90

5.0.20
1   2186.75
4   3045.16
16  2450.12
64  2375.24

as you see for 4 threads we have degradation 53%
for 16 threads  - 68%

I don't know if it InnoDB or MySQL problem yet

How to repeat:
./sysbench --test=oltp --oltp-table-size=1000000 prepare

select-range benchmark (repeat for each THREADS):
./sysbench --test=oltp --oltp-table-size=1000000 --init-rng=on --mysql-engine-trx=yes --oltp-table-name=sbtest --oltp-test-mode=complex --oltp-point-selects=0 --oltp-simple-ranges=1 --oltp-sum-ranges=0 --oltp-order-ranges=0 --oltp-distinct-ranges=0 --oltp-skip-trx=on --oltp-read-only=on --max-requests=0 --num-threads=THREADS --oltp-dist-type=special --init-rng=on --mysql-db=sbtest --max-time=60 run
[13 Apr 2006 7:45] Vadim Tkachenko
fixed version field
[13 Apr 2006 8:24] Vadim Tkachenko
5.0.19

1  2183.19
4  2989.93
16 2413.03
64 2359.50

5.0.18
1  2401.95
4  6402.10
16 7663.65
64 4933.04

So bug was introduced in 5.0.19
[13 Apr 2006 17:18] Vadim Tkachenko
I don't see such problem with MyISAM,
so I assume it is InnoDB specific
[26 Apr 2006 14:13] Marko Mäkelä
I can repeat this with one thread. __pthread_unlock() gets called almost 3 times as much under 5.0-bk than 5.0.18. This could be due to the changed default value and interpretation of innodb_thread_concurrency. However, when both 5.0.18 and 5.0-bk are run at --innodb_thread_concurrency=4, the performance gap still exists

I found this out with OProfile. I suggest you do the same when you encounter performance degradation. I will continue the investigation until I find an explanation. There is nothing obvious in the change log between 5.0.18 and 5.0.19.
[26 Apr 2006 16:31] Vadim Tkachenko
Marko,

I see very significalty growth of system CPU usage in 5.0.19 comparing to 5.0.18.
So perhaps you added additional system calls or something pthread -related.
[27 Apr 2006 8:39] Marko Mäkelä
Vadim,
yesterday I measured 5.0.18 against 5.0-bk. Today I built 5.0.19, but unfortunately I cannot see any noticeable difference on this system (Pentium-M running at 1400 MHz), one sysbench thread, innodb_buffer_pool_size=120M.

The default setting of innodb_thread_concurrency was not yet changed in 5.0.19. The thread throttling is disabled in both 5.0.18 and 5.0.19 by default.

I'll try to repeat the test on a multi-processor system.
[28 Apr 2006 11:46] Marko Mäkelä
I cannot repeat on a 4×2.4 GHz AMD Opteron running Solaris 10 in 32-bit mode:

5.0.18:
01: 2141.20
04: 6646.25
16: 6684.53
64: 6458.12

5.0.19:
01: 2141.71
04: 6650.98
16: 6784.66
64: 6507.15

Next I will try this on RHAS4.0u2 running on similar hardware, but I won't be able to diagnose until OProfile is installed (and I'm unsure when/if it can be installed).

Vadim, can you repeat it under OProfile and post (or email) the output of "opreport -x --global-percent" and "opreport -t 1 -c -l /path/to/mysqld"? You will need to run an unstripped mysqld, and you will have to do "opcontrol --reset; opcontrol --start" before sysbench and "opcontrol --stop" after.
[28 Apr 2006 12:57] Marko Mäkelä
Sorry, I cannot repeat on our RHAS4.0u2 system running on 4×2.4 GHz AMD Opteron in 64-bit mode. Here are the figures:

5.0.18:
01: 2904.20
04: 7364.05
16: 7441.80
64: 5856.47

5.0.19:
01: 2854.57
04: 7414.15
16: 7614.34
64: 5887.23

Of course, there can be some significant difference between our $HOME/.my.cnf files. Here is mine:

[client]
socket=/tmp/mmakela.sock
[mysqld]
socket=/tmp/mmakela.sock
language=/home/mmakela/mysql-5.0.19/sql/share/english
default-table-type=innodb
datadir=/var/tmp/mmakela
innodb_file_per_table
innodb_data_home_dir=/var/tmp/mmakela
[28 Apr 2006 12:57] Marko Mäkelä
Not enough information was provided for us to be able
to handle this bug. Please re-read the instructions at
http://bugs.mysql.com/how-to-report.php

If you can provide more information, feel free to add it
to this bug and change the status back to 'Open'.

Thank you for your interest in MySQL.

Additional info:

See my previous comment.
[4 May 2006 10:23] Marko Mäkelä
I repeated the test with innodb_buffer_pool_size=512M (to avoid I/O; InnoDB was spending a considerable amount of time calculating page checksums) and with OProfile on our 4×AMD64 host.

For one pair of runs with THREADS=64, 5.0.19 was 10% slower according to opreport, but that could be due to the statistical error or to my misinterpretation of the results. I should perhaps have scaled the CLK_CPU_UNHALTED counts by amount of work done (transactions per second) and waited until the server is idle (the purge thread has finished).

Here are the results without OProfile running:

5.0.18:
01: 3328.77
04: 9157.32
16: 8494.87
64: 7221.01

5.0.19:
01: 3401.33
04: 8695.67
16: 8675.49
64: 7104.22

As you see, there are no big differences. Do you have a gut feeling how much the values reported by sysbench usually fluctuate? For 4 and 64 threads, 5.0.19 is somewhat slower than 5.0.18, but I would tend to believe it can be blamed on the accuracy of the measurement.
[10 May 2006 7:37] Vadim Tkachenko
Still repeatable for me for 5.0.21

Linux quadxeon 2.4.21-15.ELsmp #1 SMP Wed Jun 2 00:59:03 CEST 2004 i686 i686 i386 GNU/Linux

4 way  Intel(R) XEON(TM) MP CPU 2.00GHz

mysql params:
--port=3306 \
--socket=/tmp/mysql.sock \
--user=root $LOGERR \
--datadir=$FSPATH \
--basedir=$BASEPATH \
--max_connections=3000 \
--max_connect_errors=10 \
--table_cache=2048 \
--max_allowed_packet=1M \
--binlog_cache_size=1M \
--max_heap_table_size=64M \
--sort_buffer_size=64K \
--join_buffer_size=1M \
--thread_cache=16 \
--thread_concurrency=16 \
--thread_stack=196K \
--query_cache_size=0 \
--ft_min_word_len=4 \
--default_table_type=MYISAM \
--transaction_isolation=REPEATABLE-READ \
--tmp_table_size=64M \
--skip-locking \
--server-id=1 \
--innodb_status_file=0 \
--innodb_data_home_dir=$FSPATH \
--innodb_data_file_path=ibdata1:100M:autoextend \
--innodb_log_group_home_dir=$FSPATH \
--innodb_buffer_pool_size=256M \
--innodb_additional_mem_pool_size=20M \
--innodb_log_file_size=900M \
--innodb_log_files_in_group=2 \
--innodb_log_buffer_size=8M \
--innodb_flush_log_at_trx_commit=2 \
--innodb_lock_wait_timeout=300 \
--innodb_locks_unsafe_for_binlog=1 \
--innodb_thread_concurrency=1000 \
--timed_mutexes=0
[10 May 2006 8:30] Marko Mäkelä
Vadim,

As I wrote on 26 Apr, --innodb_thread_concurrency=1000 will be interpreted differently starting from 5.0.19. In 5.0.18, innodb_thread_concurrency>=20 is assumed infinite, while 5.0.19 and above interpret innodb_thread_concurrency=0 as infinite.

Also the default value has changed. It may be that 5.0.21 again uses innodb_thread_concurrency=8 by default. In some earlier version of 5.0, the default was changed to infinite. However, it turned out that the thread throttling is still needed to avoid thread thrashing in some heavy workloads.

The difference you experience is probably due to srv_conc_enter_innodb() and srv_conc_exit_innodb() being called. These functions will acquire and release srv_conc_mutex.

To get comparable results, please repeat the test with innodb_thread_concurrency=0 on MySQL >= 5.0.19 and innodb_thread_concurrency>=20 on <5.0.19. Alternatively, try 0<innodb_thread_concurrency<20, which will be interpreted the same.

Please confirm if my analysis is correct. If not, please supply me with the OProfile output I requested.

Marko
[10 May 2006 9:39] Vadim Tkachenko
Marko,

with --innodb_thread_concurrency=0 
MySQL 5.0.21 works as expected,
so problem was with this variable.
[10 May 2006 9:55] Marko Mäkelä
Vadim,
I believe that you saw the difference between 5.0.18 and 5.0.19 for the same reason. The changed interpretation of the variable has been documented at http://dev.mysql.com/doc/refman/5.0/en/innodb-parameters.html.

Alas, the restoration of the default to 8 is not documented. I will track down the bug where the default was changed, and add a request to update the documentation.
[10 May 2006 10:00] Vadim Tkachenko
Marko,

I don't like an idea to change such behavior in production releases.

But if it was, then 
"In 5.0.18, innodb_thread_concurrency>=20 is
assumed infinite, while 5.0.19 and above interpret innodb_thread_concurrency=0
as infinite" should be documented also.
[10 May 2006 17:46] Peter Zaitsev
In general this shows pretty bad design for this  variable.  When it was  just added I asked Heikki to use 0 as "disabled" .    Instead it was done so value 0 actually means 1.  And value other 500 means infinite.  Than it was changed so values over 20 are assumed infinite, so if someone had innodb_thread_concurrency=32  (showed best performance for some of out multiple CPU tests) his config would be broken with upgrade.  Now we're breaking it once again.   This is not to mention default values changes. 

Anyway variable behavior is changed for good - not it is finally what someone would expect. But this mess needs careful documentation.