Bug #68979 performance regression of MySQL 5.6.10?
Submitted: 17 Apr 2013 3:47 Modified: 22 May 2013 13:17
Reporter: zhai weixiang (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S5 (Performance)
Version:5.6.10 OS:Linux
Assigned to: CPU Architecture:Any
Tags: regression

[17 Apr 2013 3:47] zhai weixiang
Description:
I have compared the performance under read only workload using our internal benchmark.

bellow is my results:

Percona Server 5.5.18:  QPS 20,200, CPU IDLE:23%

MySQL 5.6.10:    QPS 16,900, CPU IDLE:9%

MySQL 5.6.10( configured without performance schema, optimizer_trace and oprofile):  QPS:18,200, CPU IDLE:15%

buffer pool hit: >99.9%

some information from Performance Schema:
mysql>  SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 10;
+------------+------------------+----------------+---------------------------------------------+
| COUNT_STAR | SUM_TIMER_WAIT   | AVG_TIMER_WAIT | EVENT_NAME                                  |
+------------+------------------+----------------+---------------------------------------------+
|        125 | 7501975928543060 | 60015807428048 | wait/synch/cond/sql/Master_info::sleep_cond |
|  292201973 | 4262804509686000 |       14588124 | wait/synch/mutex/innodb/trx_sys_mutex       |
|  409699075 | 3130711048547832 |        7641336 | wait/synch/mutex/innodb/fil_system_mutex    |
| 6540980431 | 1356640693264188 |         207100 | wait/synch/rwlock/innodb/hash table locks   |
|  280313417 | 1250590775027324 |        4461152 | wait/synch/rwlock/innodb/btr_search_latch   |
|  253038240 |  759109234221644 |        2999680 | wait/synch/mutex/mysys/BITMAP::mutex        |
|  159387174 |  341916535409172 |        2145120 | wait/synch/mutex/sql/LOCK_plugin            |
|  212818517 |  319086402410032 |        1498968 | wait/synch/rwlock/sql/MDL_lock::rwlock      |
|  278382525 |  301173435281520 |        1081716 | wait/synch/mutex/sql/LOCK_table_cache       |
|   40706754 |  252951397737644 |        6213872 | wait/synch/mutex/innodb/buf_pool_mutex      |
+------------+------------------+----------------+---------------------------------------------+

" wait/synch/rwlock/innodb/hash table locks" used to have the biggest SUM_TIMER_WAIT, I increased the value of srv_n_page_hash_locks from 16(default value) to 256, and then trx_sys_mutex  became a bottleneck.

I don't know  if the the percona fix(Percona Server 5.5.30) for bug#49169  can reduce such mutex contention.

Below is the related information I collected. If you need more information ,please let me know :-)

How to repeat:
using our internal benchmark system. If you need more information , please let me know

Suggested fix:
I don't know...
[17 Apr 2013 3:48] zhai weixiang
there are mainly four types of queries:

select      t.feed_id, t.rated_uid, t.rated_user_nick, t.rater_uid, t.rater_user_nick, t.rater_type,   t.status, t.validscore, t.rate, t.trade_id, t.parent_trade_id, t.gmt_trade_create,   t.gmt_trade_finished, t.auc_num_id, t.auction_title, t.auction_pic_url, t.auction_price,   t.auction_virtual, t.leaf_cat_id, t.root_cat_id, t.spu_id, t.feedback, t.feedback_length,   t.validfeedback, t.reply, t.explain_delete_time, t.last_modify_from, t.edit_status,   t.biz_type, t.source, t.buy_state, t.rater_pic, t.properties, t.anony, t.privacy,   t.album_id, t.vote_useful, t.rater_star, t.sort_weight, t.attributes, t.number_1,   t.number_2, t.number_3, t.gmt_create, t.gmt_modified, t.lock_version, t.feedback_ip     
from
   (   select feed_id from                  feed_item_receive_0991                        where                 rater_type = ?        and           biz_type IN     (                ?           )        and     auc_num_id = ? and     rate = ?                         and      status in      (                ?            )               and     validfeedback = ?                                                                                       order by sort_weight desc      limit 0,21   ) t1,  
    feed_item_receive_0991    t force index(primary)  
where t.feed_id=t1.feed_id       order by t.sort_weight desc\G

SELECT COUNT ( `feed_id` ) 
FROM ( SELECT `feed_id` FROM `feed_item_receive_0991` WHERE `rater_type` = ? AND `biz_type` IN (?) AND `auc_num_id` = ? AND `rate` = - ? AND STATUS IN (?) AND `validfeedback` = ? LIMIT ? ) `temp` 

root@feedback 10:06:39>show create table feed_item_receive_0991\G
*************************** 1. row ***************************
       Table: feed_item_receive_0991
Create Table: CREATE TABLE `feed_item_receive_0991` (
  `feed_id` bigint(20) NOT NULL ,
  `rated_uid` bigint(20) NOT NULL ,
  `rated_user_nick` varchar(32) NOT NULL ,
  `rater_uid` bigint(20) NOT NULL,
  `rater_user_nick` varchar(32) NOT NULL ,
  `rater_type` tinyint(4) NOT NULL ,
  `status` tinyint(4) NOT NULL,
  `validscore` tinyint(4) NOT NULL ,
  `rate` tinyint(4) NOT NULL ,
  `trade_id` bigint(20) NOT NULL,
  `parent_trade_id` bigint(20) NOT NULL ,
  `gmt_trade_create` datetime DEFAULT NULL ,
  `gmt_trade_finished` datetime DEFAULT NULL ,
  `auc_num_id` bigint(20) NOT NULL ,
  `auction_title` varchar(256) NOT NULL ,
  `auction_pic_url` varchar(512) DEFAULT NULL ,
  `auction_price` float DEFAULT NULL ,
  `auction_virtual` tinyint(4) NOT NULL ,
  `leaf_cat_id` bigint(20) NOT NULL ,
  `root_cat_id` bigint(20) NOT NULL ,
  `spu_id` bigint(20) NOT NULL  ,
  `feedback` varchar(4000) DEFAULT NULL ,
  `feedback_length` smallint(6) NOT NULL ,
  `validfeedback` tinyint(4) NOT NULL ,
  `reply` varchar(1000) DEFAULT NULL ,
  `explain_delete_time` datetime DEFAULT NULL ,
  `last_modify_from` tinyint(4) DEFAULT NULL,
  `edit_status` int(11) NOT NULL DEFAULT '0' ,
  `biz_type` smallint(6) NOT NULL ,
  `source` bigint(20) NOT NULL ,
  `buy_state` tinyint(4) NOT NULL ,
  `rater_pic` tinyint(4) NOT NULL DEFAULT '0' ,
  `properties` varchar(1024) DEFAULT NULL ,
  `anony` tinyint(4) NOT NULL ,
  `privacy` int(11) NOT NULL ,
  `album_id` bigint(20) NOT NULL DEFAULT '-1' ,
  `vote_useful` bigint(20) NOT NULL DEFAULT '0' ,
  `rater_star` int(11) NOT NULL DEFAULT '0' ,
  `sort_weight` int(11) NOT NULL DEFAULT '0' ,
  `attributes` varchar(1024) DEFAULT NULL ,
  `number_1` bigint(20) NOT NULL ,
  `number_2` bigint(20) NOT NULL ,
  `number_3` bigint(20) NOT NULL,
  `gmt_create` datetime NOT NULL,
  `gmt_modified` datetime NOT NULL ,
  `lock_version` int(11) NOT NULL DEFAULT '0' ,
  `feedback_ip` varchar(15) DEFAULT NULL ,
  PRIMARY KEY (`feed_id`),
  UNIQUE KEY `uk_feed_item_receive` (`biz_type`,`number_1`,`number_2`,`number_3`),
  KEY `ind_feed_item_receive_rid` (`rated_uid`,`biz_type`,`rater_type`,`validfeedback`,`status`,`gmt_create`,`rate`,`source`),
  KEY `ind_feed_item_receive_rrid` (`rater_uid`,`rated_uid`,`biz_type`,`validscore`,`rater_type`,`status`,`auc_num_id`,`rate`,`gmt_trade_create`),
  KEY `ind_feed_item_receive_pid` (`parent_trade_id`,`biz_type`,`rater_type`,`trade_id`),
  KEY `ind_feed_item_receive_aidg` (`auc_num_id`,`rater_type`,`biz_type`,`status`,`validfeedback`,`gmt_create`,`rate`),
  KEY `ind_feed_item_receive_rdidn` (`rated_uid`,`rater_type`,`biz_type`,`gmt_create`,`status`,`rate`,`validfeedback`),
  KEY `ind_feed_item_receive_aidsr` (`auc_num_id`,`rater_type`,`biz_type`,`status`,`validfeedback`,`sort_weight`,`rate`,`rater_pic`),
  KEY `ind_feed_item_receive_stat` (`status`,`biz_type`,`gmt_trade_finished`,`source`),
  KEY `ind_feed_item_receive_ridr` (`rated_uid`,`biz_type`,`rater_type`,`validfeedback`,`status`,`rate`,`gmt_create`),
  KEY `ind_feed_item_receive_ridgr` (`rated_uid`,`rater_type`,`biz_type`,`rate`,`gmt_create`,`status`,`validfeedback`)
) ENGINE=InnoDB DEFAULT CHARSET=gbk;
[17 Apr 2013 3:49] zhai weixiang
select      t.feed_id, t.rated_uid, t.rated_user_nick, t.rater_uid, t.rater_user_nick, t.rater_type,   t.status, t.validscore, t.rate, t.trade_id, t.parent_trade_id, t.gmt_trade_create,   t.gmt_trade_finished, t.auc_num_id, t.auction_title, t.auction_pic_url, t.auction_price,   t.auction_virtual, t.leaf_cat_id, t.root_cat_id, t.spu_id, t.feedback, t.feedback_length,   t.validfeedback, t.reply, t.explain_delete_time, t.last_modify_from, t.edit_status,   t.biz_type, t.source, t.buy_state, t.rater_pic, t.properties, t.anony, t.privacy,   t.album_id, t.vote_useful, t.rater_star, t.sort_weight, t.attributes, t.number_1,   t.number_2, t.number_3, t.gmt_create, t.gmt_modified, t.lock_version, t.feedback_ip    
from 
(   select feed_id from                      feed_item_send_0991                     where             rater_uid = ? and           biz_type IN     (                ?           )                                                     and      status in      (                ?            )               and     validfeedback = ?            AND     anony = ?                                                                     order by gmt_create desc      limit 0,21   ) t1,                    
feed_item_send_0991                t force index(primary)   
where t.feed_id=t1.feed_id       order by t.gmt_create desc

