tidb写入延时过高

看起来手动执行很快,slow_log里面insert into mysql.stats_histograms的操作也有大量慢查询。

那有可能是某一时间段的 duration 较高,集群 TiKV 的机器磁盘 IO wait 是否也出现波动,另外,在 slowlog 出现的方便的话麻烦挑选一个 insert 慢日志较多的时间段(30 min 即可),导出一下具体的监控用作进一步分析。导出方法:
1)使用 chrome 浏览器,安装Full Page Screen Capture插件。

2)展开grafana 监控的 “cluster-name-overview” 的所有 dashboard (先按 d 再按 E 可将所有 Rows 的 Panels 打开,需等待一段时间待页面加载完成)

3)使用插件导出 pdf

screencapture-172-16-116-213-3000-d-eDbRZpnWk-tidb-cluster-overview-2020-03-25-16_32_50.rar (4.1 MB)

  1. 看 overview 的监控有请问这个时间段内的慢的 insert 是否都集中在 15:55 ~ 16:00 这个时间段内。(可以通过 pt-query-digest --since --until 汇总一下看看)
  2. 看网络部分 tcp retrans 也有异常,麻烦也从网络部分也需要排查一下。
  • 慢查询主要是系统表stats_histograms:thinking: pt.txt (19.3 KB)

  • 网络那个应该是当时失误,执行了个select *,有上千万数据

  1. 分析了一下 PT 结果看到 slowlog 里面 stats_histograms 相关的 internal SQL ,存在比较高的 backoff time 有可能是由于失误引起的 select * 导致的 workload 引起的,再观察一下其他时间段,看是否仍然存在,另外也可以通过 slowlog 的 backoff 的输出以及 TiKV 的 backoff 输出结合排查。 \
  2. Insert 的 slowlog ,麻烦重新上传最新的 slowlog 集中的 30 分钟的时间段内的监控,之前的监控被 失误引起的 select * 干扰了。比较难分析结果,麻烦上传一下 这30 分钟内的 slowlog (包含 insert SQL 的), 以及对应的 30 分钟内的 TiDB 、 TiKV detail 的监控。
  • pt

pt.txt (13.3 KB)

  • pdf

https://share.weiyun.com/5SELXi9

可以在 tikv-detail 的监控面板中,查下 scheduler , grpc , coprocessor 相关的监控,来辅助定位当时 duration 升高的原因。

看起来没什么异常

查看集群 Duration 监控,999 耗时在 500ms 左右

获取 tso 存在耗时比较长的情况 从 tikv-detail 看写入的延迟比较低

tso wait duration 比较高这个可以排查一下 pd 节点负载是否比较高 另外可以看下 Binlog 监控中 write binlog latency 的情况,判断一下 binlog 写入是否有影响

下面是当时机器的负载情况,以及binlog的写入情况。

我确认一下目前的问题应该是确定写入慢的原因是吧,与 Binlog 没有关系,因为看之前的回复,一开始延迟高的时候查看配置文件中 Binlog 是没有开启的,后来开启之后集群的 Duration 也没有变化。

标题的开启 binlog 之后,tidb 写入延时变高,指的是部署 pump drainer 之后集群写入延迟才变高的吗?之前的延迟情况是怎么样的?

对,是确认写入慢的原因。这个是前几天重装的,之前用的3.0.9版本,每秒写入4000多,也没这么高的延时。

不好意思回复比较久,因为从监控中似乎没有找出明显的异常点 所以麻烦反馈一下下面两个信息:

  1. 在命令行中执行 insert 语句是否也在 500ms 以上,麻烦用 trace 语法追踪一下 insert 语句的耗时情况
类似这种形式,看下每个阶段的耗时
mysql>  trace format='row' insert into test(name) values('sg');
+-------------------------------------------------------+-----------------+------------+
| operation                                             | startTS         | duration   |
+-------------------------------------------------------+-----------------+------------+
| trace                                                 | 08:56:02.964877 | 8.041739ms |
|   └─session.Execute                                   | 08:56:02.964894 | 8.004243ms |
|     ├─session.ParseSQL                                | 08:56:02.964911 | 37.253µs   |
|     ├─executor.Compile                                | 08:56:02.964998 | 97.466µs   |
|     │ └─session.getTxnFuture                          | 08:56:02.965004 | 3.588µs    |
|     └─session.runStmt                                 | 08:56:02.965143 | 7.723137ms |
|       ├─executor.handleNoDelayExecutor                | 08:56:02.965159 | 411.549µs  |
|       │ └─*executor.InsertExec.Next                   | 08:56:02.965170 | 364.251µs  |
|       │   └─table.AllocBatchAutoIncrementValue        | 08:56:02.965185 | 10.828µs   |
|       └─session.CommitTxn                             | 08:56:02.965590 | 7.22576ms  |
|         └─session.doCommitWitRetry                    | 08:56:02.965594 | 7.21476ms  |
|           └─tikvTxn.Commit                            | 08:56:02.965598 | 7.182527ms |
|             ├─twoPhaseCommitter.prewriteMutations     | 08:56:02.965683 | 4.152947ms |
|             │ └─rpcClient.SendRequest                 | 08:56:02.965706 | 4.099288ms |
|             ├─tikvStore.getTimestampWithRetry         | 08:56:02.969850 | 298.04µs   |
|             └─twoPhaseCommitter.commitMutations       | 08:56:02.970174 | 2.585914ms |
|               └─rpcClient.SendRequest                 | 08:56:02.970198 | 2.526998ms |
+----------------------------
  1. 慢日志中都是 stats_histograms 查询的话,可以考虑关闭 feedback 观察一下集群情况 关闭 feedback 方法:将 feedback-probability 参数设置为 0

trace 速度很快,insert不能格式化为row

这是重启tidb节点之后的情况

单条 trace 性能没有问题,那说明单条插入的性能是可以的,那可以怀疑一下是不是并发引起的问题 之前 3.0.9 版本测试的时候:

  1. 目前版本和 3.0.9 版本单表数据量是一致的吗
  2. 重启之后集群 Duration 有一些下降,是不是因为之前有别的任务运行的影响
  1. 以前数据比现在多,差不多是现在的至少十倍,单表上亿的有很多表,现在最多几千万;

  2. 重启的时候把feedback-probability关闭了

您好: 1. 请问,当前3.1.0-beta的duration 999 大概看起来是250ms多. 请问之前3.0.9的duraiton是多少,还有3.0.9的监控信息吗,麻烦看一下duration信息。如果没有,请问duration 需要达到多少满足要求?

    2.  之前3.0.9有关闭feedback吗,3.0.9和3.1.0的硬件配置一样吗?
    
    3. 如果这个问题需要继续分析,请上传一份有问题时,一小时的完整的overview, tidb,detail-tikv, disk-performance监控信息. 

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

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

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

  1. 关闭feedback之后的延时和之前比较接近,可以接受

  2. 机器都是一样的机器,之前没有改过feedback相关的参数

  3. 这个问题目前来看是feedback引起的,新版本的feedback和以前有很大区别吗?关闭feedback没有问题的话,那这个问题就没必要继续讨论了

  1. feedback的问题,我确认了,应该没有区别.
  2. 你可以尝试打开feedback,观察是否还是会升高,上传监控信息,我们继续排查,多谢