Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.Original topic: 第 1 次读取缓存表数据后，TiDB 未将数据缓存到内存中
|
username: OnTheRoad
[TiDB Usage Environment] Test
[TiDB Version] 6.1.0
[Encountered Issues]
- After the first SELECT read of the cached table data, TiDB did not cache it in memory.
- Executing the trace command 4 times consecutively did not read data from the cache. Only on the 5th execution did it read data from the cache.
- Multiple executions of explain analyze to view the execution plan returned inconsistent execute info content in the execution plan.
[Reproduction Path]
For convenience, the reproduction path has been converted to HTML format: cachetable.html (97.8 KB) cachetable.html
mysql> CREATE TABLE T_SYS_ORG( id bigint, org_code varchar(30), org_name varchar(64), PRIMARY KEY(id) );
Query OK, 0 rows affected (0.54 sec)
mysql> INSERT INTO T_SYS_ORG(id, org_code, org_name) VALUES( 1, 'D1001', '研发一部' );
Query OK, 1 row affected (0.01 sec)
mysql> ALTER TABLE t_sys_org cache;
Query OK, 0 rows affected (0.52 sec)
mysql> SHOW CREATE TABLE t_sys_org\G
*************************** 1. row ***************************
Table: T_SYS_ORG
Create Table: CREATE TABLE `T_SYS_ORG` (
`id` bigint(20) NOT NULL,
`org_code` varchar(30) DEFAULT NULL,
`org_name` varchar(64) DEFAULT NULL,
PRIMARY KEY (`id`) /*T![clustered_index] CLUSTERED */
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin /* CACHED ON */
1 row in set (0.00 sec)
## First read of cached table data
mysql> SELECT * FROM t_sys_org;
+----+----------+--------------+
| id | org_code | org_name |
+----+----------+--------------+
| 1 | D1001 | 研发一部 |
+----+----------+--------------+
1 row in set (0.00 sec)
## The first trace result contains the regionRequest.SendReqCtx operator, indicating that the data was read from TiKV and not from the cache.
mysql> trace SELECT * FROM t_sys_org;
+----------------------------------------------------------------------------+-----------------+------------+
| operation | startTS | duration |
+----------------------------------------------------------------------------+-----------------+------------+
| trace | 12:06:40.131338 | 1.515082ms |
| ├─session.ExecuteStmt | 12:06:40.131342 | 648.603µs |
| │ ├─executor.Compile | 12:06:40.131349 | 127.18µs |
| │ └─session.runStmt | 12:06:40.131490 | 484.829µs |
| │ └─UnionScanExec.Open | 12:06:40.131878 | 79.064µs |
| │ ├─TableReaderExecutor.Open | 12:06:40.131880 | 40.363µs |
| │ │ └─distsql.Select | 12:06:40.131895 | 16.678µs |
| │ │ └─regionRequest.SendReqCtx | 12:06:40.132034 | 721.713µs |
| │ │ └─rpcClient.SendRequest, region ID: 19009, type: Cop | 12:06:40.132046 | 576.483µs |
| │ ├─buildMemTableReader | 12:06:40.131925 | 1.742µs |
| │ └─memTableReader.getMemRows | 12:06:40.131947 | 4.309µs |
| ├─*executor.UnionScanExec.Next | 12:06:40.131998 | 827.082µs |
| │ ├─*executor.TableReaderExecutor.Next | 12:06:40.132000 | 797.723µs |
| │ └─*executor.TableReaderExecutor.Next | 12:06:40.132811 | 5.153µs |
| └─*executor.UnionScanExec.Next | 12:06:40.132830 | 10.332µs |
| └─*executor.TableReaderExecutor.Next | 12:06:40.132832 | 3.03µs |
+----------------------------------------------------------------------------+-----------------+------------+
16 rows in set (0.00 sec)
## Second trace execution
mysql> trace SELECT * FROM t_sys_org;
+----------------------------------------------------------------------------+-----------------+------------+
| operation | startTS | duration |
+----------------------------------------------------------------------------+-----------------+------------+
| trace | 12:14:05.486711 | 2.728361ms |
| ├─session.ExecuteStmt | 12:14:05.486715 | 614.474µs |
| │ ├─executor.Compile | 12:14:05.486722 | 180.01µs |
| │ └─session.runStmt | 12:14:05.486920 | 394.645µs |
| │ └─UnionScanExec.Open | 12:14:05.487239 | 57.358µs |
| │ ├─TableReaderExecutor.Open | 12:14:05.487241 | 36.868µs |
| │ │ └─distsql.Select | 12:14:05.487253 | 15.823µs |
| │ │ └─regionRequest.SendReqCtx | 12:14:05.487371 | 1.981447ms |
| │ │ └─rpcClient.SendRequest, region ID: 19009, type: Cop | 12:14:05.487382 | 1.935303ms |
| │ ├─buildMemTableReader | 12:14:05.487283 | 1.932µs |
| │ └─memTableReader.getMemRows | 12:14:05.487288 | 3.539µs |
| ├─*executor.UnionScanExec.Next | 12:14:05.487336 | 2.075412ms |
| │ ├─*executor.TableReaderExecutor.Next | 12:14:05.487338 | 2.049476ms |
| │ └─*executor.TableReaderExecutor.Next | 12:14:05.489400 | 6.178µs |
| └─*executor.UnionScanExec.Next | 12:14:05.489416 | 10.28µs |
| └─*executor.TableReaderExecutor.Next | 12:14:05.489417 | 3.147µs |
+----------------------------------------------------------------------------+-----------------+------------+
16 rows in set (0.00 sec)
## Third trace execution
mysql> trace SELECT * FROM t_sys_org;
+----------------------------------------------------------------------------+-----------------+------------+
| operation | startTS | duration |
+----------------------------------------------------------------------------+-----------------+------------+
| trace | 12:14:12.895781 | 1.749038ms |
| ├─session.ExecuteStmt | 12:14:12.895784 | 648.19µs |
| │ ├─executor.Compile | 12:14:12.895791 | 159.061µs |
| │ └─session.runStmt | 12:14:12.895963 | 454.642µs |
| │ └─UnionScanExec.Open | 12:14:12.896338 | 60.14µs |
| │ ├─TableReaderExecutor.Open | 12:14:12.896339 | 35.242µs |
| │ │ └─distsql.Select | 12:14:12.896351 | 14.927µs |
| │ │ └─regionRequest.SendReqCtx | 12:14:12.896479 | 954.026µs |
| │ │ └─rpcClient.SendRequest, region ID: 19009, type: Cop | 12:14:12.896491 | 907.385µs |
| │ ├─buildMemTableReader | 12:14:12.896380 | 2.753µs |
| │ └─memTableReader.getMemRows | 12:14:12.896388 | 3.683µs |
| ├─*executor.UnionScanExec.Next | 12:14:12.896438 | 1.062756ms |
| │ ├─*executor.TableReaderExecutor.Next | 12:14:12.896441 | 1.034751ms |
| │ └─*executor.TableReaderExecutor.Next | 12:14:12.897490 | 6.041µs |
| └─*executor.UnionScanExec.Next | 12:14:12.897507 | 9.381µs |
| └─*executor.TableReaderExecutor.Next | 12:14:12.897509 | 2.438µs |
+----------------------------------------------------------------------------+-----------------+------------+
16 rows in set (0.00 sec)
## First execution plan view
mysql> explain analyze select * from t_sys_org;
+-------------------------+---------+---------+-----------+-----------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+---------+---------+-----------+-----------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| UnionScan_5 | 1.00 | 1 | root | | time:686.3µs, loops:2 | | N/A | N/A |
| └─TableReader_7 | 1.00 | 1 | root | | time:676.4µs, loops:3, cop_task: {num: 1, max: 611.1µs, proc_keys: 1, rpc_num: 1, rpc_time: 584.6µs, copr_cache_hit_ratio: 0.00} | data:TableFullScan_6 | 268 Bytes | N/A |
| └─TableFullScan_6 | 1.00 | 1 | cop[tikv] | table:T_SYS_ORG | tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 1, total_process_keys_size: 56, total_keys: 2, rocksdb: {delete_skipped_count: 0, key_skipped_count: 1, block: {cache_hit_count: 0, read_count: 0, read_byte: 0 Bytes}}} | keep order:false, stats:pseudo | N/A | N/A |
+-------------------------+---------+---------+-----------+-----------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
3 rows in set (0.00 sec)
## Second execution plan view
mysql> explain analyze select * from t_sys_org;
+-------------------------+---------+---------+-----------+-----------------+-----------------------+--------------------------------+---------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+---------+---------+-----------+-----------------+-----------------------+--------------------------------+---------+------+
| UnionScan_5 | 1.00 | 1 | root | | time:2.52µs, loops:2 | | N/A | N/A |
| └─TableReader_7 | 1.00 | 0 | root | | time:0s, loops:0 | data:TableFullScan_6 | 0 Bytes | N/A |
| └─TableFullScan_6 | 1.00 | 0 | cop[tikv] | table:T_SYS_ORG | | keep order:false, stats:pseudo | N/A | N/A |
+-------------------------+---------+---------+-----------+-----------------+-----------------------+--------------------------------+---------+------+
3 rows in set (0.00 sec)
## Fourth trace execution
mysql>
mysql> trace SELECT * FROM t_sys_org;
+----------------------------------------------------------------------------+-----------------+------------+
| operation | startTS | duration |
+----------------------------------------------------------------------------+-----------------+------------+
| trace | 12:15:57.396589 | 2.234831ms |
| ├─session.ExecuteStmt | 12:15:57.396594 | 639.665µs |
| │ ├─executor.Compile | 12:15:57.396623 | 296.78µs |
| │ └─session.runStmt | 12:15:57.396937 | 280.857µs |
| │ └─UnionScanExec.Open | 12:15:57.397076 | 119.855µs |
| │ ├─TableReaderExecutor.Open | 12:15:57.397104 | 62.506µs |
| │ │ └─distsql.Select | 12:15:57.397118 | 39.292µs |
| │ │ └─regionRequest.SendReqCtx | 12:15:57.397262 | 1.463508ms |
| │ │ └─rpcClient.SendRequest, region ID: 19009, type: Cop | 12:15:57.397276 | 1.386946ms |
| │ ├─buildMemTableReader | 12:15:57.397174 | 3.641µs |
| │ └─memTableReader.getMemRows | 12:15:57.397183 | 5.128µs |
| ├─*executor.UnionScanExec.Next | 12:15:57.397241 | 1.550612ms |
| │ ├─*executor.TableReaderExecutor.Next | 12:15:57.397244 | 1.519639ms |
| │ └─*executor.TableReaderExecutor.Next | 12:15:57.398780 | 6.189µs |
| └─*executor.UnionScanExec.Next | 12:15:57.398797 | 12.082µs |
| └─*executor.TableReaderExecutor.Next | 12:15:57.398799 | 3.88µs |
+----------------------------------------------------------------------------+-----------------+------------+
16 rows in set (0.00 sec)
## Fifth trace execution
mysql> trace SELECT * FROM t_sys_org;
+-------------------------------------------+-----------------+------------+
| operation | startTS | duration |
+-------------------------------------------+-----------------+------------+
| trace | 12:15:58.664117 | 628.856µs |
| ├─session.ExecuteStmt | 12:15:58.664121 | 597.222µs |
| │ ├─executor.Compile | 12:15:58.664131 | 135.55µs |
| │ └─session.runStmt | 12:15:58.664284 | 421.125µs |
| │ └─UnionScanExec.Open | 12:15:58.664644 | 43.4µs |
| │ ├─TableReaderExecutor.Open | 12:15:58.664646 | 10.568µs |
| │ ├─buildMemTableReader | 12:15:58.664665 | 2.778µs |
| │ └─memTableReader.getMemRows | 12:15:58.664673 | 9.969µs |
| ├─*executor.UnionScanExec.Next | 12:15:58.664724 | 2.125µs |
| └─*executor.UnionScanExec.Next | 12:15:58.664730 | 692ns |
+-------------------------------------------+-----------------+------------+
10 rows in set (0.00 sec)
# Third execution plan view
mysql> explain analyze select * from t_sys_org;
+-------------------------+---------+---------+-----------+-----------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
+-------------------------+---------+---------+-----------+-----------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+
| UnionScan_5 | 1.00 | 1 | root | | time:996.6µs, loops:2 | | N/A | N/A |
| └─TableReader_7 | 1.00 | 1 | root | | time:968µs, loops:3, cop_task: {num: 1, max: 882.8µs, proc_keys: 1, rpc_num: 1, rpc_time: 848.3µs, copr_cache_hit_ratio: 0.00} | data:TableFullScan_6 | 268 Bytes | N/A |
| └─TableFullScan_6 | 1.00 | 1 | cop[tikv] | table:T_SYS_ORG | tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 1, total_process_keys
|
username: