TiDB 写入慢流程排查系列(四)— TiKV Server 写入流程

在 TiDB Server 端做完 SQL 的解析,以及冲突检测后,会将相应的请求通过 gRPC 发生给 TiKV 进一步进行事务处理两阶段提交,Raft Log 的发送以及 Apply,以及 RocksDB 的数据存储。

当我们在谈论两阶段提交,我们在谈论什么?

  1. 提交的是什么?

写入的算子 Insert / Update / Delete 在执行过程中对于写入的数据编码为 Key-Value 并先写入事务的 In-Memory Buffer,写入的数据包含两类:

  1. 普通数据插入
  2. 索引数据插入

普通数据和索引数据使用不同的编码方式转换 Key 和 Value,如何将数据编码成对应的 Key-Value 的细节与监控以及原理无关,这一部分可以暂时忽略,统一理解为 Key-Value 即可。

两阶段提交的本质就是将 In-Memory Buffer 中的 Key-Value 通过 tikvclient 写入到 TiKV 中。

  1. 如何提交?

两阶段提交顾名思义就是将事务的提交分成两个阶段:

Prewrite

Commit

在每个 Transaction 开启时会获取一个 TSO 作为 start_ts,在 Prewrite 成功后 Commit 前获取 TSO 作为 commit_ts,如下图:

并且不论是两阶段提交的 prewrite 还是 commit 阶段,都会走相同的 TiKV 写入数据流程:通过 Raft 来确保数据的一致性,以及 RocksDB 来实现数据的持久化。下图为 TiKV 写流程示意图,分别包括了 Scheduler 、Raftstore 以及 RocksDB 等相关内容:

  • gRPC

  • KV 的请求类型
    ➢ Raw KV
    Raw KV 操作包括 raw put、raw get、raw delete、raw batch get、raw batch put、raw batch delete、raw scan 等普通 KV 操作。
    如果是写入操作,没有事务处理部分,会直接调用 async_write 接口发送给底层的 KV 存储引擎。

➢ Txn KV
Txn KV 操作是为了实现事务机制而设计的一系列操作,如 prewrite 和 commit 分别对应于 2PC 中的 prepare 和 commit 阶段的操作。以 prewrite 为例:

Scheduler

统计 Scheduler 内所有写入请求的写入流量

Scheduler 收到 prewrite 请求的时候首先会进行流控判断,如果 Scheduler 里的请求过多,会直接返回 SchedTooBusy 错误,提示等一会再发送,否则进入下一步。

获取内存锁 Latches

在事务模式下,为了防止多个请求同时对同一个 key 进行写操作,请求在写这个 key 之前必须先获取这个 key 的内存锁。每个 Latch 内部包含一个等待队列,没有拿到 latch 的请求按先后顺序插入到等待队列中。

获取 latch 成功之后把 prewrite 请求交给 scheduler worker pool 进行处理。

scheduler worker pool 收到 prewrite 请求之后,主要工作是从拿到的数据库快照里确认当前 prewrite 请求是否能够执行,比如是否已经有更大 ts 的事务已经对数据进行了修改,具体的细节可以参考 TiKV 官方博客 《TiKV 事务模型概览》。当判断 prewrite 是可以执行的,会调用 async_write 接口执行真正的写入操作。

  • async write

async write 包括 raft log 的 propose,append 以及 apply 等关键流程结点。这个部分主要涉及下面的模块:

IO:两个 RocksDB 实例
➢ Raft RocksDB 用于保存 raft 日志
➢ KV RocksDB 用于保存 key-value 数据

CPU:两个线程池(每个线程池默认为两个线程)
➢ raft 线程池
➢ apply 线程池

Network:leader 向 follower 同步日志

async write 具体的流程细节如下:

➢ propose
发送请求给 raftstore

➢ append log
指把 raft log 写入到 raftdb 中。

➢ commit log
➢ apply wait log
Raft log commit 后,会等待 apply ,这里可能会因为资源繁忙而出现等待的情况。

➢ apply log
当资源充足时,此时会 apply 这条 Raft log,而 apply log 是指把用户数据写入到 RocksDB KV。

  • 当 async_write 执行成功或失败之后,会调用 Scheduler 的 release_lock 函数来释放 latch 并且唤醒等待在这些 latch 上的请求继续执行。