select    count(feed_id)  
 from 
(   select feed_id from                      feed_item_send_0991                     where             rater_uid = ?            and           biz_type IN     (                ?           )                                                     and      status in      (                ?            )               and     validfeedback = ?            AND     anony = ?                                                                 limit 101   ) temp;

root@feedback 10:06:33>show create table feed_item_send_0991\G
*************************** 1. row ***************************
       Table: feed_item_send_0991
Create Table: CREATE TABLE `feed_item_send_0991` (
  `feed_id` bigint(20) NOT NULL,
  `rated_uid` bigint(20) NOT NULL ,
  `rated_user_nick` varchar(32) NOT NULL,
  `rater_uid` bigint(20) NOT NULL ,
  `rater_user_nick` varchar(32) NOT NULL ,
  `rater_type` tinyint(4) NOT NULL ,
  `status` tinyint(4) NOT NULL ,
  `validscore` tinyint(4) NOT NULL ,
  `rate` tinyint(4) NOT NULL ,
  `trade_id` bigint(20) NOT NULL ,
  `parent_trade_id` bigint(20) NOT NULL ,
  `gmt_trade_create` datetime DEFAULT NULL ,
  `gmt_trade_finished` datetime DEFAULT NULL ,
  `auc_num_id` bigint(20) NOT NULL ,
  `auction_title` varchar(256) NOT NULL,
  `auction_pic_url` varchar(512) DEFAULT NULL ,
  `auction_price` float DEFAULT NULL ,
  `auction_virtual` tinyint(4) NOT NULL ,
  `leaf_cat_id` bigint(20) NOT NULL ,
  `root_cat_id` bigint(20) NOT NULL ,
  `spu_id` bigint(20) NOT NULL ,
  `feedback` varchar(4000) DEFAULT NULL ,
  `feedback_length` int(11) NOT NULL ,
  `validfeedback` tinyint(4) NOT NULL ,
  `reply` varchar(1000) DEFAULT NULL ,
  `explain_delete_time` datetime DEFAULT NULL ,
  `last_modify_from` tinyint(4) DEFAULT NULL ,
  `edit_status` int(11) NOT NULL DEFAULT '0' ,
  `biz_type` smallint(6) NOT NULL,
  `source` bigint(20) NOT NULL ,
  `buy_state` tinyint(4) NOT NULL ,
  `rater_pic` tinyint(4) NOT NULL DEFAULT '0',
  `properties` varchar(1024) DEFAULT NULL,
  `anony` tinyint(4) NOT NULL ,
  `privacy` int(11) NOT NULL ,
  `album_id` bigint(20) NOT NULL DEFAULT '-1' ,
  `vote_useful` bigint(20) NOT NULL DEFAULT '0' ,
  `rater_star` int(11) NOT NULL DEFAULT '0' ,
  `sort_weight` int(11) NOT NULL DEFAULT '0' ,
  `attributes` varchar(1024) DEFAULT NULL ,
  `number_1` bigint(20) NOT NULL ,
  `number_2` bigint(20) NOT NULL,
  `number_3` bigint(20) NOT NULL ,
  `gmt_create` datetime NOT NULL ,
  `gmt_modified` datetime NOT NULL ,
  `lock_version` int(11) NOT NULL DEFAULT '0' ,
  `feedback_ip` varchar(15) DEFAULT NULL ,
  PRIMARY KEY (`feed_id`),
  KEY `ind_feed_item_send_rrid` (`rater_uid`,`biz_type`,`status`,`validfeedback`,`rate`,`gmt_create`,`anony`,`rater_type`),
  KEY `ind_feed_item_send_aid` (`auc_num_id`,`rater_uid`,`rater_type`,`gmt_create`,`status`)
) ENGINE=InnoDB DEFAULT CHARSET=gbk
[17 Apr 2013 3:49] zhai weixiang
result of perf top ( 5.6.10):
  3.29%  libc-2.12.so                  [.] memcpy
  2.59%  mysqld                        [.] lfind
  2.05%  mysqld                        [.] MYSQLparse(void*)
  1.32%  mysqld                        [.] rec_init_offsets_comp_ordinary(unsigned char const*, bool, dict_index_t const*, unsigned long*)
  1.19%  mysqld                        [.] row_sel_field_store_in_mysql_format_func(unsigned char*, mysql_row_templ_t const*, unsigned char const*, unsigned long)
  1.17%  mysqld                        [.] cmp_dtuple_rec_with_match_low(dtuple_t const*, unsigned char const*, unsigned long const*, unsigned long, unsigned long*, unsigned long*)
  1.06%  mysqld                        [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
  1.00%  libc-2.12.so                  [.] _int_malloc
  0.99%  mysqld                        [.] mach_read_from_1(unsigned char const*)
  0.98%  mysqld                        [.] ut_delay(unsigned long)
  0.86%  mysqld                        [.] lex_one_token(void*, void*)
  0.84%  mysqld                        [.] row_sel_store_mysql_field_func(unsigned char*, row_prebuilt_t*, unsigned char const*, unsigned long const*, unsigned long, mysql_row_templ_t const*)
  0.81%  mysqld                        [.] rec_init_offsets(unsigned char const*, dict_index_t const*, unsigned long*)
  0.81%  mysqld                        [.] my_qsort
  0.67%  mysqld                        [.] mach_read_from_1(unsigned char const*)
  0.63%  mysqld                        [.] buf_page_hash_get_low(buf_pool_t*, unsigned long, unsigned long, unsigned long)
  0.63%  libc-2.12.so                  [.] __memset_sse2
  0.53%  mysqld                        [.] ptr_compare_0
  0.53%  mysqld                        [.] PFS_single_stat::aggregate_value(unsigned long long)
  0.52%  libpthread-2.12.so            [.] pthread_getspecific
[17 Apr 2013 3:50] zhai weixiang
my.cnf of 5.5.18
[client]
socket=/u01/mysql/run/mysql.sock
default-character-set=utf8

[innotop]
socket=/u01/mysql/run/mysql.sock

[mysql]
prompt=\\u@\\d \\r:\\m:\\s>
no-auto-rehash

[mysqld_safe]
pid-file=/u01/mysql/run/mysqld.pid
[mysqld]

#### Baes dir ####
basedir=/u01/mysql
datadir=/u01/mysql/data
tmpdir=/u01/mysql/tmp
socket=/u01/mysql/run/mysql.sock

#### Base configure info ####
#default-character-set=utf8  #5.1
character_set_server=utf8 #5.5
port=3306
skip-external-locking  # 5.1->skip-locking
skip-name-resolve
old_passwords=0
lower_case_table_names=1
open_files_limit=65535
max_allowed_packet=160M
max_connect_errors=50000
max_connections=2100
max_user_connections=2000
thread_cache_size=256
table_cache=2048
table_definition_cache=2048
thread_stack=524288

#### Log info ####
log-error=/u01/mysql/log/alert.log
slow-query-log=1
slow_query_log_file=/u01/mysql/log/slow.log
log-slow-admin-statements
#log-queries-not-using-indexes
long_query_time=1

#### Binary log && Relay log ####
log-bin=/u01/mysql/log/mysql-bin
log-slave-updates=1
relay-log=/u01/mysql/log/mysqld-relay-bin
relay-log-index=/u01/mysql/log/mysqld-relay-bin.index
master-info-file=/u01/mysql/log/master.info
relay-log-info-file=/u01/mysql/log/relay-log.info
expire_logs_days=7
max_binlog_size=500M
max_binlog_cache_size=16G
binlog_format=ROW
slave-skip-errors=1022,1032,1062
log_bin_trust_function_creators=1
auto_increment_increment=2
auto_increment_offset=2

#### query cache ####
query_cache_size=0
query_cache_limit=2K
query_cache_min_res_unit=1K
query_cache_type=0
#myisam
concurrent_insert=2
key_buffer=100M
sort_buffer_size=400k
join_buffer_size=100K
read_buffer_size=1M
read_rnd_buffer_size=5M
myisam_sort_buffer_size=100M

#innodb plugin
#ignore_builtin_innodb
innodb_file_format=Barracuda
innodb_strict_mode=1
#innodb
default-storage-engine=INNODB

innodb_flush_method=O_DIRECT
innodb_file_per_table=1
innodb_lock_wait_timeout=100
innodb_additional_mem_pool_size=20M
innodb_log_buffer_size=200M
innodb_log_file_size=1000M
innodb_log_files_in_group=4
innodb_open_files=60000

###InnoDB IO
innodb_file_io_threads=4
innodb_write_io_threads=8
innodb_read_io_threads=8
innodb_flush_log_at_trx_commit=2
innodb_data_file_path=ibdata1:5G;ibdata2:5G:autoextend

# Percona
innodb_page_size=16k

#!!!!!!!!!!!!!!!!!!!!!!!!!!!!
#fusion-io
innodb_flush_neighbor_pages=0
innodb_adaptive_flushing=1
innodb_max_dirty_pages_pct=60
innodb_adaptive_flushing_method=keep_average
innodb_read_ahead=0
innodb_thread_concurrency=64
innodb_sync_spin_loops=100
innodb_spin_wait_delay=30
innodb_io_capacity=1000

log_warnings=0
skip-slave-start
innodb_stats_on_metadata=off
innodb_buffer_pool_instances=8

#sync_binlog=1
#innodb_use_purge_thread=8 #percona 5.5 remove innodb_use_purge_thread
#log_slow_verbosity=full
#userstat=1
#enable_query_response_time_stats=1

#2013 add
transaction_isolation=READ-COMMITTED
innodb_rollback_segments=128
sql_mode=STRICT_ALL_TABLES,no_zero_date,no_zero_in_date
sync_binlog=1000
log_slow_verbosity=full
innodb_purge_threads=1
innodb_lazy_drop_table=1
back_log=500

#### sever_id and innodb_buffer_pool_size #########

server_id=1767583306
innodb_buffer_pool_size=156G

my.cnf of 5.6.10

client]
socket = /u01/mysql/run/mysql.sock

