MySQL Bugs: #70086: Degraded performance for index

Bug #70086	Degraded performance for index_merge updates
Submitted:	19 Aug 2013 16:06	Modified:	2 Nov 2013 8:52
Reporter:	trevor price	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S2 (Serious)
Version:	5.6.13-log	OS:	Linux (2.6.16.33-xenU x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	index_merge update performance

Description:
Between 5.5.8 and 5.6.13 the performance for some update statements has gotten significantly worse.  Consider the statement

mysql> explain update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: power_up_value
         type: index_merge
possible_keys: track_id_idx,station_id_idx
          key: track_id_idx,station_id_idx
      key_len: 8,8
          ref: NULL
         rows: 69
        Extra: Using intersect(track_id_idx,station_id_idx); Using where

on the table

mysql> show create table jelli.power_up_value \G
*************************** 1. row ***************************
       Table: power_up_value
Create Table: CREATE TABLE `power_up_value` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `track_id` bigint(20) unsigned NOT NULL,
  `station_id` bigint(20) unsigned NOT NULL,
  `power_up_id` bigint(20) unsigned DEFAULT NULL,
  `active` bit(1) NOT NULL,
  `value` bigint(20) NOT NULL,
  `applied_server_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `inactivated_server_time` timestamp NULL DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `FK_power_up_value_to_power_up` (`power_up_id`),
  KEY `track_id_idx` (`track_id`),
  KEY `station_id_idx` (`station_id`)
) ENGINE=InnoDB AUTO_INCREMENT=3177130 DEFAULT CHARSET=utf8

for the data set in question on 5.6.13 this statement takes :

mysql> update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 ;
Query OK, 0 rows affected (0.23 sec)

so .23 seconds.  On mysql 5.5.8 on the same data it takes ~ .04 seconds.  This is a huge difference.  Notice the 0 rows were modified.  Now look at the time if I convert this update statement into a select

mysql> select sql_no_cache * from jelli.power_up_value  where active<>0 and track_id=76821 and station_id=3519 \G
*************************** 1. row ***************************
                     id: 3177012
               track_id: 76821
             station_id: 3519
            power_up_id: 13032192
                 active: 
                  value: 0
    applied_server_time: 2013-08-17 00:52:58
inactivated_server_time: NULL
1 row in set (0.04 sec)

It does not seem correct to me that a zero row modified update statement will take 5X the equivalent statement as a select.  This is a show stopping performance issue for us since it slows replication.

How to repeat:
CREATE TABLE `power_up` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `user_id` bigint(20) unsigned NOT NULL,
  `track_id` bigint(20) unsigned DEFAULT NULL COMMENT 'track_id == null means not yet applied',
  `station_id` bigint(20) unsigned DEFAULT NULL,
  `active` bit(4) NOT NULL COMMENT 'Use to inactivate a power up - for auditing reasons, do not delete power ups from the database!',
  `type` varchar(20) NOT NULL,
  `last_modified_server_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `apply_time` timestamp NULL DEFAULT NULL,
  `expiration_time` timestamp NULL DEFAULT NULL,
  `version` int(10) unsigned NOT NULL DEFAULT '1',
  `apply_client_id` int(5) DEFAULT NULL,
  `in_orbit` enum('0','1') DEFAULT '0',
  PRIMARY KEY (`id`),
  KEY `FK_vote_to_user` (`user_id`),
  KEY `FK_vote_to_track` (`track_id`),
  KEY `FK_power_up_to_station` (`station_id`),
  KEY `last_modified_server_time_idx` (`last_modified_server_time`),
  KEY `expiration_time_idx` (`expiration_time`),
  KEY `in_orbit_idx` (`station_id`,`in_orbit`),
  KEY `apply_time_idx` (`apply_time`)
) ENGINE=InnoDB

with update 

update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 ;

Some additional information.

1) According the show status "Handler" variables, the update and select behave the same, so its seems the optimizer is not the problem.
2) Using the performance schema, the update spends nearly all its time "fetching".

*************************** 4. row ***************************
             event_id: 17572601
        rows_examined: 4
           event_name: stage/sql/updating
           event_name: wait/io/table/sql/handler
            operation: fetch
sum(waitl.timer_wait): 19953568

not sure if row locking happens during this operation, but perhaps the query is slower because of row-locking overhead.

so, dropping of of the indicies being merged greatly speeds performance

mysql> explain update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: power_up_value
         type: range
possible_keys: track_id_idx
          key: track_id_idx
      key_len: 8
          ref: const
         rows: 949
        Extra: Using where
1 row in set (0.00 sec)

mysql> update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
Query OK, 0 rows affected (0.00 sec)
Rows matched: 0  Changed: 0  Warnings: 0

the station_id_ix index was dropped, which was part of the index_merge.

Thank you for the report.

I can not repeat described behavior with test data. Did you try to run ANALYZE TABLE and OPTIMIZE TABLE on problematic table?

yes I ran optimize table and analyze table.  This is a single table query, so I can upload the entire table, it's around 600MB.

Here is a more concise rendering of the problem.

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

mysql> optimize table power_up_value ;
+----------------------+----------+----------+-------------------------------------------------------------------+
| Table                | Op       | Msg_type | Msg_text                                                          |
+----------------------+----------+----------+-------------------------------------------------------------------+
| jelli.power_up_value | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
| jelli.power_up_value | optimize | status   | OK                                                                |
+----------------------+----------+----------+-------------------------------------------------------------------+
2 rows in set (1 min 31.39 sec)

mysql> analyze table power_up_value ;
+----------------------+---------+----------+----------+
| Table                | Op      | Msg_type | Msg_text |
+----------------------+---------+----------+----------+
| jelli.power_up_value | analyze | status   | OK       |
+----------------------+---------+----------+----------+
1 row in set (0.01 sec)

mysql> alter table power_up_value add index station_id_idx (station_id) ;
Query OK, 0 rows affected (14.42 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql>  explain update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: power_up_value
         type: index_merge
possible_keys: track_id_idx,station_id_idx
          key: track_id_idx,station_id_idx
      key_len: 8,8
          ref: NULL
         rows: 72
        Extra: Using intersect(track_id_idx,station_id_idx); Using where
1 row in set (0.00 sec)

mysql> update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
Query OK, 1 row affected (0.37 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
Query OK, 0 rows affected (0.35 sec)
Rows matched: 1  Changed: 0  Warnings: 0

mysql> alter table power_up_value drop index station_id_idx ;
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> explain update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: power_up_value
         type: range
possible_keys: track_id_idx
          key: track_id_idx
      key_len: 8
          ref: const
         rows: 961
        Extra: Using where
1 row in set (0.00 sec)

mysql> update jelli.power_up_value set value=0 where active<>0 and track_id=76821 and station_id=3519 \G
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0

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

Hi Trevor,

If you can upload a repeatable test case from your data it would come very handy for us. If you're able to reduce the test case down a bit from 600MB it would be even better - most likely you don't need all the columns and rows to make a test case. 

I'll investigate the reason once I get a repro.

Thanks,
Jørgen

a data file has been ftp'd to ftp.oracle.com.  This file is bug-data-70086.zip, and the instructions to replicate the issue are in the README.

Hi Trevor,

Due to unexpected issues, your uploaded repro has been deleted from the ftp server. I would really like to take a look at the repro, but I'm afraid I didn't get hold of it while it was available. Can you please upload it one more time?

We're terribly sorry for the inconvenience. 

Regards,
Jørgen

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".