1赞

1. 服务器资源使用情况

在开始细分析,哪个环节导致写请求变慢之前,建议首先查看当前集群服务器的负载情况和集群内部的运行情况,在 Overview 监控面板 system info 下,可以看到当前各节点服务器的 Load、CPU 使用情况、磁盘 IO 使用情况、以及网卡流量使用情况,如果上面各指标的使用已经比较繁忙,甚至达到饱和,建议先着重查看导致上述问题的原因,比如:出现较多慢 SQL、其他外部程序占用、业务本身繁忙(需考虑扩容)等,而在 TiDB -> KV Errors 及 TiKV-Detail -> Errors 下的监控指标,则可以查看集群内部运行是否出现异常,如: backoff(内部重试)、Resolve LOCK、Serverisbusy 等问题,如果这些指标出现问题,建议查看官网对应监控项所代表的含义,来优先解决这些问题。

1赞

2. gRPC

tidb-server 通过 gRPC 发送写请求到 tikv 端

2.1 gRPC CPU

gRPC 线程是一个纯 CPU 的线程,不涉及 IO 操作。

  • TiKV-Detail -> Thread CPU -> gRPC poll CPU:表示 每个 TIKV 实例的 gRPC 线程的 CPU 使用率,建议使用率不超过 grpc-concurrency*80% ,如果使用率过高,可以考虑调整 gRPC 线程数量,不然客户端请求会因为处理不及时导致延迟加大,此时 gRPC 会成为瓶颈。

2.2 gRPC message count

在 TiKV Details 的 gRPC 的监控中,写相关的请求主要包含 kv_prewrite / kv_commit / raw_put(仅 Raw KV ) 等可以通过以下监控查看请求的数量、失败数量、延迟等情况:

  • TiKV-Detail -> gRPC -> gRPC message count:每种 gRPC 消息的个数
  • TiKV-Detail -> gRPC -> gRPC message failed:失败的 gRPC 消息的个数
  • TiKV-Detail -> gRPC -> gRPC message duration:gRPC 消息的执行时间,表示请求在 TiKV 端的总耗时(这里主要关心 kv_prewrite / kv_commit 两种类型,写流程虽然也涉及读操作,但分析过程参考:读操作慢分析),通过对比 TiKV 的 gRPC duration 以及 TiDB 中的 KV duration 可以发现潜在的网络问题。
  • TiKV gRPC duration 很短但是 TiDB 的 KV duration 显示很长,说明 TiDB 和 TiKV 之间网络延迟可能很高,或者 TiDB 和 TiKV 之间的网卡带宽打满了:
  • 网络延时


Blackbox_exporter -> Network Status -> Ping latency: 各节点之间网络延迟情况

  • 网络带宽使用情况


Overview -> System info -> Network Traffic: 各节点的网卡流量情况

  • 反之, 如果 TiDB 和 TiKV 的时间能对的上,但是时间比较长,可以进一步查看 Scheduler Duration 慢的原因,gRPC duration 的时间等于 gRPC 线程池将这个请求分发给 Scheduler 模块以及这个命令在 Scheduler 内部执行时间的总和
1赞

3. Scheduler

gRPC 把对应的请求发送给 tikv scheduler 线程池来执行写操作的不同具体动作,如:prewrite、commit 等。在具体执行这些动作时,会先拿到一个 Snapshot,然后根据这个请求的具体类型执行一些具体逻辑,比如读取锁信息,然后将最终要写入的数据写入 Raftstore。Scheduler duration 等于 latch-wait duration + async-snapshot duration + load lock (all keys total) + async-write duration 的时间总和,具体每个部分的耗时情况下面会逐一讲解。

3.1 Scheduler CPU

TiKV Details --> Thread CPU --> Scheduler worker CPU:scheduler worker 线程的 CPU 使用率,通常建议 scheduler CPU 使用率不超过scheduler-worker-pool-size*80%:

  • 一般情况下,该 CPU 在各个 TiKV 节点之间使用是均衡的状态。如果出现某个 TiKV 节点的 CPU 在某个时间点或者一个连续的时间段高于其他 TiKV 节点