[innotop]
socket = /u01/mysql/run/mysql.sock

[mysql]
auto-rehash

[mysqld]
core-file

#### Baes dir ####
basedir = /u01/mysql
datadir = /u01/mysql/data
tmpdir = /u01/mysql/tmp
socket = /u01/mysql/run/mysql.sock
#### Base configure info ####
port = 3306
skip-name-resolve
old_passwords = 0
lower_case_table_names = 1
open_files_limit = 65535
max_allowed_packet = 160M
max_connect_errors = 50000
max_connections = 2100
max_user_connections = 2000
thread_cache_size=256

table_open_cache_instances=5
metadata_locks_hash_instances = 64
metadata_locks_cache_size=10240
#innodb_use_native_aio = 1
innodb_sync_array_size=256

table_open_cache_instances=20
table_open_cache=10000

innodb_data_file_path=ibdata1:5G;ibdata2:5G:autoextend
innodb_log_buffer_size=200M
innodb_log_file_size=1000M
innodb_log_files_in_group=4

innodb_file_format=Barracuda
bind-address = 0.0.0.0

innodb_buffer_pool_dump_at_shutdown=1
innodb_buffer_pool_load_at_startup = 1
innodb_print_all_deadlocks = 1
innodb_buffer_pool_instances=8
innodb_online_alter_log_max_size=2G
innodb_lru_scan_depth=8192

