MySQL：COUNT(*) profile optimizing階段慢

簡單記錄一下，以供后面分析

一、問題

一個朋友@問心問我為什么在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
          }
        }

作者微信：gp_22389860