tidb日志中存在大量的expensive sql 是 use database

🪐 TiDB 技术问题
1

【TiDB 使用环境】生产环境 /测试/ Poc
【TiDB 版本】V6.5.0
【操作系统】/
【部署方式】K8S
1、只有这一个库存在expensive sql并且都是use db，其他库没有出现这种信息，这种该如何排查解决？
2、如果use db算expensive sql，为啥这种expensive sql 没有记录到慢日志中？

相关日志：
[2025/07/14 17:33:09.302 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.039100007s] [conn_id=6307315467399207771] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:12.803 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.536516131s] [conn_id=6307315467399207255] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:17.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.112905885s] [conn_id=6307315467399207695] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:18.503 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=360.340207688s] [conn_id=6307315467399207405] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:21.302 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.128396208s] [conn_id=6307315467399207701] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:23.303 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.198402285s] [conn_id=6307315467399207609] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:29.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.170236878s] [conn_id=6307315467399207619] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:30.202 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.494145184s] [conn_id=6307315467399207279] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:30.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.154000843s] [conn_id=6307315467399207713] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:30.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.328813166s] [conn_id=6307315467399207545] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:33.102 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.142589459s] [conn_id=6307315467399207625] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:33.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.398615022s] [conn_id=6307315467399207549] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:33.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.450880655s] [conn_id=6307315467399207197] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:35.573 +00:00] [INFO] [data_window.go:256] [“Error exists when getting the SQL Metric.”]
[2025/07/14 17:33:36.403 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.131196204s] [conn_id=6307315467399207629] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:41.102 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=420.402428725s] [conn_id=6307315467399207351] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:41.303 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.181331595s] [conn_id=6307315467399207637] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:41.402 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.244489291s] [conn_id=6307315467399207639] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:43.202 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.667703196s] [conn_id=6307315467399207295] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:43.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.480172912s] [conn_id=6307315467399207297] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:44.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.461503671s] [conn_id=6307315467399207303] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:50.202 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.286440855s] [conn_id=6307315467399207567] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:50.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.09770658s] [conn_id=6307315467399207737] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:50.702 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.199732286s] [conn_id=6307315467399207651] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:54.002 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.511230553s] [conn_id=6307315467399207311] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:57.403 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.030659903s] [conn_id=6307315467399207757] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:33:58.902 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.385183269s] [conn_id=6307315467399207505] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:00.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.031901319s] [conn_id=6307315467399207763] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:02.002 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.247279144s] [conn_id=6307315467399207585] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:05.002 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.355420142s] [conn_id=6307315467399207521] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:05.002 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.358046089s] [conn_id=6307315467399207519] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:05.075 +00:00] [INFO] [gc_worker.go:1073] [“[gc worker] start resolve locks”] [uuid=64d995517f4000f] [safePoint=0] [try-resolve-locks-ts=459411068039200814] [concurrency=3]
[2025/07/14 17:34:05.075 +00:00] [INFO] [range_task.go:137] [“range task started”] [name=resolve-locks-runner] [startKey=] [endKey=] [concurrency=3]
[2025/07/14 17:34:05.212 +00:00] [INFO] [range_task.go:243] [“range task finished”] [name=resolve-locks-runner] [startKey=] [endKey=] [“cost time”=136.910995ms] [“completed regions”=721]
[2025/07/14 17:34:05.212 +00:00] [INFO] [gc_worker.go:1095] [“[gc worker] finish resolve locks”] [uuid=64d995517f4000f] [safePoint=0] [try-resolve-locks-ts=459411068039200814] [regions=721]
[2025/07/14 17:34:09.403 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=120.139962522s] [conn_id=6307315467399207771] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:12.903 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.636681608s] [conn_id=6307315467399207255] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:17.702 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.211945776s] [conn_id=6307315467399207695] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:18.503 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=420.340474874s] [conn_id=6307315467399207405] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:21.303 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.128837398s] [conn_id=6307315467399207701] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:23.403 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.298336777s] [conn_id=6307315467399207609] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:29.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.27029309s] [conn_id=6307315467399207619] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:30.302 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.593884407s] [conn_id=6307315467399207279] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:30.702 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.428717024s] [conn_id=6307315467399207545] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:30.703 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.254134172s] [conn_id=6307315467399207713] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:33.103 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.143136842s] [conn_id=6307315467399207625] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:33.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.498770122s] [conn_id=6307315467399207549] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:35.578 +00:00] [INFO] [data_window.go:256] [“Error exists when getting the SQL Metric.”]
[2025/07/14 17:34:36.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.230271527s] [conn_id=6307315467399207629] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:36.902 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.05152938s] [conn_id=6307315467399207865] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:41.103 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=480.402801087s] [conn_id=6307315467399207351] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:41.303 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.181516777s] [conn_id=6307315467399207637] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:41.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.344764599s] [conn_id=6307315467399207639] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:43.602 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.579601989s] [conn_id=6307315467399207297] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:44.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.462350363s] [conn_id=6307315467399207303] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:46.203 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.084191346s] [conn_id=6307315467399207881] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:50.303 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.3868193s] [conn_id=6307315467399207567] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:50.702 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.196880377s] [conn_id=6307315467399207737] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:50.802 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=240.299475334s] [conn_id=6307315467399207651] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:54.002 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=540.511670848s] [conn_id=6307315467399207311] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:34:57.502 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.130162416s] [conn_id=6307315467399207757] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:35:00.603 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=180.032165939s] [conn_id=6307315467399207763] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:35:02.003 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=300.247869836s] [conn_id=6307315467399207585] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]
[2025/07/14 17:35:03.003 +00:00] [WARN] [expensivequery.go:118] [expensive_query] [cost_time=60.024192053s] [conn_id=6307315467399207909] [user=xxxxx] [txn_start_ts=0] [mem_max=“0 Bytes (0 Bytes)”] [sql=“use xxxxx”]

2

:thinking: use 一下用9分钟？网络连接异常么？

3

感觉不是网络问题，看了对应的监控，没发现啥问题，其他库都是好的。
只有这个库日志一直在打印，现在还是一直存在。

1 个赞
4

手工执行use 也要9分钟？

5

手工执行正常的，感觉1s内执行完了。

6

上下文是不是有事务啊？这个use是提交事务的语句

7

我用show processlist查看info显示的是use xxx，而且用digest看也是use xxx。确实是use xxx 执行了很长时间。

8

expensive 记录有两种，一个是 scan key 比较多的。一个是执行时间超过 60s 的。
你们集群是不是 scheme 比较多？导致 use database 的时候加载的慢。
你登录数据库 mysql -A . -A 可以跳过一些加载看看快不快。

9

这个日志的数量特别多，他这个应该是业务代码里的，不是人为执行的。
人为执行的时候，即使不用-A，也是挺快的。

10

这个 sql ，慢日志内容发下，里面应该有 cost time 的分布。

11

这个sql在慢日志中并没有记录

12

不可能吧，除非你是一个事务里面的 sql，慢日志只记录 commit 和上一个 sql。
不然应该不会找不到的。

13

我也觉得奇怪呢。。。
这是现在还在打的日志
企业微信截图_17534115185086
这是是对应节点上的慢日志，并没有慢日志产生
image

14

connect id 看看能不能找到对应时间前后的。

15

Hikari 4.0.3 配置了cacheServerConfiguration=true 会导致该问题。

16

此话题已在最后回复的 7 天后被自动关闭。不再允许新回复。