Bug #104699 can not get result when order by clause within subquery
Submitted: 23 Aug 2021 13:57 Modified: 25 Aug 2021 2:45
Reporter: Ye Jinrong Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: DML Severity:S3 (Non-critical)
Version:8.0.25 OS:Any
Assigned to: CPU Architecture:Any

[23 Aug 2021 13:57] Ye Jinrong
Description:
can not get result when order by clause within subquery

How to repeat:
table ddl:
```
mysql> show create table a\G
*************************** 1. row ***************************
       Table: a
Create Table: CREATE TABLE `a` (
  `ID` int NOT NULL AUTO_INCREMENT,
  `CC_CODE` varchar(64) DEFAULT '',
  `SELLER_ID` int DEFAULT NULL,
  `seller_name` varchar(64) DEFAULT '',
  `O_TYPE` varchar(64) CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci NOT NULL DEFAULT '''1''',
  `op_value` decimal(64,2) DEFAULT '0.00',
  `B_VALUE` decimal(64,2) NOT NULL DEFAULT '0.00',
  `L_VALUE` decimal(64,2) NOT NULL DEFAULT '0.00',
  `P_STATUS` varchar(2) CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci DEFAULT 'T',
  `OP_NAME` varchar(64) DEFAULT '',
  `OP_ID` int DEFAULT NULL,
  `REMARK` varchar(100) DEFAULT NULL,
  `CREATE_BY` varchar(64) DEFAULT '',
  `CREATE_TIME` datetime DEFAULT CURRENT_TIMESTAMP,
  `MODIFY_BY` varchar(64) DEFAULT '',
  `MODIFY_TIME` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `DELETED` char(1) NOT NULL,
  `EXT_CODE` varchar(64) DEFAULT NULL,
  PRIMARY KEY (`ID`) USING BTREE,
  KEY `Idx_modify_time` (`MODIFY_TIME`) USING BTREE,
  KEY `IDX_CREATE_TIME` (`CREATE_TIME`) USING BTREE,
  KEY `IDX_SELLER_ID` (`SELLER_ID`) USING BTREE
) ENGINE=InnoDB;

mysql> select count(*) from a;
+----------+
| count(*) |
+----------+
|      100 |
+----------+
1 row in set (0.00 sec)

mysql> desc SELECT count(DISTINCT create_time) create_time FROM
  (select
  '111' as service_code,
  seller_name,
  op_value,
  create_time,
  remark from  a order by create_time desc )  tttt;
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
| id | select_type | table | partitions | type  | possible_keys   | key             | key_len | ref  | rows | filtered | Extra                    |
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
|  1 | SIMPLE      | a     | NULL       | range | IDX_CREATE_TIME | IDX_CREATE_TIME | 0       | NULL |    1 |   100.00 | Using index for group-by |
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
```

This SQL has been running for a long time and can't get results.

see the slow log:
```
# Query_time: 96.578231  Lock_time: 0.000065 Rows_sent: 0  Rows_examined: 208846518 Thread_id: 11574624 Errno: 1317 Killed: 0 Bytes_received: 0 Bytes_sent: 86 Read_first: 1 Read_last: 1 Read_key: 208846520 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2021-08-23T21:45:13.666735+08:00 End: 2021-08-23T21:46:50.244966+08:00 Schema: mgr Rows_affected: 0
# Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: No  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 1
SET timestamp=1629726313;
SELECT count(DISTINCT create_time) create_time FROM (select      '111' as service_code,      seller_name,      op_value,                     create_time,      remark from  a order by create_time desc )  tttt;
```

P.S, After running for too long, I kill it.

