简单记录一下，以供后面分析
一、问题
一个朋友@问心问我为什么在optimizing 阶段会慢
mysql> show profiles;
+----------+------------+----------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+----------------------------------------+
| 1 | 0.00399900 | SHOW VARIABLES LIKE '%profiling%' |
| 2 | 6.62358725 | select count(*) from cw_base_snap_flow |
+----------+------------+----------------------------------------+
2 rows in set, 1 warning (0.00 sec)
mysql> show profile block io,cpu for query 2;
+----------------------+----------+-----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+-----------+------------+--------------+---------------+
| starting | 0.000073 | 0.000112 | 0.000004 | 0 | 0 |
| checking permissions | 0.000012 | 0.000022 | 0.000002 | 0 | 0 |
| Opening tables | 0.000033 | 0.000063 | 0.000003 | 0 | 0 |
| init | 0.000017 | 0.000032 | 0.000002 | 0 | 0 |
| System lock | 0.000018 | 0.000033 | 0.000002 | 0 | 0 |
| optimizing | 6.623237 | 17.625023 | 2.907697 | 22520 | 63424 |
| executing | 0.000040 | 0.000053 | 0.000004 | 0 | 0 |
| end | 0.000011 | 0.000019 | 0.000001 | 0 | 0 |
| query end | 0.000014 | 0.000028 | 0.000000 | 0 | 0 |
| closing tables | 0.000015 | 0.000028 | 0.000002 | 0 | 0 |
| freeing items | 0.000023 | 0.000042 | 0.000003 | 0 | 0 |
| logging slow query | 0.000070 | 0.000133 | 0.000007 | 0 | 8 |
| cleaning up | 0.000027 | 0.000051 | 0.000003 | 0 | 0 |
+----------------------+----------+-----------+------------+--------------+---------------+
二、以前的认识
因为优化器部分没有怎么仔细看过但记录了一些阶段的调入接口
- starting:lex+yacc 语法语义解析,得到解析树
- checking permissions:权限检查
- Opening tables:打开表做好table cache，做好和innodb表物理文件的关联，同时加MDL LOCK 主要函数open_tables
- init:语句做首次优化 调入函数SELECT_LEX::prepare及st_select_lex::prepare
- System lock:主要函数handler::ha_external_lock，之前会实现myisam等引擎的mysql层表锁，innodb做共享表锁。
下面三个阶段对应 逻辑物理优化执行计划生成： - optimizing: SELECT_LEX::optimize->JOIN::optimize 调入，
- statistics: JOIN::make_join_plan调入，
- preparing: make_join_select 调入
所以还是比较奇怪
三、栈帧
放朋友打印了一下栈帧才发现问题，居然count(*)的实际数据访问阶段提前了如下：
Thread 1 (process 33641):
#0 0x00007f20e284ca93 in pread64 () from /lib64/libpthread.so.0
#1 0x00000000010649c3 in os_file_io (in_type=..., file=56, buf=0x7f20b2a08000, n=16384, offset=4458364928, err=0x7f1f2de82a9c) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/os/os0file.cc:5423
#2 0x0000000001065221 in os_file_pread (err=0x7f1f2de82a9c, offset=4458364928, n=16384, buf=0x7f20b2a08000, file=56, type=...) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/os/os0file.cc:5601
#3 os_file_read_page (type=..., file=56, buf=0x7f20b2a08000, offset=4458364928, n=16384, o=0x0, exit_on_err=true) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/os/os0file.cc:5640
#4 0x0000000001065767 in os_file_read_func (type=..., file=<optimized out>, buf=<optimized out>, offset=<optimized out>, n=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/os/os0file.cc:6033
#5 0x00000000012056eb in pfs_os_aio_func (src_line=5758, m2=0x7f20ae782388, m1=0xc9235e8, read_only=false, n=16384, offset=4458364928, buf=0x7f20b2a08000, file=56, name=0xc9236b8 "./bat/cw_base_snap_flow.ibd", mode=24, type=..., src_file=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/include/os0file.ic:252
#6 fil_io (type=..., sync=true, page_id=..., page_size=..., byte_offset=139771890905024, len=16384, buf=0x7f20b2a08000, message=0x7f20ae782388) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/fil/fil0fil.cc:5758
#7 0x00000000011bd2b2 in buf_read_page_low (err=0x7f1f2de833ac, sync=true, type=0, mode=<optimized out>, page_id=..., page_size=..., unzip=false) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/buf/buf0rea.cc:183
#8 0x00000000011bdd20 in buf_read_page (page_id=..., page_size=...) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/buf/buf0rea.cc:406
#9 0x000000000119c9eb in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=<optimized out>, mode=10, file=0x15fe390 "/export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/btr/btr0pcur.cc", line=448, mtr=0x7f1f2de837f0, dirty_with_no_latch=false) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/buf/buf0buf.cc:4180
#10 0x0000000001185841 in btr_block_get_func (mtr=0x7f1f2de837f0, line=448, file=0x15fe390 "/export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/btr/btr0pcur.cc", mode=1, page_size=..., page_id=...) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/include/btr0btr.ic:63
#11 btr_pcur_move_to_next_page (cursor=0x7f1e18271c40, mtr=0x7f1f2de837f0) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/btr/btr0pcur.cc:448
#12 0x00000000010dfc22 in btr_pcur_move_to_next (cursor=<optimized out>, mtr=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/include/btr0pcur.ic:360
#13 0x00000000010e5019 in row_search_mvcc (buf=0x7f1e18221768 "@\027\"\030\036\177", mode=PAGE_CUR_G, prebuilt=0x7f1e18271a48, match_mode=0, direction=1) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/row/row0sel.cc:5872
#14 0x00000000010c3960 in row_search_for_mysql (direction=1, prebuilt=0x7f1e18271a48, buf=0x7f1e18221768 "@\027\"\030\036\177", mode=<optimized out>, match_mode=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/include/row0sel.ic:139
#15 row_scan_index_for_mysql (prebuilt=0x7f1e18271a48, index=0x7f1ec01ad8d8, check_keys=false, n_rows=0x7f1f2de86438) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/row/row0mysql.cc:5896
#16 0x0000000000ff815b in ha_innobase::records (this=0x7f1e1826da90, num_rows=0x7f1f2de87200) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/storage/innobase/handler/ha_innodb.cc:13280
#17 0x0000000000e4e0ee in ha_records (num_rows=0x7f1f2de87200, this=0x7f1e1826da90) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/handler.h:2668
#18 get_exact_record_count (tables=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/opt_sum.cc:84
#19 opt_sum_query (thd=0x7f1e18012170, tables=0x7f1e180016a8, all_fields=..., conds=0x0) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/opt_sum.cc:347
#20 0x0000000000ceba8f in JOIN::optimize (this=0x7f1e18001db8) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/sql_optimizer.cc:293
#21 0x0000000000d301d2 in st_select_lex::optimize (this=0x7f1e18000940, thd=0x7f1e18012170) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/sql_select.cc:1009
#22 0x0000000000d3046f in handle_query (thd=0x7f1e18012170, lex=0x7f1e180142b8, result=0x7f1e18001ce8, added_options=1, removed_options=0) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/sql_select.cc:164
#23 0x0000000000cf1cc3 in execute_sqlcom_select (thd=0x7f1e18012170, all_tables=<optimized out>) at /export/home/pb2/build/sb_0-19699473-1468327072.46/mysql-5.7.14/sql/sql_parse.cc:5143
大家可以看看。实际上这里我们可以看到已经到了innodb层并且在读取数据了。这个阶段居然是optimizing调入的，当然也就在optimizing阶段了。
四、源码调入
一、opt_sum_query 部分
case Item_sum::COUNT_FUNC:
/*
If the expr in COUNT(expr) can never be null we can change this
to the number of rows in the tables if this number is exact and
there are no outer joins.
Don't apply this optimization when there is a FORCE INDEX on any of
the tables.
*/
if (!conds && !((Item_sum_count*) item)->get_arg(0)->maybe_null &&
!outer_tables && maybe_exact_count && !force_index)
{
if (!is_exact_count)
{
/*
We will skip calling record count for explain query,
since it might take long time to compute.
*/
if (!thd->lex->describe &&
(count= get_exact_record_count(tables)) == ULLONG_MAX) //这里调用了get_exact_record_count
{
/* Error from handler in counting rows. Don't optimize count() */
const_result= 0;
continue;
}
is_exact_count= 1; // count is now exact
}
}