innodb_file_io_threads=4
innodb_write_io_threads=8
innodb_read_io_threads=8

innodb_sync_spin_loops=100
innodb_spin_wait_delay=30

transaction_isolation=READ-COMMITTED
sql_mode=STRICT_ALL_TABLES,no_zero_date,no_zero_in_date

binlog_format=ROW
#### Log info ####
log-error = /u01/mysql/log/alert.log
log-queries-not-using-indexes
long_query_time = 1

#### Binary log && Relay log ####
log-bin = /u01/mysql/log/mysql-bin
log-slave-updates = 1
relay-log = /u01/mysql/log/mysqld-relay-bin
relay-log-index = /u01/mysql/log/mysqld-relay-bin.index
master-info-file = /u01/mysql/log/master.info
relay-log-info-file = /u01/mysql/log/relay-log.info
#expire_logs_days=1
max_binlog_size = 500M
max_binlog_cache_size = 2G
sync_binlog = 1
### Server id ####
server-id= 336783306

#### query cache ####
query_cache_size = 0
query_cache_limit = 2048
query_cache_min_res_unit = 1K
query_cache_type=0

#myisam
concurrent_insert=2
key_buffer=100M
sort_buffer_size=400k
join_buffer_size=100K
read_buffer_size=1M
read_rnd_buffer_size=5M
myisam_sort_buffer_size=100M