I run perf top to observe the mysqld process:
```
Samples: 125K of event 'cycles', Event count (approx.): 142594760840
  Children      Self  Command  Shared Object         Symbol
+   98.70%     0.00%  mysqld   libpthread-2.28.so    [.] start_thread
+   98.70%     0.00%  mysqld   mysqld                [.] pfs_spawn_thread
+   98.50%     0.01%  mysqld   mysqld                [.] handle_connection
+   96.93%     0.00%  mysqld   mysqld                [.] do_command
+   96.68%     0.01%  mysqld   mysqld                [.] dispatch_command
+   96.49%     0.01%  mysqld   mysqld                [.] dispatch_sql_command
+   96.38%     0.00%  mysqld   mysqld                [.] mysql_execute_command
+   96.35%     0.01%  mysqld   mysqld                [.] Sql_cmd_dml::execute
+   96.00%     0.00%  mysqld   mysqld                [.] Query_expression::execute
+   96.00%     0.00%  mysqld   mysqld                [.] Query_expression::ExecuteIteratorQuery
+   95.81%     1.26%  mysqld   mysqld                [.] AggregateIterator::Read
+   91.38%     0.55%  mysqld   mysqld                [.] IndexRangeScanIterator::Read
+   90.58%     1.30%  mysqld   mysqld                [.] QUICK_GROUP_MIN_MAX_SELECT::get_next
+   87.67%     2.16%  mysqld   mysqld                [.] QUICK_GROUP_MIN_MAX_SELECT::next_prefix
+   81.99%     2.04%  mysqld   mysqld                [.] handler::ha_index_read_map
+   78.54%     4.85%  mysqld   mysqld                [.] ha_innobase::index_read
+   66.63%     9.08%  mysqld   mysqld                [.] row_search_mvcc
+   40.83%     4.78%  mysqld   mysqld                [.] btr_cur_open_at_index_side_func
+   29.67%     2.76%  mysqld   mysqld                [.] buf_page_get_gen
+   23.82%     2.59%  mysqld   mysqld                [.] Buf_fetch<Buf_fetch_normal>::single_page
+   15.40%     3.38%  mysqld   mysqld                [.] Buf_fetch_normal::get
+   10.03%     3.11%  mysqld   mysqld                [.] Buf_fetch<Buf_fetch_normal>::lookup
+    5.87%     2.58%  mysqld   mysqld                [.] mtr_t::s_lock
+    4.83%     0.59%  mysqld   mysqld                [.] mtr_t::commit
+    4.81%     1.80%  mysqld   mysqld                [.] row_sel_store_mysql_rec
+    3.92%     0.58%  mysqld   mysqld                [.] mtr_t::Command::release_all
+    3.48%     3.24%  mysqld   mysqld                [.] my_timer_cycles
+    3.31%     3.28%  mysqld   mysqld                [.] memo_slot_release
+    2.99%     2.10%  mysqld   mysqld                [.] row_sel_store_mysql_field_func
+    2.99%     0.61%  mysqld   mysqld                [.] btr_pcur_t::store_position
+    2.53%     2.43%  mysqld   mysqld                [.] Buf_fetch<Buf_fetch_normal>::mtr_add_page
+    2.49%     1.96%  mysqld   mysqld                [.] key_copy
+    2.45%     0.48%  mysqld   mysqld                [.] Item_sum_count::add
+    2.38%     2.33%  mysqld   mysqld                [.] rw_lock_s_lock_func
+    2.27%     0.24%  mysqld   mysqld                [.] thd_to_trx
+    2.14%     2.13%  mysqld   mysqld                [.] rec_copy_prefix_to_buf
+    1.87%     1.82%  mysqld   mysqld                [.] buf_page_hash_get_low
+    1.83%     1.78%  mysqld   mysqld                [.] hash_lock_s_confirm
+    1.74%     1.70%  mysqld   mysqld                [.] trx_start_if_not_started_low
Tip: To set sample time separation other than 100ms with --sort time use --time-quantum
```

If you remove order by clause from the subquery, everything is normal:
```
mysql> SELECT count(DISTINCT create_time) create_time FROM (select      '111' as service_code,      seller_name,      op_value,                     create_time,      remark from  a )  tttt;
+-------------+
| create_time |
+-------------+
|         100 |
+-------------+
1 row in set (0.00 sec)
```

There is slow log:
```
# Query_time: 0.000311  Lock_time: 0.000043 Rows_sent: 1  Rows_examined: 0 Thread_id: 11574624 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 58 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2021-08-23T21:53:42.610078+08:00 End: 2021-08-23T21:53:42.610389+08:00 Schema: mgr Rows_affected: 0
# Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 5
SET timestamp=1629726822;
select count(*) from a;
```
[23 Aug 2021 13:58] Ye Jinrong
perf top data

Attachment: perf.data-20210823.gz (application/x-gzip, text), 2.19 MiB.

[24 Aug 2021 12:07] MySQL Verification Team
Hi Mr. Jinrong,

Thank you for your bug report.

However, it seems to us that this is not a bug.

Your query simply has to examine 210 million rows !!!!! Things are even worse than that ..... It has to do it, not by scanning rows (which is fast as it is done sequentially), but jumping to and fro through an index, in order to resolve ORDER BY.

What you can do is use the optimiser switch to ignore that index for group by and see if it is any better. You will find a list of optimiser switches in our Reference Manual. You can also try setting a flag to ignore that index. That might resolve your performance problems. These flags should be set in the nested query. Beside that, you can do away with a nested query and re-write it as a single, stand-alone query, although the speed improvement would not be as good as those with optimiser flags and switches.

Not a bug.
[25 Aug 2021 2:45] Ye Jinrong
bug table a only had 100 rows

mysql> select count(*) from a;
+----------+
| count(*) |
+----------+
|      100 |
+----------+

and you can see the explain result
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
| id | select_type | table | partitions | type  | possible_keys   | key             | key_len | ref  | rows | filtered | Extra                    |
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
|  1 | SIMPLE      | a     | NULL       | range | IDX_CREATE_TIME | IDX_CREATE_TIME | 0       | NULL |    1 |   100.00 | Using index for group-by |
+----+-------------+-------+------------+-------+-----------------+-----------------+---------+------+------+----------+--------------------------+
[25 Aug 2021 12:25] MySQL Verification Team
Hi,

We have not heard from you whether you have tried the recommendations that we have provided for you.

Also, do note that you have made a dependent nested query, which has to be re-run for every single row, so why don't you try to simplify that ???