先要查看是否有较多的锁冲突导致 CPU 使用较高


TiDB–> KV Errors --> Lock Resolve OPS:锁冲突的数量

否侧,建议按照写热点进行排查,文档参考写热点处理文档

  • 锁冲突严重导致的问题:

  • 如果各节点 scheduler CPU 使用均衡,但负载较高,对应 Scheduler commands 很多,则建议调大参数:scheduler work pool size 参数来增加线程数。不然请求会因为处理不及时导致延迟加大,此时 CPU 会成为瓶颈。

TiKV Details --> Scheduler --> Scheduler stage total:每种命令不同阶段的个数,正常情况下,不会在短时间内出现大量的错误
TiKV Details --> Scheduler --> Scheduler priority commands:不同优先级命令的个数
TiKV Details --> Scheduler --> Scheduler pending commands:每个 TiKV 实例上 pending 命令的个数

3.2 获取 Snapshot

和读取动作一样,在具体进行写操作之前需要先获得一个 snapshot

TiKV-Detail -> Storage -> storage async snapshot duration:获取 snapshot 的时间。如果该时间较长,可以参考读流程 snapshot 获取快照慢,如:查看 raftstore 是否较忙 (raft store CPU) 及各节点网络状况是否良好等进行排查

具体动作分析

这里主要关心 Prewrite / Commit 两种类型,并且由于他们的排查方式一样,统一按照下面方式排查,不在单独赘述


TiKV-Detail -> Scheduler-prewrite/commit -> Scheduler command duration:prewrite/commit 的耗时情况 ,如果上面获取 snapshot 时间及 scheduler CPU 使用没有异常,根据上面的公式,我们需要查看获取 latch 的耗时情况是否正常,以及具体动作的执行情况:


TiKV-Detail -> Scheduler-prewrite/commit -> Scheduler latch wait duration:prewrite/commit latch wait 的耗时情况,通常获取 latch 的时间都很低,如果 latch wait 时间较长,可能原因如下:

  • 多个事务同时对相同的 key 进行写操作导致冲突,这个时候需要等锁。
  • 同时写入到 TiKV 的 key 的个数非常多(比如大并发导数据场景),超过了 latch 的默认值 2048000,这个时候可以调大 latch 来缓解。对应的参数是[storage] scheduler-concurrency。

如果发现 latch wait duration 不高,则需要查看具体 load lock (all keys total) 动作的情况,判断是否出现扫描过多的 tombstone 导致性能下降,如果没有,建议进入下部分 Raftstore 的写入来进一步排查 async-write duration 的耗时情况。

TiKV-Detail -> Scheduler-prewrite -> Scheduler keys read:prewrite 命令读取 key 的个数
TiKV-Detail -> Scheduler-prewrite -> Scheduler keys written:pprewrite 命令写入 key 的个数
TiKV-Detail -> Scheduler-prewrite -> Scheduler scan details:执行 prewrite 命令时,扫描每个 CF 中 key 的详细情况
TiKV-Detail -> Scheduler-prewrite -> Scheduler scan details [lock]:执行 prewrite 命令时,扫描每个 lock CF 中 key 的详细情况
TiKV-Detail -> Scheduler-prewrite -> Scheduler scan details [write]:执行 prewrite 命令时,扫描每个 write CF 中 key 的详细情况
TiKV-Detail -> Scheduler-prewrite -> Scheduler scan details [default]:执行 prewrite 命令时,扫描每个 default CF 中 key 的详细情况

4. Raftstore

上层的请求会发送到 raft 线程池,raft 线程将 raft 日志写入到 Raft RocksDB 并同步给其他 peer,当日志提交之后,apply 线程将数据写入 RocksDB KV,整体流程如下图所示:

4.1 Storage async write duration

async write 包括 raft log 的 propose,append 以及 apply 等关键流程结点。并且 async write 的 duration 的整体耗时是下面 5 个部分的总和:

  • Propose wait duration
  • Append log duration
  • Commit log duration
  • Apply wait duration
  • Apply log duration