#innodb
default-storage-engine = INNODB
innodb_file_per_table = 1
innodb_flush_log_at_trx_commit = 2
innodb_lock_wait_timeout = 100
innodb_buffer_pool_size = 156G
innodb_max_dirty_pages_pct = 60
innodb_thread_concurrency=64
innodb_purge_threads = 4
innodb_io_capacity=1000
#innodb_flush_method = O_DIRECT_NO_FSYNC
innodb_flush_method = O_DIRECT
innodb_flush_neighbors=0
innodb_read_ahead_threshold=0
innodb_sort_buffer_size=2M

performance_schema_instrument = '%=on'
performance_schema=ON
innodb_page_hash_locks=256

thread_stack = 524288
[mysqld_safe]
pid-file = /u01/mysql/run/mysql.pid
[17 Apr 2013 11:16] zhai weixiang
I've turned on innodb_read_only, and still got a frustrating result:

mysql> show variables like '%innodb_read_only%';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| innodb_read_only | ON |
+------------------+-------+
1 row in set (0.00 sec)
 
QPS: 16800   CPU IDLE: 10%   buffer pool hit: 99.92%
 
from Performance Schema
mysql> SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 5;
+------------+-----------------+-----------------+--------------------------------------------------+
| COUNT_STAR | SUM_TIMER_WAIT | AVG_TIMER_WAIT | EVENT_NAME |
+------------+-----------------+-----------------+--------------------------------------------------+
| 82862093 | 987940919662796 | 11922420 | wait/synch/mutex/innodb/trx_sys_mutex |
| 145849673 | 920348832390760 | 6310228 | wait/synch/mutex/innodb/fil_system_mutex |
| 77441712 | 684392806680508 | 8837284 | wait/synch/rwlock/innodb/btr_search_latch |
| 1 | 476390655607576 | 476390655607576 | wait/synch/cond/sql/MYSQL_RELAY_LOG::update_cond |
| 8 | 476389823157136 | 59548727894424 | wait/synch/cond/sql/Master_info::sleep_cond |
+------------+-----------------+-----------------+--------------------------------------------------+
 
I closed  the performance schema dynamically: 
update setup_consumers set enabled='NO';
update setup_instruments set enabled='NO',timed='NO';

QPS:18200, CPU IDLE: 15%
[18 Apr 2013 12:47] Sinisa Milivojevic
Hi !

In order to proceed we do need some additional info.

First of all, how many cores do you have on the server (HW / SW details).. - if less than 16 cores, then probably it's expected behavior. We need the info in order to make an analysis as these data look pretty different from what we saw until now.. 

Is there any dataset to reproduce the problem ?..
We would appreciate if you would prepare a tarball with all needed stuff and upload it  somewhere via ftp or http..

What is also missing is  info if the execution plan was the same in 5.5 and 5.6. Last, but not least, "perf" report is missing from 5.5 too..

Sinisa Milivojevic
[18 Apr 2013 15:16] zhai weixiang
cpuinfo

Attachment: cpuinfo (application/octet-stream, text), 20.53 KiB.

