'select from partition table limit 1' takes much more time than explan analyze shows #40441
Description
Enhancement
MySQL [(none)]> explain analyze
SELECT PROV_DESC , AREA_DESC , USER_ID , CUST_ID , SERVICE_TYPE ,
SERVICE_TYPE_DESC , SERVICE_BIG_TYPE , INNET_DATE , OPER_DATE , USER_CLASS ,
CLOSE_DATE , LAST_STOP_DATE , USER_STATUS_CBSS_DESC , STOP_TYPE_DESC ,
LOST_TYPE_DESC , RN , DINNER_BASE_FEE , DINNER_GRAD , SERVICE_TYPE_OLD ,
LOGIN_NET_TYPE , LOGIN_NET_TYPE_DESC , IS_COMP , IS_ACCT , IS_ACCT_LAST_MON ,
IS_INNET , IS_CARD , IS_STAT , IS_THIS_DEV_ADD , IS_LAST_MON_DEV ,
IS_THIS_MON_BREAK , IS_THIS_MON_STOP , IS_SING_CARD , IS_FAMILY_CARD ,
IS_RURAL_MARKET , IS_IOT , IS_DOUBLE_TERM , IS_GROUP , IS_ACTIVE , IS_THREE_NIL ,
IS_THREE_NIL_LAST_MON , IS_2I , IS_ACTIVE_USER , TOTAL_FEE , TOTAL_FLUX ,
TOTAL_FLUX_CARRY_OVER , TOTAL_FLUX_DUR , TOTAL_CALL_BILL_DUR , TOTAL_CDR_NUMS ,
TOTAL_SMS_NUMS , OWE_MONTH
FROM JHS_APP.step_28229746852 LIMIT 1 ;
Explan analyze result, max rpc time is 726.5µs, but the query in total takes 63ms:
+------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------+---------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------+---------+------+
| Limit_17 | 100.00 | 100 | root | | time:1.36ms, loops:2 | offset:1, count:100 | N/A | N/A |
| └─TableReader_25 | 101.00 | 101 | root | partition:p0,p1,p2,p3,p4,p5,p6,p7,p8,p9,p10,p11,p12,p13,p14,p15,p16,p17,p18,p19,p20,p21,p22,p23,p24,p25,p26,p27,p28,p29,p30 | time:1.25ms, loops:1, cop_task: {num: 1, max: 726.5µs, proc_keys: 0, rpc_num: 1, rpc_time: 679.5µs, copr_cache_hit_ratio: 1.00, distsql_concurrency: 96} | data:Limit_24 | 3.73 MB | N/A |
| └─Limit_24 | 101.00 | 101 | cop[tikv] | | tikv_task:{time:0s, loops:3}, scan_detail: {get_snapshot_time: 99.6µs, rocksdb: {block: {}}} | offset:0, count:101 | N/A | N/A |
| └─Selection_21 | 101.00 | 224 | cop[tikv] | | tikv_task:{time:0s, loops:3} | eq(jhs_dww.dwa_v_m_cus_al_user_info_yd.month_id, "202110") | N/A | N/A |
| └─TableFullScan_20 | 101.00 | 224 | cop[tikv] | table:t0 | tikv_task:{time:0s, loops:3} | keep order:false | N/A | N/A |
+------------------------------+---------+---------+-----------+-----------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------+---------+------+
5 rows in set (0.063 sec)
Here is the trace result:
+-----------------------------------------------------------------------------+-----------------+-------------+
| operation | startTS | duration |
+-----------------------------------------------------------------------------+-----------------+-------------+
| trace | 23:54:55.068713 | 181.93499ms |
| ├─session.ExecuteStmt | 23:54:55.068729 | 164.15001ms |
| │ ├─executor.Compile | 23:54:55.068861 | 20.49214ms |
| │ └─session.runStmt | 23:54:55.089423 | 142.85039ms |
| │ └─TableReaderExecutor.Open | 23:54:55.089817 | 141.95558ms |
| │ └─distsql.Select | 23:54:55.089979 | 141.69896ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231826 | 16.71035ms |
| │ │ └─rpcClient.SendRequest, region ID: 964253, type: Cop | 23:54:55.232001 | 8.04579ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231862 | 7.8585ms |
| │ │ └─rpcClient.SendRequest, region ID: 964249, type: Cop | 23:54:55.231955 | 7.18586ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231884 | 15.06774ms |
| │ │ └─rpcClient.SendRequest, region ID: 964247, type: Cop | 23:54:55.232018 | 5.78104ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231923 | 11.46212ms |
| │ │ └─rpcClient.SendRequest, region ID: 964251, type: Cop | 23:54:55.232007 | 5.76149ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231926 | 9.02249ms |
| │ │ └─rpcClient.SendRequest, region ID: 964299, type: Cop | 23:54:55.232370 | 5.60385ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231928 | 12.7523ms |
| │ │ └─rpcClient.SendRequest, region ID: 964361, type: Cop | 23:54:55.231994 | 6.58863ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231935 | 4.67326ms |
| │ │ └─rpcClient.SendRequest, region ID: 964438, type: Cop | 23:54:55.232037 | 4.53871ms |
| │ │ └─tikv.RPC | 23:54:55.232046 | 1.9473ms |
| │ │ ├─tikv.Wait | 23:54:55.232046 | 17.36µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232046 | 17.36µs |
| │ │ └─tikv.Process | 23:54:55.232063 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231941 | 5.01159ms |
| │ │ └─rpcClient.SendRequest, region ID: 964283, type: Cop | 23:54:55.232053 | 4.85447ms |
| │ │ └─tikv.RPC | 23:54:55.232071 | 2.40527ms |
| │ │ ├─tikv.Wait | 23:54:55.232071 | 14.53µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232071 | 14.53µs |
| │ │ └─tikv.Process | 23:54:55.232086 | 2ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231955 | 13.2467ms |
| │ │ └─rpcClient.SendRequest, region ID: 964291, type: Cop | 23:54:55.232008 | 6.88084ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231966 | 7.72785ms |
| │ │ └─rpcClient.SendRequest, region ID: 964315, type: Cop | 23:54:55.232135 | 7.47004ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.231995 | 10.61205ms |
| │ │ └─rpcClient.SendRequest, region ID: 964337, type: Cop | 23:54:55.232154 | 6.73455ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232010 | 12.70983ms |
| │ │ └─rpcClient.SendRequest, region ID: 964349, type: Cop | 23:54:55.232703 | 5.9264ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232024 | 13.88788ms |
| │ │ └─rpcClient.SendRequest, region ID: 964293, type: Cop | 23:54:55.232570 | 7.11541ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232049 | 7.46638ms |
| │ │ └─rpcClient.SendRequest, region ID: 964307, type: Cop | 23:54:55.232214 | 7.23136ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232055 | 6.01571ms |
| │ │ └─rpcClient.SendRequest, region ID: 964303, type: Cop | 23:54:55.232253 | 5.62391ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232087 | 13.55101ms |
| │ │ └─rpcClient.SendRequest, region ID: 964325, type: Cop | 23:54:55.232254 | 7.03948ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232089 | 5.09668ms |
| │ │ └─rpcClient.SendRequest, region ID: 964295, type: Cop | 23:54:55.232155 | 4.88109ms |
| │ │ └─tikv.RPC | 23:54:55.232167 | 2.02285ms |
| │ │ ├─tikv.Wait | 23:54:55.232167 | 10.52µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232167 | 10.52µs |
| │ │ └─tikv.Process | 23:54:55.232177 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232097 | 8.7529ms |
| │ │ └─rpcClient.SendRequest, region ID: 964301, type: Cop | 23:54:55.232268 | 5.57636ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232129 | 6.17121ms |
| │ │ └─rpcClient.SendRequest, region ID: 964339, type: Cop | 23:54:55.232191 | 5.90357ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232178 | 6.8302ms |
| │ │ └─rpcClient.SendRequest, region ID: 964351, type: Cop | 23:54:55.232239 | 6.63858ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232188 | 14.6379ms |
| │ │ └─rpcClient.SendRequest, region ID: 964311, type: Cop | 23:54:55.232255 | 7.52914ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232195 | 11.18424ms |
| │ │ └─rpcClient.SendRequest, region ID: 964305, type: Cop | 23:54:55.232310 | 5.66393ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232215 | 9.83113ms |
| │ │ └─rpcClient.SendRequest, region ID: 964289, type: Cop | 23:54:55.232266 | 6.34759ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232239 | 10.02104ms |
| │ │ └─rpcClient.SendRequest, region ID: 964400, type: Cop | 23:54:55.232300 | 6.53104ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232254 | 9.84579ms |
| │ │ └─rpcClient.SendRequest, region ID: 964418, type: Cop | 23:54:55.232396 | 6.2592ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232261 | 9.60082ms |
| │ │ └─rpcClient.SendRequest, region ID: 964408, type: Cop | 23:54:55.232634 | 5.71241ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232261 | 7.55027ms |
| │ │ └─rpcClient.SendRequest, region ID: 964428, type: Cop | 23:54:55.232323 | 7.39241ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232265 | 6.50281ms |
| │ │ └─rpcClient.SendRequest, region ID: 964420, type: Cop | 23:54:55.232331 | 6.37169ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232280 | 9.98563ms |
| │ │ └─rpcClient.SendRequest, region ID: 964412, type: Cop | 23:54:55.232336 | 6.32986ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232287 | 4.53721ms |
| │ │ └─rpcClient.SendRequest, region ID: 964287, type: Cop | 23:54:55.232499 | 4.30102ms |
| │ │ └─tikv.RPC | 23:54:55.232518 | 2.20122ms |
| │ │ ├─tikv.Wait | 23:54:55.232518 | 31.12µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232518 | 31.12µs |
| │ │ └─tikv.Process | 23:54:55.232549 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232315 | 6.19772ms |
| │ │ └─rpcClient.SendRequest, region ID: 964353, type: Cop | 23:54:55.232399 | 5.3961ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232315 | 7.51607ms |
| │ │ └─rpcClient.SendRequest, region ID: 964380, type: Cop | 23:54:55.232498 | 6.5253ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232319 | 4.42312ms |
| │ │ ├─rpcClient.SendRequest, region ID: 964313, type: Cop | 23:54:55.232460 | 4.25068ms |
| │ │ │ └─tikv.RPC | 23:54:55.232478 | 2.27901ms |
| │ │ │ ├─tikv.Wait | 23:54:55.232478 | 59.09µs |
| │ │ │ │ └─tikv.GetSnapshot | 23:54:55.232478 | 59.09µs |
| │ │ │ └─tikv.Process | 23:54:55.232537 | 1ms |
| │ │ └─regionRequest.SendReqCtx | 23:54:55.236793 | 7.02682ms |
| │ │ └─rpcClient.SendRequest, region ID: 964313, type: Cop | 23:54:55.236810 | 1.21362ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232350 | 11.42464ms |
| │ │ └─rpcClient.SendRequest, region ID: 964309, type: Cop | 23:54:55.232546 | 5.49655ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232369 | 12.97912ms |
| │ │ └─rpcClient.SendRequest, region ID: 964297, type: Cop | 23:54:55.232416 | 6.66644ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232378 | 11.81762ms |
| │ │ └─rpcClient.SendRequest, region ID: 964369, type: Cop | 23:54:55.232586 | 5.83054ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232382 | 17.89588ms |
| │ │ └─rpcClient.SendRequest, region ID: 964402, type: Cop | 23:54:55.232427 | 17.7514ms |
| │ │ └─tikv.RPC | 23:54:55.232899 | 1.82872ms |
| │ │ ├─tikv.Wait | 23:54:55.232899 | 10.2µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232899 | 10.2µs |
| │ │ └─tikv.Process | 23:54:55.232909 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232393 | 6.11189ms |
| │ │ └─rpcClient.SendRequest, region ID: 964327, type: Cop | 23:54:55.232562 | 5.76965ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232417 | 11.36708ms |
| │ │ └─rpcClient.SendRequest, region ID: 964426, type: Cop | 23:54:55.232461 | 5.57107ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232420 | 16.20652ms |
| │ │ └─rpcClient.SendRequest, region ID: 964390, type: Cop | 23:54:55.232588 | 5.31002ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232422 | 10.82537ms |
| │ │ └─rpcClient.SendRequest, region ID: 964359, type: Cop | 23:54:55.232522 | 7.33133ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232422 | 6.36257ms |
| │ │ └─rpcClient.SendRequest, region ID: 964255, type: Cop | 23:54:55.232599 | 5.95164ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232435 | 11.20974ms |
| │ │ └─rpcClient.SendRequest, region ID: 964347, type: Cop | 23:54:55.232472 | 5.43857ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232466 | 11.72727ms |
| │ │ └─rpcClient.SendRequest, region ID: 964392, type: Cop | 23:54:55.232510 | 5.81671ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232469 | 12.86471ms |
| │ │ └─rpcClient.SendRequest, region ID: 964357, type: Cop | 23:54:55.232693 | 6.18251ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232470 | 9.98683ms |
| │ │ └─rpcClient.SendRequest, region ID: 964317, type: Cop | 23:54:55.232617 | 6.24281ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232476 | 4.77805ms |
| │ │ └─rpcClient.SendRequest, region ID: 964404, type: Cop | 23:54:55.232524 | 4.60959ms |
| │ │ └─tikv.RPC | 23:54:55.232529 | 1.80286ms |
| │ │ ├─tikv.Wait | 23:54:55.232529 | 11.52µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232529 | 11.52µs |
| │ │ └─tikv.Process | 23:54:55.232541 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232480 | 9.43176ms |
| │ │ └─rpcClient.SendRequest, region ID: 964345, type: Cop | 23:54:55.232840 | 5.69076ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232484 | 7.55482ms |
| │ │ └─rpcClient.SendRequest, region ID: 964424, type: Cop | 23:54:55.232563 | 7.37521ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232533 | 9.92558ms |
| │ │ └─rpcClient.SendRequest, region ID: 964323, type: Cop | 23:54:55.232979 | 5.71187ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232535 | 5.6707ms |
| │ │ └─rpcClient.SendRequest, region ID: 964269, type: Cop | 23:54:55.232726 | 5.38099ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232540 | 4.86217ms |
| │ │ └─rpcClient.SendRequest, region ID: 964432, type: Cop | 23:54:55.232592 | 4.57607ms |
| │ │ └─tikv.RPC | 23:54:55.232598 | 1.75471ms |
| │ │ ├─tikv.Wait | 23:54:55.232598 | 11.34µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232598 | 11.34µs |
| │ │ └─tikv.Process | 23:54:55.232610 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232543 | 4.38371ms |
| │ │ └─rpcClient.SendRequest, region ID: 964416, type: Cop | 23:54:55.232935 | 3.41447ms |
| │ │ └─tikv.RPC | 23:54:55.232955 | 2.12261ms |
| │ │ ├─tikv.Wait | 23:54:55.232955 | 21.66µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232955 | 21.66µs |
| │ │ └─tikv.Process | 23:54:55.232976 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232548 | 6.8712ms |
| │ │ └─rpcClient.SendRequest, region ID: 964414, type: Cop | 23:54:55.232876 | 5.98061ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232555 | 11.29216ms |
| │ │ └─rpcClient.SendRequest, region ID: 964321, type: Cop | 23:54:55.232850 | 5.19581ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232578 | 12.80051ms |
| │ │ └─rpcClient.SendRequest, region ID: 964285, type: Cop | 23:54:55.232977 | 6.01475ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232609 | 14.29801ms |
| │ │ └─rpcClient.SendRequest, region ID: 964373, type: Cop | 23:54:55.232658 | 5.00607ms |
| │ │ └─tikv.RPC | 23:54:55.232664 | 1.994ms |
| │ │ ├─tikv.Wait | 23:54:55.232664 | 9.2µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232664 | 9.2µs |
| │ │ └─tikv.Process | 23:54:55.232673 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232626 | 7.33181ms |
| │ │ └─rpcClient.SendRequest, region ID: 964376, type: Cop | 23:54:55.232729 | 7.16279ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232636 | 17.73734ms |
| │ │ └─rpcClient.SendRequest, region ID: 964422, type: Cop | 23:54:55.232696 | 14.58702ms |
| │ │ └─tikv.RPC | 23:54:55.232700 | 1.84931ms |
| │ │ ├─tikv.Wait | 23:54:55.232700 | 9.93µs |
| │ │ │ └─tikv.GetSnapshot | 23:54:55.232700 | 9.93µs |
| │ │ └─tikv.Process | 23:54:55.232709 | 1ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232647 | 7.04831ms |
| │ │ └─rpcClient.SendRequest, region ID: 964434, type: Cop | 23:54:55.232814 | 6.73284ms |
| │ ├─regionRequest.SendReqCtx | 23:54:55.232656 | 9.3814ms |
| │ │ └─rpcClient.SendRequest, region ID: 964261, type: Cop | 23:54:55.232817 | 5.72926ms |
Each rpcClient.SendRequest takes several milliseconds, but the query in total takes 164ms
It means that distsql.Select can't return immediately after the limit 1 condition, when a lot of regions involved, this kind of query takes more time than expected.
distsql.Select | 23:54:55.089979 | 141.69896ms