TiKV Details --> Storage --> Storage async write duration:表示异步写所花费的时间

4.2 Raft store CPU

raftstore 主要负责 Raft 状态机消息的处理,Region 上读写请求的处理、Raft log 的持久化和复制、Raft 的心跳处理等。


TiKV Details --> Thread CPU --> Raft store CPU:表示 raftstore 线程的 CPU 使用率,通常应低于 80%:

  • 一般情况下,Raft store CPU 在各个 TiKV 节点之间是均衡的状态。如果出现某个 TiKV 节点的 raft CPU 某个时间点或者一个连续的时间段高于其他 TiKV 节点,建议排查热点,文档参考写热点处理文档
  • 如果确认是 Raftstore CPU 达到了瓶颈,那么可以参考『海量 Region 集群调优最佳实践』文档进行相应的处理,根据当前集群环境,调整 raftstore 线程数,或开启静默 region 等。

4.3 Propose wait duration

TiKV Details --> Raft Propose --> Propose wait duration:是从发送请求给 Raftstore,到 Raftstore 真正开始处理请求之间的延迟时间。如果该延迟时间较长:

  • Raftstore 比较繁忙如 Raftstore CPU 利用率比较高
  • TiKV Details --> Thread CPU --> Raft store CPU
  • 处理 append log 比较耗时导致 Raftstore 不能及时处理请求,此时建议查看 TiKV Details --> Raft IO --> Append log duration 监控项的具体情况
  • raftstore batch 过小,也可能出现消息堆积导致线程消费过慢的现象,参数为 raftstore.store-max-batch-size ,如果 TiKV Details --> RocksDB raft --> Bytes / Write 显示的流量较低,并且 TiKV Details --> Thread CPU --> Raft store CPU不高,可尝试调大后观察 propose wait duration 是否缓解:
  • TiKV Details --> Raft Propose --> Propose wait duration pre server:表示每个 TiKV 节点 propose 的等待耗时。

4.4 Append log duration


TiKV Details --> Raft IO --> Append log duration:表示 Raft append 日志所花费的时间,写 raft log 的耗时。如果延时比较高,建议进一步排查 Raft RocksDB 慢的问题,文档参考RocksDB 写入流程

TiKV Details --> Raft IO --> Append log duration per server:每个 TiKV 实例上 Raft append 日志所花费的时间。

4.5 Async apply CPU

TiKV Details --> Thread CPU --> Async apply CPU:表示 async apply 线程的 CPU 使用率,通常应低于 90%

4.6 Commit log duration

TiKV Details --> Raft IO --> Commit log duration:Raft commit 日志所花费的时间。

  • 一般情况下如果在总的 async write duration 耗时中,commit log duration 耗时占比最高,那么可能是触发了 Raft 流控。
  • 每个 Region 对应一个独立的 Raft group,Raft 本身是有流控机制的,类似 TCP 的滑动窗口机制,通过参数
    raftstore.raft-max-inflight-msgs = 256 来控制滑动窗口的大小,如果 commit log duration 比较高可以适度调大该参数,比如 1024。

TiKV Details --> Raft IO --> Commit log duration per server:每个 TiKV 实例上 Raft commit 日志所花费的时间。

4.7 Apply wait duration

TiKV Details --> Raft Propose --> Apply wait duration:committed raft log 发送给 apply 线程到 apply 线程真正 apply 这些 log 之间的延迟。
如果该延迟比较高说明 apply 线程比较繁忙,建议排查下面的内容:

  • apply CPU 使用情况
    TiKV Details --> Thread CPU --> Async apply CPU

  • apply batch 过小,也可能出现消息堆积导致 apply 线程消费过慢的问题,对应参数为 raftstore.apply-max-batch-size ,如果 TiKV Details --> RocksDB kv --> Bytes / Write 显示的流量较低,并且 TiKV Details --> Thread CPU --> Async apply CPU 使用率也比较低,但是 apply wait duration 比较高,可尝试调大后观察 apply wait duration 是否缓解:

  • 磁盘负载导致
    Disk - Performance --> Disk Latency --> write latency ( 该 metrics 默认隐藏,需要显示后查看 )
    Disk - Performance --> Disk Bandwidth
    Disk - Performance --> Disk Load