[18 Apr 2013 15:20] zhai weixiang
results of explain

Attachment: explain.txt (text/plain), 25.86 KiB.

[18 Apr 2013 15:20] Sinisa Milivojevic
Thank you.

We need other info, as well.
[19 Apr 2013 1:56] zhai weixiang
result of perf top (PS5.5.18)

4.71%  libc-2.12.so                  [.] memcpy
  3.75%  mysqld                        [.] row_search_for_mysql
  2.71%  mysqld                        [.] MYSQLparse(void*)
  2.47%  mysqld                        [.] row_sel_store_mysql_rec
  2.46%  mysqld                        [.] buf_page_get_gen
  1.61%  mysqld                        [.] rec_init_offsets
  1.49%  mysqld                        [.] ut_delay
  1.44%  mysqld                        [.] cmp_dtuple_rec_with_match
  1.25%  mysqld                        [.] rec_get_offsets_func
  1.19%  libc-2.12.so                  [.] _int_malloc
  1.18%  mysqld                        [.] lex_one_token(void*, void*)
  1.04%  mysqld                        [.] my_qsort
  0.78%  mysqld                        [.] radixsort_for_str_ptr
  0.76%  mysqld                        [.] page_cur_search_with_match
  0.74%  mysqld                        [.] page_rec_get_n_recs_before
  0.67%  mysqld                        [.] pfs_mutex_enter_func
  0.65%  mysqld                        [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)
  0.63%  libc-2.12.so                  [.] __memset_sse2
  0.62%  mysqld                        [.] my_hash_sort_utf8
  0.58%  mysqld                        [.] Arg_comparator::compare_e_int()
  0.56%  mysqld                        [.] make_sortkey(st_sort_param*, unsigned char*, unsigned char*)
  0.55%  mysqld                        [.] btr_cur_search_to_nth_level
  0.54%  [kernel]                      [k] clear_page_c
  0.53%  [kernel]                      [k] _spin_lock_bh
  0.53%  libc-2.12.so                  [.] malloc
  0.52%  mysqld                        [.] alloc_root
[19 Apr 2013 13:21] Sinisa Milivojevic
Thank you.

We would very much appreciate to have all data and a confirmation that all queries and tables used are those posted in this bug record.
[24 Apr 2013 14:11] Jørgen Thomsen
I also experience severe regression in 5.6.11

On slower hardware and 5.5.28-log this statement executes in 
16 total, request 6.8136 sec

On faster hardware (both CPU and disk and more RAM)
16 total, request 22.0405 sec
[24 Apr 2013 15:44] Sinisa Milivojevic
Jørgen,

We need all the data for all tables involved !!! Make a tarball and upload them, please ...

Next, please confirm the blank rows in "Extra" column for 5.5 EXPLAIN.

Next, please confirm that you have only 4 CPU cores. Is that for slower or faster machine. Can you describe the other machine.

Last, but not least, we would welcome very much `perf` output for both 5.5 and 5.6.

Many thanks in advance.
[26 Apr 2013 10:35] zhai weixiang
HI, Sinisa, thanks for your reply.

I am afraid I can't provide the dataset because that's  the production data and we are not allowed to make it public.
[26 Apr 2013 14:19] Sinisa Milivojevic
Zhai, Jorgen,

We truly need all the data that we requested. Without those, in their full extent, we can not even attempt in reproducing the behavior that you both are observing !!!
[28 Apr 2013 23:49] Jørgen Thomsen
Different number of records with explains

Attachment: explain.txt (text/plain), 4.79 KiB.

[28 Apr 2013 23:52] Jørgen Thomsen
8 million records of production data are not to be uploaded.
I have reduced the problem to a pure 5.6.11 problem, though.
There seems to be a difference depending on the number of records in the main table as to be seen in the uploaded file.
[28 Apr 2013 23:56] Jørgen Thomsen
It is the ref NULL on the T2 index which is causing the slow select
[29 Apr 2013 0:04] Jørgen Thomsen
A test ordrer table had been populated with 4 million record and afterwards 2.8 million records had been deleted and the explain showed a positive result.
I then ran an optimize on the table and the bad 'ref NULL' appeared in the explain and performance went down.  Sic !
[30 Apr 2013 12:42] Øystein Grøvlen
Zhai,

