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