store-pool-size 配置过大,也可能出现消息堆积导致 apply 线程消费过慢的问题。如果配置了 store-pool-size 较大值,apply pool 使用默认值,从 store pool 产生待 apply 任务速度较快,在 apply pool 侧容易堆积较多,增加了 apply 的延时。可尝试调大 apply-pool-size 。可根据以下监控判断:


TiKV Details --> Raft Propose --> Apply wait duration per server:表示每个 TiKV 节点 apply wait 的耗时。

4.8 Apply log duration

TiKV Details --> Raft IO --> Apply log duration:Raft apply 日志所花费的时间,执行 raft log ,把用户数据写入到 RocksDB KV 的耗时。
TiKV Details --> Raft IO --> Apply log duration per server:每个 TiKV 实例上 Raft apply 日志所花费的时间。

1赞

5. 其他原因

5.1 PD 调度

由于读写请求都是根据 Region 来进行的,所以集群内部的各种调度,也会对读写请求的延迟有影响。可以从两方面进行确认,如果调度的数量较多,可以通过修改调度相关的参数 store-limit 来限制对集群使用的影响。另外,调度 Region 后,可能会触发 RocksDB kv 进行 compaction ,compaction 会对集群的性能产生一定的影响,具体见 Compation 流程

5.1.1 PD Metrics

Operator

PD --> Operator --> Schedule operator create:新创建的不同 operator 的数量,单位 opm 代表一分钟内创建的个数
PD --> Operator --> Schedule operator check:已检查的 operator 的次数,主要检查是否当前步骤已经执行完成,如果是,则执行下一个步骤
PD --> Operator --> Schedule operator finish:已完成调度的 operator 的数量
PD --> Operator --> Schedule operator timeout:已超时的 operator 的数量
PD --> Operator --> Schedule operator replaced or canceled:已取消或者被替换的 operator 的数量
PD --> Operator --> Schedule operators count by state:不同状态的 operator 的数量
PD --> Operator --> Operator finish duration:已完成的 operator 所花费的最长时间
PD --> Operator --> Operator step duration:已完成的 operator 的步骤所花费的最长时间

Statistics-balance

PD --> Statistics-balance --> Store leader score:每个 store 上面的 leader 分数
PD --> Statistics-balance --> Store region size:每个 store 上面的 region 大小
PD --> Statistics-balance --> Store leader size:每个 store 上面的 leader 大小
PD --> Statistics-balance --> Store region count:每个 store 上面的 region 数量
PD --> Statistics-balance --> Store leader score:每个 store 上面的 leader 数量

5.2 TiKV Details Metrics

5.2.1 Snapshot

Region 在调度时,会先获取这个 Region 的 Snapshot ,然后将这个 Region 调度到目标 Store 。在生成 Snapshot 时,也会扫描 TiKV。如果调度非常频繁,那么在 Snapshot 面板中会看到持续不断的生成 Snapshot 的操作,并且会不断的对 TiKV 造成压力,从而影响集群性能:

TiKV Details --> Snapshot --> Rate snapshot message:发送 Raft snapshot 消息的速率
TiKV Details --> Snapshot --> 99% Handle snapshot duration:99% 的情况下,处理 snapshot 所需花费的时间
TiKV Details --> Snapshot --> Snapshot state count:不同状态的 snapshot 的个数
TiKV Details --> Snapshot --> 99.99% Snapshot size:99.99% 的 snapshot 的大
TiKV Details --> Snapshot --> 99.99% Snapshot KV count:99.99% 的 snapshot 包含的 key 的个数

5.2.2 RocksDB KV

调度 Region 后,生成的 Snapshot 会使用 Ingest SST 的方式快速的将数据写入到 RocksDB 中,在 Ingest SST 时,整个集群会阻塞写入。相关监控如下:


TiKV Details --> RocksDB kv --> Ingest SST duration seconds : ingest SST 所花费的时间。当该监控项出现连续的 Ingest SST ,并且耗时较长时,也会影响整个集群的写入性能。

1赞

Mark

1赞