The only significant difference I see in your EXPLAIN output is that MySQL 5.6 uses ref access for the derived table while MySQL 5.5 seems to use table scan (type=ALL).  However, I have a hard time believing that table scan should be any better here, but just to rule it out:  Would it be possible for you to check what happens if you force table scan to happen in 5.6?  You can do this by adding "USE INDEX()" to the sub-query (Note empty index list).  (It might also be that there is an EXPLAIN bug in 5.5 that shows table scan when index is actually used.)

It would also be great if you could run such a query manually against 5.5 and 5.6 and give me the reported handler calls.  That is, run this sequence:

FLUSH STATUS;
<query>
SHOW SESSION STATUS LIKE 'handler%';

Another note:  I guess you are using the sub-query and join in order to force MySQL to evaluate all where conditions on the index before fetching rows from the table.  MySQL 5.6 provides Index Condition Pushdown (ICP) which does this for you.  Hence, this trick should no longer be necessary, and such queries could be written as follows:

SELECT ...
FROM <table> USE INDEX(<indexes that cover all columns of WHERE and ORDER BY)
WHERE ...
ORDER BY ...
LIMIT ...

Note the USE INDEX hint.  It is probably necessary in order for MySQL to choose an index where ICP gives the most benefit.
[30 Apr 2013 13:01] Øystein Grøvlen
Jørgen,

It seems your issue is that in 5.6 one choose another index than 5.5 in order to avoid sorting.  However, the required index scan is more costly than using another index that requires sorting.  A work-around for you would be to force the use of the same index as in 5.5.  That is, in your query, add FORCE INDEX(datanplusd) after "INNER JOIN `ordrer` AS T2".

To know more about why optimizer makes this decision, it would be nice if you could provide optimizer trace for this query.  See http://dev.mysql.com/doc/internals/en/optimizer-tracing-typical-usage.html for instructions on how to generate optimizer trace.

Also, since your issue does not seem to be the same as the original issue in this bug report, it would be nice if you could create a separate bug report for your performance issue.
[30 Apr 2013 18:14] Jørgen Thomsen
Using FORCE INDEX(datanplusd) improves the query.
However, it appears, that this is another instance of the problem in 
bug #69013 Poor execution plan when ORDER BY with LIMIT X

When the LIMIT 5000 is removed the optimizer is selecting a better plan.
[14 May 2013 16:14] Sinisa Milivojevic
Our Oystein did ask some questions that require the answer.

Also, we do require the entire dataset in order to repeat the situation.

Thanks in advance.
[22 May 2013 13:17] Øystein Grøvlen
It seems the queries with performance regression is of type:

select count(feed_id) from ( select feed_id from feed_item_receive_:d where rater_type = :d and biz_type in ( :d ) and auc_num_id = :d and status in ( :d ) and validfeedback = :d limit :d ) temp;

Plan in 5.6:

|  1 | PRIMARY     | <derived2>             | ALL  | NULL
             | NULL                        | NULL    | NULL               |   17 | NULL        |
|  2 | DERIVED     | feed_item_receive_0994 | ref  | uk_feed_item_receive,ind_feed_item_receive_aidg,ind_feed_item_receive_aidsr,ind_feed_item_receive_stat | ind_feed_item_receive_aidsr | 13      | const,const,const,const,const |   17 | Using index |

Plan in 5.5:

|  1 | PRIMARY     | NULL                   | NULL | NULL
             | NULL                        | NULL    | NULL | NULL | Select tables optimized away |
|  2 | DERIVED     | feed_item_receive_0994 | ref  | uk_feed_item_receive,ind_feed_item_receive_aidg,ind_feed_item_receive_aidsr,ind_feed_item_receive_stat | ind_feed_item_receive_aidsr | 13      |      |   17 | Using index              |

As you can see, 5.5 has "Select tables optimized away".  According to data on handler calls, this means that 5.5 manage with only read_next calls, while 5.6 in addition will do an equal amount of read_rnd_next.

The change is a result of the 5.6 feature "Delayed materialization of derived tables".  Derived tables will no longer materialized in optimization phase.
Hence, the size of the derived table is no longer available during optimization and the count(*)-shortcut will not be possible anymore.

A work-around could be to eliminate the derived table:

select count(feed_id) from feed_item_receive_:d where rater_type = :d and biz_type in ( :d ) and auc_num_id = :d and status in ( :d ) and validfeedback = :d ;

However, this will not improve performance for large results since without the limit clause one will no longer be able to put a maximum limit the number of rows that are processed by the query.
[11 Jul 2018 15:11] Sinisa Milivojevic
This bug has a duplicate in this bug:

https://bugs.mysql.com/bug.php?id=91598