analyze大表性能损耗问题

  • 【TiDB 版本】:v3.0.7
  • 【问题描述】:手工收集一个近两亿大表时,集群慢查询飙升,query监控如下
    image

当时第一反应是有慢查询导致性能降低,于是每个节点看了下日志,搜索expensive_query关键词,日志如下
[root@host-tidb-pdtidb001 log]# grep ‘2020/09/02 23:3’ tidb-2020-09-02T23-50-50.494.log|grep expensive_query|more

[2020/09/02 23:36:01.294 +08:00] [WARN] [expensivequery.go:160] [expensive_query] [cost_time=60.012666892s] [conn_id=574
59702] [user=root] [database=user_collect] [txn_start_ts=0] [mem_max="0 Bytes"] [sql="analyze table collect"]
[2020/09/02 23:36:50.195 +08:00] [WARN] [expensivequery.go:160] [expensive_query] [cost_time=60.051810188s] [process_tim
e=2.287s] [wait_time=2.287s] [request_count=62] [total_keys=1352301] [process_keys=1352236] [num_cop_tasks=62] [process_
avg_time=0.036887096s] [process_p90_time=0.038s] [process_max_time=0.548s] [process_max_addr=10.74.131.85:20160] [wait_a
vg_time=4.304677419s] [wait_p90_time=14.318s] [wait_max_time=27.412s] [wait_max_addr=10.74.131.84:20160] [stats=collect:
419184232880668679] [conn_id=57456355] [user=user] [database=user_collect] [table_ids="[5036]"] [index_ids="[co
llect:created_time]"] [txn_start_ts=419184233706422303] [mem_max="76.95711612701416 MB"] [sql="SELECT COUNT(*) AS `numro
ws`\

FROM collect
WHERE key = ‘8290068’
AND type = ‘gzuser’
AND status = 1
AND created_time > ‘1598706113’
"]
发现23:36:01触发analyze table,23:36:50时三个tidb节点同一秒开始堆积大量慢查询,都是wait_time比较久,且sql语句都是同一类型,只是value不同,问题时段我有确认过
SELECT COUNT(*) AS numrowsFROMcollectWHEREkey= '8290068' ANDtype= 'gzuser' ANDstatus= 1 ANDcreated_time > '1598706113'的执行计划是没有问题的


因此排除了业务sql大量扫表导致集群性能降低

那么对于这种大表的统计信息收集,有什么方案可以避免再出现类似情况呢

您好,能否麻烦您反馈下监控信息,over-view,tidb ,detail-tikv,我们先检查下,多谢。

(1)、chrome 安装这个插件https://chrome.google.com/webstore/detail/full-page-screen-capture/fdpohaocaechififmbbbbbknoalclacl

(2)、鼠标焦点置于 Dashboard 上,按 ?可显示所有快捷键,先按 d 再按 E 可将所有 Rows 的 Panels 打开,需等待一段时间待页面加载完成。

(3)、使用这个 full-page-screen-capture 插件进行截屏保存

见附件,附件太大,只能拆分多个
tidb监控截图.zip (6.9 MB)
overview监控截图.zip (3.6 MB)
screencapture-d-RDVQiEzZz-tidb-cluster1-tikv-details-2020-09-03-14_48_48.png.zip (6.2 MB)
screencapture-d-RDVQiEzZz-tidb-cluster1-tikv-details-2020-09-03-14_48_48-2.png.zip (5.7 MB)
screencapture-d-RDVQiEzZz-tidb-cluster1-tikv-details-2020-09-03-14_48_48-3.png.zip (4.8 MB)

顺便说下,这个集群配置了最大超时时间10s,但昨晚出问题时,我执行 select * from INFORMATION_SCHEMA.PROCESSLIST where TIME > 30 and info != 'NULL' ;
查看执行超过30s的sql,发现我上面发的类似 SELECT COUNT(*) AS numrows FROM
collect WHERE key = '8290068' AND type = 'gzuser' AND status = 1 AND created_time > '1598706113'
这种sql每个节点都堆积了几百条

  1. 查看 over-view 监控 , coprocessor cpu 达到1500%,时间也达到分钟级别


  2. 可以看到整体资源有些主机 cpu 也达到了 100%

  3. 查看 tidb duration

  4. 查看 grpc duration

  5. 查看 analyze table 慢日志中扫描了 1352236 keys.

恩,比较担心下次analyze table时还是出现这种情况,该如何避免呢

analyze table 可以在业务低峰的时候搞,比如后半夜 3-4 点

排查这个问题建议分析一下 slow query,注意慢查询的 plan 是否有什么变化。
像这种情况很有可能是由于 plan 变化了,导致的大量的扫描数据
analyze 操作本身不应该产生这么大的影响,analyze 造成 plan 变化或者 plan 自身变化可能性更大

有分析慢sql的,上面有提到,而且出问题当时我也看了explain,也是正常的

您好 可以参考下这部分文档
https://docs.pingcap.com/zh/tidb/v3.0/statistics#控制-analyze-并发度
进行合适的调整.
并且可以根据 SHOW STATS_HEALTHY 检查分数接近 60 或已低于 60 的 表,选择业务低峰期统一进行手动的 analyze table 操作.
也可调整自动收集统计信息的时间窗口,避免非预期的统计信息收集

计划是没有问题,但是 index scan 扫描的行数也不好说。从你贴的慢日志来看,[total_keys=1352301] [process_keys=1352236] 也是扫了 135 万,跟一次 analyze 差不多。