背景:
今天遇到一個主鍵范圍查找的情況:
select ... from tb left join tb1 on ... where tb.id between 0 and 10000
id是主鍵,每次取10000。上面的這個查詢id范圍越往后面消耗的時間越久。通過id自增主鍵去查找數據應該不會出現這個現象的。以前都沒有注意這個奇怪的現象,現在就好好分析下。
知識點:
索引的根節點到子節點的距離是一樣的,根節點包含指向子節點的指針,存儲引擎通過指針來查找數據。所以通過索引查找他們的消耗是一樣的。
測試:
1:SQL結構:
explain select sql_no_cache post.id, post.root, post.boardId, post.postTime, post.subject, post.file, body.body, post.userId, post.click, post.child, post.type, post.rating, post.votes, topic.approved, topic.archived, topic.reply, user.status from j_post as post left join j_post_body as body on post.id = body.id left join j_topic as topic on post.id=topic.id left join j_user as user on user.id=post.userId where post.id between 1090000 and 1100000; +----+-------------+-------+--------+---------------+---------+---------+------------------+-------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+--------+---------------+---------+---------+------------------+-------+-------------+ | 1 | SIMPLE | post | range | PRIMARY | PRIMARY | 4 | NULL | 17876 | Using where | | 1 | SIMPLE | body | eq_ref | PRIMARY | PRIMARY | 4 | jute.post.id | 1 | | | 1 | SIMPLE | topic | eq_ref | PRIMARY | PRIMARY | 4 | jute.post.id | 1 | | | 1 | SIMPLE | user | eq_ref | PRIMARY | PRIMARY | 4 | jute.post.userId | 1 | | +----+-------------+-------+--------+---------------+---------+---------+------------------+-------+-------------+
執行的狀況:
1090000 and 1100000 >show profile cpu,block io for query 1; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000156 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000062 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000068 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.001326 | 0.004001 | 0.000000 | 0 | 0 | | preparing | 0.000030 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.640303 | 0.384024 | 0.028001 | 0 | 0 | | end | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 19 rows in set (0.01 sec) 21000000 and 21010000 >show profile cpu,block io for query 2; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000161 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000042 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000065 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.017431 | 0.000000 | 0.000000 | 144 | 0 | | preparing | 0.000031 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 3.228074 | 0.696043 | 0.164010 | 45936 | 0 | | end | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000052 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 19 rows in set (0.01 sec) 26000000 and 26010000 >show profile cpu,block io for query 3; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000146 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000042 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000065 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.013855 | 0.004000 | 0.000000 | 392 | 0 | | preparing | 0.000064 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 4.075430 | 0.676042 | 0.140009 | 82288 | 0 | | end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000050 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 19 rows in set (0.03 sec) 6000000 and 6010000 >show profile cpu,block io for query 4; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000164 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000041 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000064 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.013467 | 0.004000 | 0.000000 | 392 | 0 | | preparing | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 1.345275 | 0.476030 | 0.084005 | 19848 | 0 | | end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000042 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000058 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 19 rows in set (0.02 sec) 27000000 and 27010000 >show profile cpu,block io for query 5; +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000144 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000041 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000065 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.011399 | 0.000000 | 0.000000 | 208 | 0 | | preparing | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 3.157346 | 0.616038 | 0.176011 | 71840 | 0 | | end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000054 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000056 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 19 rows in set (0.02 sec)
從上面的結果可以看出越往后,消耗的時間越久。
這個和知識點里說的不一樣,為什么出現這個情況?先從另一方面看:上面是連表查詢,很可能出現問題的不是使用主鍵id的這個表。那就開始用單表看看,會是怎么樣的情況。
2:SQL結構
explain select sql_no_cache post.id, post.root, post.boardId, post.postTime, post.subject, post.file, post.userId, post.click, post.child, post.type, post.rating, post.votes from jute_post as post where post.id between 1090000 and 1100000; +----+-------------+-------+-------+---------------+---------+---------+------+-------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+-------+---------------+---------+---------+------+-------+-------------+ | 1 | SIMPLE | post | range | PRIMARY | PRIMARY | 4 | NULL | 17876 | Using where | +----+-------------+-------+-------+---------------+---------+---------+------+-------+-------------+
執行狀況:
1090000 and 1100000 +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000164 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.174908 | 0.012001 | 0.004000 | 1720 | 0 | | System lock | 0.000046 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000066 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000033 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.001264 | 0.004000 | 0.000000 | 0 | 0 | | preparing | 0.000040 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.057492 | 0.052004 | 0.004000 | 16 | 0 | | end | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 21000000 and 21010000 +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000101 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000029 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000044 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.007977 | 0.000000 | 0.000000 | 32 | 0 | | preparing | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.083919 | 0.068004 | 0.004001 | 288 | 0 | | end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 26000000 and 26010000 +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000102 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000043 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.001315 | 0.000000 | 0.000000 | 0 | 0 | | preparing | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.083872 | 0.068004 | 0.004000 | 48 | 0 | | end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 6000000 and 6010000 +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000082 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000026 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.000753 | 0.000000 | 0.004000 | 0 | 0 | | preparing | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.057981 | 0.036003 | 0.000000 | 40 | 0 | | end | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.007655 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+ 27000000 and 27010000 +----------------------+----------+----------+------------+--------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+--------------+---------------+ | starting | 0.000103 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000043 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.008353 | 0.000000 | 0.004001 | 8 | 0 | | preparing | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.071468 | 0.060004 | 0.004000 | 64 | 0 | | end | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | | cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+--------------+---------------+
發現上面執行時候消耗都差不多,驗證了知識點里的內容。
總結:
上面的測試數據都是在磁盤上,沒有預熱的,所以和BP無關。通過1和2的測試對比得知:越往后越慢的問題在於Join,多表查出來不一樣的時間,應該是跟數據在磁盤分布有關。id越往后越慢主要受到了其他幾張關聯表的影響。對於數據在磁盤上怎么分布的,有機會得去好好的學習下。