墨墨导读：MySQL在统计表记录数时，指定使用主键查询反而慢，在执行效率上进行对比分析。
问题描述
在统计表记录数时，平时我很少注意里面的细节，这几天有空分析了一下，下面是我的分析过程，不妥之处，还请指正。
root@localhost#mysql.sock : tc0112:28:09>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.13 sec)
root@localhost#mysql.sock : tc0112:28:11>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.13 sec)
root@localhost#mysql.sock : tc0112:28:13>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.13 sec)
root@localhost#mysql.sock : tc0112:28:14>
查询了三次每次查询耗时都是0.13秒。
root@localhost#mysql.sock : tc0112:31:01>select count(*) from test2 use index (PRIMARY);+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.15 sec)
root@localhost#mysql.sock : tc0112:31:02>select count(*) from test2 use index (PRIMARY);+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.15 sec)
root@localhost#mysql.sock : tc0112:31:05>select count(*) from test2 use index (PRIMARY);+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.15 sec)
使用主键查询了三次，每次查询耗时都是0.15秒，为什么走主键会有0.02秒的差异呢？
分析过程
查看执行计划
我们首先想到的就是下看看执行计划是否一样。
root@localhost#mysql.sock : tc0112:33:34>explain select count(*) from test2;+----+-------------+-------+------------+-------+---------------+----------------+---------+------+---------+----------+-------------+| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |+----+-------------+-------+------------+-------+---------------+----------------+---------+------+---------+----------+-------------+| 1 | SIMPLE | test2 | NULL | index | NULL | index_vote_num | 4 | NULL | 1114117 | 100.00 | Using index |+----+-------------+-------+------------+-------+---------------+----------------+---------+------+---------+----------+-------------+1 row in set, 1 warning (0.07 sec)
root@localhost#mysql.sock : tc0112:33:35>explain select count(*) from test2 use index (PRIMARY);+----+-------------+-------+------------+-------+---------------+---------+---------+------+---------+----------+-------------+| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |+----+-------------+-------+------------+-------+---------------+---------+---------+------+---------+----------+-------------+| 1 | SIMPLE | test2 | NULL | index | NULL | PRIMARY | 4 | NULL | 1114117 | 100.00 | Using index |+----+-------------+-------+------------+-------+---------------+---------+---------+------+---------+----------+-------------+1 row in set, 1 warning (0.00 sec)
从显示的执行计划我们可以看出，两个SQL语句的执行计划不一样，走主键索引反而慢0.02秒，什么原因？
查看索引情况如下：
root@localhost#mysql.sock : tc0112:34:27>show index from test2;+-------+------------+----------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |+-------+------------+----------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+| test2 | 0 | PRIMARY | 1 | id | A | 1054391 | NULL | NULL | | BTREE | | || test2 | 1 | index_name | 1 | name | A | 1055674 | NULL | NULL | | BTREE | | || test2 | 1 | index_vote_num | 1 | vote_num | A | 9929 | NULL | NULL | | BTREE | | || test2 | 1 | index_group | 1 | group_id | A | 501 | NULL | NULL | | BTREE | | || test2 | 1 | index_group | 2 | sdate | A | 824214 | NULL | NULL | YES | BTREE | | |+-------+------------+----------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+5 rows in set (0.00 sec)
cardinality是索引中不重复记录的预估值。
使用profile查看耗时差异在什么地方
root@localhost#mysql.sock : tc0112:41:21>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.14 sec)root@localhost#mysql.sock : tc0112:41:33>show profile cpu,block io for query 3;+----------------------+----------+----------+------------+--------------+---------------+| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |+----------------------+----------+----------+------------+--------------+---------------+| starting | 0.000047 | 0.000033 | 0.000009 | 0 | 0 || checking permissions | 0.000005 | 0.000004 | 0.000001 | 0 | 0 || Opening tables | 0.000013 | 0.000010 | 0.000003 | 0 | 0 || init | 0.000011 | 0.000008 | 0.000003 | 0 | 0 || System lock | 0.000006 | 0.000005 | 0.000001 | 0 | 0 || optimizing | 0.000003 | 0.000003 | 0.000001 | 0 | 0 || statistics | 0.000010 | 0.000007 | 0.000002 | 0 | 0 || preparing | 0.000007 | 0.000006 | 0.000002 | 0 | 0 || executing | 0.000002 | 0.000001 | 0.000000 | 0 | 0 || Sending data | 0.133695 | 0.133527 | 0.000000 | 0 | 0 || end | 0.000016 | 0.000009 | 0.000000 | 0 | 0 || query end | 0.000009 | 0.000009 | 0.000000 | 0 | 0 || closing tables | 0.000008 | 0.000008 | 0.000000 | 0 | 0 || freeing items | 0.000017 | 0.000017 | 0.000000 | 0 | 0 || cleaning up | 0.000009 | 0.000009 | 0.000000 | 0 | 0 |+----------------------+----------+----------+------------+--------------+---------------+15 rows in set, 1 warning (0.00 sec)
root@localhost#mysql.sock : tc0112:41:27>select count(*) from test2 use index (PRIMARY);+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.15 sec)root@localhost#mysql.sock : tc0112:41:56>show profile cpu,block io for query 4;+----------------------+----------+----------+------------+--------------+---------------+| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |+----------------------+----------+----------+------------+--------------+---------------+| starting | 0.000052 | 0.000036 | 0.000010 | 0 | 0 || checking permissions | 0.000005 | 0.000003 | 0.000001 | 0 | 0 || Opening tables | 0.000013 | 0.000011 | 0.000004 | 0 | 0 || init | 0.000010 | 0.000007 | 0.000002 | 0 | 0 || System lock | 0.000006 | 0.000005 | 0.000001 | 0 | 0 || optimizing | 0.000003 | 0.000002 | 0.000001 | 0 | 0 || statistics | 0.000010 | 0.000008 | 0.000002 | 0 | 0 || preparing | 0.000008 | 0.000006 | 0.000002 | 0 | 0 || executing | 0.000002 | 0.000001 | 0.000000 | 0 | 0 || Sending data | 0.149678 | 0.149268 | 0.000191 | 0 | 0 || end | 0.000014 | 0.000006 | 0.000002 | 0 | 0 || query end | 0.000009 | 0.000007 | 0.000002 | 0 | 0 || closing tables | 0.000008 | 0.000006 | 0.000002 | 0 | 0 || freeing items | 0.000014 | 0.000011 | 0.000003 | 0 | 0 || cleaning up | 0.000015 | 0.000011 | 0.000003 | 0 | 0 |+----------------------+----------+----------+------------+--------------+---------------+15 rows in set, 1 warning (0.00 sec)
差异主要出现在Sending data部分，Sending data包括“收集 + 发送" 数据。
查看optimizer_trace
root@localhost#mysql.sock : tc0112:45:02>set optimizer_trace='enabled=on';Query OK, 0 rows affected (0.00 sec)
root@localhost#mysql.sock : tc0112:46:05>set optimizer_trace_max_mem_size=1000000;Query OK, 0 rows affected (0.00 sec)
root@localhost#mysql.sock : tc0112:46:11>set end_markers_in_json=on;Query OK, 0 rows affected (0.00 sec)
root@localhost#mysql.sock : tc0112:46:16>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.13 sec)
root@localhost#mysql.sock : tc0112:46:22>select * from information_schema.optimizer_traceG*************************** 1. row *************************** QUERY: select count(*) from test2 TRACE: { "steps": [ { "join_preparation": { "select#": 1, "steps": [ { "expanded_query": "/* select#1 */ select count(0) AS `count(*)` from `test2`" } ] /* steps */ } /* join_preparation */ }, { "join_optimization": { "select#": 1, "steps": [ { "table_dependencies": [ { "table": "`test2`", "row_may_be_null": false, "map_bit": 0, "depends_on_map_bits": [ ] /* depends_on_map_bits */ } ] /* table_dependencies */ }, { "rows_estimation": [ { "table": "`test2`", "table_scan": { "rows": 1114117, "cost": 6375 } /* table_scan */ } ] /* rows_estimation */ }, { "considered_execution_plans": [ { "plan_prefix": [ ] /* plan_prefix */, "table": "`test2`", "best_access_path": { "considered_access_paths": [ { "rows_to_scan": 1114117, "access_type": "scan", "resulting_rows": 1.11e6, "cost": 229198, "chosen": true } ] /* considered_access_paths */ } /* best_access_path */, "condition_filtering_pct": 100, "rows_for_plan": 1.11e6, "cost_for_plan": 229198, "chosen": true } ] /* considered_execution_plans */ }, { "attaching_conditions_to_tables": { "original_condition": null, "attached_conditions_computation": [ ] /* attached_conditions_computation */, "attached_conditions_summary": [ { "table": "`test2`", "attached": null } ] /* attached_conditions_summary */ } /* attaching_conditions_to_tables */ }, { "refine_plan": [ { "table": "`test2`" } ] /* refine_plan */ } ] /* steps */ } /* join_optimization */ }, { "join_execution": { "select#": 1, "steps": [ ] /* steps */ } /* join_execution */ } ] /* steps */}MISSING_BYTES_BEYOND_MAX_MEM_SIZE: 0 INSUFFICIENT_PRIVILEGES: 01 row in set (0.00 sec)
root@localhost#mysql.sock : tc0112:46:33>
root@localhost#mysql.sock : tc0104:49:23>select * from information_schema.optimizer_traceG*************************** 1. row *************************** QUERY: select count(*) from test2 use index (PRIMARY) TRACE: { "steps": [ { "join_preparation": { "select#": 1, "steps": [ { "expanded_query": "/* select#1 */ select count(0) AS `count(*)` from `test2` USE INDEX (PRIMARY)" } ] /* steps */ } /* join_preparation */ }, { "join_optimization": { "select#": 1, "steps": [ { "table_dependencies": [ { "table": "`test2` USE INDEX (PRIMARY)", "row_may_be_null": false, "map_bit": 0, "depends_on_map_bits": [ ] /* depends_on_map_bits */ } ] /* table_dependencies */ }, { "rows_estimation": [ { "table": "`test2` USE INDEX (PRIMARY)", "table_scan": { "rows": 1114117, "cost": 6375 } /* table_scan */ } ] /* rows_estimation */ }, { "considered_execution_plans": [ { "plan_prefix": [ ] /* plan_prefix */, "table": "`test2` USE INDEX (PRIMARY)", "best_access_path": { "considered_access_paths": [ { "rows_to_scan": 1114117, "access_type": "scan", "resulting_rows": 1.11e6, "cost": 229198, "chosen": true } ] /* considered_access_paths */ } /* best_access_path */, "condition_filtering_pct": 100, "rows_for_plan": 1.11e6, "cost_for_plan": 229198, "chosen": true } ] /* considered_execution_plans */ }, { "attaching_conditions_to_tables": { "original_condition": null, "attached_conditions_computation": [ ] /* attached_conditions_computation */, "attached_conditions_summary": [ { "table": "`test2` USE INDEX (PRIMARY)", "attached": null } ] /* attached_conditions_summary */ } /* attaching_conditions_to_tables */ }, { "refine_plan": [ { "table": "`test2` USE INDEX (PRIMARY)" } ] /* refine_plan */ } ] /* steps */ } /* join_optimization */ }, { "join_execution": { "select#": 1, "steps": [ ] /* steps */ } /* join_execution */ } ] /* steps */}MISSING_BYTES_BEYOND_MAX_MEM_SIZE: 0 INSUFFICIENT_PRIVILEGES: 01 row in set (0.00 sec)
根据收集到的optimizer_trace信息，没有看到查异。
使用strace分析
使用的命令
strace -o ./xxxx.log -T -tt -f -p `pidof mysqld`
收集到的主要内容如下：
2779 17:31:57.090832 recvfrom(19, "3select count(*) from test2", 27, MSG_DONTWAIT, NULL, NULL) = 27 <0.000011>2746 17:31:57.131173 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <1.000589>2746 17:31:57.131221 futex(0x3176e68, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000009>2746 17:31:57.131471 futex(0x3176e94, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 388151, {1593250318, 131449000}, ffffffff <unfinished ...>2745 17:31:57.198173 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <1.000774>2745 17:31:57.198219 futex(0x420a018, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000008>2745 17:31:57.198251 futex(0x420a044, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 388233, {1593250318, 198244000}, ffffffff <unfinished ...>2779 17:31:57.221047 sendto(19, "1 1136 23def 10count(*) f? 25 "..., 62, MSG_DONTWAIT, NULL, 0) = 62 <0.000157>2779 17:31:57.221269 recvfrom(19, 0x57addc0, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000009>2779 17:31:57.221303 poll([{fd=19, events=POLLIN|POLLPRI}], 1, 600000 <unfinished ...>
2779 17:32:21.413376 recvfrom(19, "3select count(*) from test2 use "..., 47, MSG_DONTWAIT, NULL, NULL) = 47 <0.000010>2748 17:32:21.446209 <... nanosleep resumed> NULL) = 0 <1.009241>2748 17:32:21.446265 nanosleep({1, 0}, <unfinished ...>2738 17:32:21.501216 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out) <1.007208>2738 17:32:21.501262 futex(0x3177018, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000008>2738 17:32:21.501297 futex(0x3177044, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 388723, {1593250342, 501290000}, ffffffff <unfinished ...>2737 17:32:21.523241 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510550>2736 17:32:21.523280 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510589>2735 17:32:21.523287 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510591>2734 17:32:21.523292 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510593>2733 17:32:21.523298 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510594>2732 17:32:21.523303 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510597>2731 17:32:21.523309 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510598>2730 17:32:21.523314 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510600>2729 17:32:21.523319 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510601>2728 17:32:21.523324 <... io_getevents resumed> [], {0, 500000000}) = 0 <0.510594>2737 17:32:21.523368 io_getevents(140091831586816, 1, 256, <unfinished ...>2736 17:32:21.523377 io_getevents(140091831599104, 1, 256, <unfinished ...>2735 17:32:21.523382 io_getevents(140091831611392, 1, 256, <unfinished ...>2734 17:32:21.523385 io_getevents(140091831623680, 1, 256, <unfinished ...>2733 17:32:21.523389 io_getevents(140091831926784, 1, 256, <unfinished ...>2732 17:32:21.523393 io_getevents(140091831939072, 1, 256, <unfinished ...>2731 17:32:21.523397 io_getevents(140092021788672, 1, 256, <unfinished ...>2730 17:32:21.523401 io_getevents(140092021800960, 1, 256, <unfinished ...>2729 17:32:21.523405 io_getevents(140091831902208, 1, 256, <unfinished ...>2728 17:32:21.523408 io_getevents(140091831914496, 1, 256, <unfinished ...>2779 17:32:21.563856 sendto(19, "1 1136 23def 10count(*) f? 25 "..., 62, MSG_DONTWAIT, NULL, 0) = 62 <0.000103>2779 17:32:21.564086 recvfrom(19, 0x57addc0, 4, MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable) <0.000008>2779 17:32:21.564120 poll([{fd=19, events=POLLIN|POLLPRI}], 1, 600000 <unfinished ...>
发现使用主键查询的步骤更多，自然也就增加了耗时。
查看一下SQL的逻辑读情况
root@localhost#mysql.sock : tc0105:39:52>show status like 'innodb_buffer%';+---------------------------------------+--------------------------------------------------+| Variable_name | Value |+---------------------------------------+--------------------------------------------------+| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started || Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 200625 11:36:26 || Innodb_buffer_pool_resize_status | || Innodb_buffer_pool_pages_data | 21727 || Innodb_buffer_pool_bytes_data | 355975168 || Innodb_buffer_pool_pages_dirty | 0 || Innodb_buffer_pool_bytes_dirty | 0 || Innodb_buffer_pool_pages_flushed | 353199 || Innodb_buffer_pool_pages_free | 11017 || Innodb_buffer_pool_pages_misc | 24 || Innodb_buffer_pool_pages_total | 32768 || Innodb_buffer_pool_read_ahead_rnd | 0 || Innodb_buffer_pool_read_ahead | 0 || Innodb_buffer_pool_read_ahead_evicted | 0 || Innodb_buffer_pool_read_requests | 120950072 || Innodb_buffer_pool_reads | 576 || Innodb_buffer_pool_wait_free | 0 || Innodb_buffer_pool_write_requests | 13289147 |+---------------------------------------+--------------------------------------------------+18 rows in set (0.00 sec)
root@localhost#mysql.sock : tc0105:39:54>select count(*) from test2;+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.13 sec)
root@localhost#mysql.sock : tc0105:39:57>show status like 'innodb_buffer%';+---------------------------------------+--------------------------------------------------+| Variable_name | Value |+---------------------------------------+--------------------------------------------------+| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started || Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 200625 11:36:26 || Innodb_buffer_pool_resize_status | || Innodb_buffer_pool_pages_data | 21727 || Innodb_buffer_pool_bytes_data | 355975168 || Innodb_buffer_pool_pages_dirty | 0 || Innodb_buffer_pool_bytes_dirty | 0 || Innodb_buffer_pool_pages_flushed | 353199 || Innodb_buffer_pool_pages_free | 11017 || Innodb_buffer_pool_pages_misc | 24 || Innodb_buffer_pool_pages_total | 32768 || Innodb_buffer_pool_read_ahead_rnd | 0 || Innodb_buffer_pool_read_ahead | 0 || Innodb_buffer_pool_read_ahead_evicted | 0 || Innodb_buffer_pool_read_requests | 121076043 || Innodb_buffer_pool_reads | 576 || Innodb_buffer_pool_wait_free | 0 || Innodb_buffer_pool_write_requests | 13289147 |+---------------------------------------+--------------------------------------------------+18 rows in set (0.00 sec)
root@localhost#mysql.sock : tc0105:39:59>121076043-120950072=125971
root@localhost#mysql.sock : tc0105:40:30>show status like 'innodb_buffer%';+---------------------------------------+--------------------------------------------------+| Variable_name | Value |+---------------------------------------+--------------------------------------------------+| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started || Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 200625 11:36:26 || Innodb_buffer_pool_resize_status | || Innodb_buffer_pool_pages_data | 21728 || Innodb_buffer_pool_bytes_data | 355991552 || Innodb_buffer_pool_pages_dirty | 0 || Innodb_buffer_pool_bytes_dirty | 0 || Innodb_buffer_pool_pages_flushed | 353303 || Innodb_buffer_pool_pages_free | 11016 || Innodb_buffer_pool_pages_misc | 24 || Innodb_buffer_pool_pages_total | 32768 || Innodb_buffer_pool_read_ahead_rnd | 0 || Innodb_buffer_pool_read_ahead | 0 || Innodb_buffer_pool_read_ahead_evicted | 0 || Innodb_buffer_pool_read_requests | 121120574 || Innodb_buffer_pool_reads | 576 || Innodb_buffer_pool_wait_free | 0 || Innodb_buffer_pool_write_requests | 13289849 |+---------------------------------------+--------------------------------------------------+18 rows in set (0.00 sec)
root@localhost#mysql.sock : tc0105:40:31>select count(*) from test2 use index (PRIMARY);+----------+| count(*) |+----------+| 1120198 |+----------+1 row in set (0.15 sec)
root@localhost#mysql.sock : tc0105:40:33>show status like 'innodb_buffer%';+---------------------------------------+--------------------------------------------------+| Variable_name | Value |+---------------------------------------+--------------------------------------------------+| Innodb_buffer_pool_dump_status | Dumping of buffer pool not started || Innodb_buffer_pool_load_status | Buffer pool(s) load completed at 200625 11:36:26 || Innodb_buffer_pool_resize_status | || Innodb_buffer_pool_pages_data | 21728 || Innodb_buffer_pool_bytes_data | 355991552 || Innodb_buffer_pool_pages_dirty | 0 || Innodb_buffer_pool_bytes_dirty | 0 || Innodb_buffer_pool_pages_flushed | 353303 || Innodb_buffer_pool_pages_free | 11016 || Innodb_buffer_pool_pages_misc | 24 || Innodb_buffer_pool_pages_total | 32768 || Innodb_buffer_pool_read_ahead_rnd | 0 || Innodb_buffer_pool_read_ahead | 0 || Innodb_buffer_pool_read_ahead_evicted | 0 || Innodb_buffer_pool_read_requests | 121251637 || Innodb_buffer_pool_reads | 576 || Innodb_buffer_pool_wait_free | 0 || Innodb_buffer_pool_write_requests | 13289849 |+---------------------------------------+--------------------------------------------------+18 rows in set (0.00 sec)121251637-121120574=131063
Innodb_buffer_pool_read_requests走主键查询用了131063，不走主键用了 125971，相差5092。
小结
执行计划不一样，和MySQL的CBO算法有关，使用optimizer_trace没有看到差异，也就不继续分析下去，其他专家如果有更好的方法可以分享一下。
逻辑读不一样和使用的索引字段有关。
这里提供MySQL的一些分析思路和方法，供大家参考。
墨天轮原文链接：https://www.modb.pro/db/26860（复制到浏览器中打开或者点击“阅读原文”）
推荐阅读：144页！分享珍藏已久的数据库技术年刊
数据和云
ID：OraNews
如有收获，请划至底部，点击“在看”，谢谢！
点击下图查看更多 ↓
云和恩墨大讲堂 | 一个分享交流的地方
长按，识别二维码，加入万人交流社群
请备注：云和恩墨大讲堂
点个“在看”
你的喜欢会被看到❤