Bug #51543 innodb sorting result very slow(using index,no filesort)
Submitted: 26 Feb 2010 9:26 Modified: 23 Aug 2010 18:13
Reporter: Zhaoyang Jian Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S5 (Performance)
Version:5.0.81, 5.1.34 sp1, 5.1.44 OS:Linux (rh5.3)
Assigned to: CPU Architecture:Any
Tags: innodb, performance, slow, sorting result

[26 Feb 2010 9:26] Zhaoyang Jian
Description:

Schema info:

root@localhost : (none) 05:01:36> show create table my_table_name\G
*************************** 1. row ***************************
       Table: my_table_name
Create Table: CREATE TABLE `my_table_name` (
  `SITE` varchar(64) COLLATE utf8_bin DEFAULT NULL,
  `id` bigint(20) NOT NULL,
  `gmt_expire` datetime DEFAULT NULL,
  `gmt_post` datetime DEFAULT NULL,
  `ACTION` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  `STATUS` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  `SUBJECT` varchar(512) COLLATE utf8_bin DEFAULT NULL,
  `TYPE` varchar(32) COLLATE utf8_bin DEFAULT NULL,
  `member_id` varchar(32) COLLATE utf8_bin NOT NULL,
  `group_id` bigint(20) DEFAULT NULL,
  <........................>
  PRIMARY KEY (`id`),
  KEY `idx_my_table_name_mid_st_ge_gid_tp` (`member_id`,`STATUS`,`gmt_expire`,`group_id`,`id`,`TYPE`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin

root@localhost : my_table_name1 05:05:42> show table status like 'my_table_name'\G
*************************** 1. row ***************************
           Name: my_table_name
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 1614637
 Avg_row_length: 1527
    Data_length: 2466250752
Max_data_length: 0
   Index_length: 146800640
      Data_free: 7340032
 Auto_increment: NULL
    Create_time: 2010-02-26 11:42:54
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_bin
       Checksum: NULL
 Create_options: 
        Comment: 

*******************************************************************************************************************
When query(with order by,wort by index,no filesort) same data with several threads, 
most of all threads wait at sorting result,innodb status like this:

*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
100226 14:17:01 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 56 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 76696, signal count 51519
--Thread 1184885056 has waited at btr/btr0cur.c line 442 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x2aaec10cbb10 created in file buf/buf0buf.c line 547
a writer (thread id 1170241856) has reserved it in mode  exclusive
number of readers 0, waiters flag 1
..........all like this..........
--Thread 1179560256 has waited at btr/btr0cur.c line 442 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x2aaec10c93b0 created in file buf/buf0buf.c line 547
a writer (thread id 1185683776) has reserved it in mode  exclusive
number of readers 0, waiters flag 1
Last time read locked in file not yet reserved line 0
Last time write locked in file buf/buf0buf.c line 1797
Mutex spin waits 0, rounds 1646767, OS waits 3389
RW-shared spins 150566, OS waits 70115; RW-excl spins 38241, OS waits 1329
------------
TRANSACTIONS
------------
Trx id counter 0 416217421
Purge done for trx's n:o < 0 414474793 undo n:o < 0 0
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 404, OS thread id 1185950016
MySQL thread id 80, query id 3721 localhost root
show innodb status
...
---TRANSACTION 0 416217195, not started, process no 404, OS thread id 1180358976 estimating records in index range
---TRANSACTION 0 416217408, ACTIVE 0 sec, process no 404, OS thread id 1178495296 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 75, query id 3456 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416217155, sees < 0 416214381
---TRANSACTION 0 416217082, ACTIVE 6 sec, process no 404, OS thread id 1185417536 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 78, query id 3384 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416217083, sees < 0 416214381
---TRANSACTION 0 416216769, ACTIVE 16 sec, process no 404, OS thread id 1166514496 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 2, query id 3059 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416216770, sees < 0 416214381
---TRANSACTION 0 416216044, ACTIVE 65 sec, process no 404, OS thread id 1184618816 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 73, query id 2295 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416216045, sees < 0 416214381
---TRANSACTION 0 416214611, ACTIVE 209 sec, process no 404, OS thread id 1180891456 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 57, query id 737 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416214612, sees < 0 416214314
---TRANSACTION 0 416214381, ACTIVE 251 sec, process no 404, OS thread id 1170241856 fetching rows
mysql tables in use 1, locked 0
MySQL thread id 17, query id 419 172.22.32.45 my_table_name Sorting result
select ID,GMT_MODIFIED,GMT_POST,GMT_EXPIRE,STATUS,ACTION from my_table_name where MEMBER_ID='kangshida2' and (STATUS<>'member deleted') order by MEMBER_ID,STATUS,GMT_EXPIRE limit 0,20
Trx read view will not see trx with id >= 0 416214382, sees < 0 416214280

...
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 260, seg size 262,
0 inserts, 0 merged recs, 0 merges
Hash table size 35401603, node heap has 5970 buffer(s)
44958.29 hash searches/s, 11942.09 non-hash searches/s

...

How to repeat:
Several thread query same data(with same where clause);
query with order by;
order by with index(no filesort);

Suggested fix:
no
[26 Feb 2010 9:26] Zhaoyang Jian
more information

Attachment: mysql.bug.log (text/x-log), 25.33 KiB.

[26 Feb 2010 9:39] Valeriy Kravchuk
Thank you for the problem report. Please, check if the same problem happens with a newer version, 5.1.44. 

If 5.1.44 is also affected, please, send EXPLAIN results for the query and your my.cnf file content, to begin with.
[1 Mar 2010 6:35] Zhaoyang Jian
The same problem  happens at 5.0.81 and 5.1.44
[1 Mar 2010 8:01] Valeriy Kravchuk
Please, send the results of SHOW CREATE TABLE and SHOW TABLE STATUS for that table used in the query.
[13 May 2010 19:05] Valeriy Kravchuk
I still would like to see the exact query and EXPLAIN results for it.
[13 Jun 2010 23:00] Bugs System
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".
[23 Jul 2010 18:13] Valeriy Kravchuk
Sorry for a delay. My fault.

So, according to EXPLAIN, first 3 columns from the idx_offer_mid_st_ge_gid_tp index are used for a range scan, but with only first column used to really select the beginning of range. 

If you still can check, please, send the results of:

select count(*) from my_table_name where MEMBER_ID='kaishengwanglan';

select count(*) from my_table_name where MEMBER_ID='kaishengwanglan' and (STATUS<>'member deleted');
[23 Aug 2010 23:00] Bugs System
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".