Performance Diagnosis Enhancements

[sticnarf]

TiKV users and developers often care about performance, but it is never easy to diagnose performance issues or find performance bottlenecks.

• Latency of some parts in the critical path is not recorded, sometimes making the cause of performance issues only inferred indirectly.
• Metrics displayed in the Grafana dashboard are not very well organized. It's not easy to find the cause quickly.
• It's hard to investigate the cause of an individual slow request if the overall latency is normal.

To improve the situation, we need to fill up the missing parts of the metrics, add more details to the metrics and try to improve the way we display the metrics. And, it's better to collect performance data in the request level and send back to the client if possible, enabling analyzing tail latency causes.

Data to be collected

Below are the missing data we are going to collect. "(R)" means the data may be collected for each request, and "(M)" means they are collected as metrics.

Read

• (R) Whether async_snapshot is completed by the local reader
• (R) async_snapshot propose wait duration
• (R) async_snapshot read index wait duration
• (RM) RocksDB GetSnapshot duration
• (R) RocksDB seek count, total seek duration, max seek duration
• (R) RocksDB block read duration
• (RM) RocksDB DB mutex wait duration
• (RM) Read pool scheduling wait duration
• (RM) Read pool queue length
• (R) Priority in the read pool
• (RM) Semaphore wait duration
• (RM) Semaphore wait queue length
• (RM) Task yield count, total yield duration

Write

• (RM) Latch wait queue length
• (R) Latch wait time
• (RM) Scheduler pool wait duration
• (RM) Scheduler pool wait queue length
• (R) Scheduler flow control throttle duration
• (R) Scheduler flow control throttle reason
• (R) Request async_write duration
• (R) Request propose wait duration
• (RM) Store loop queue length
• (RM) Store loop queue wait rounds
• (R) Store loop batch size
• (R) Store loop batch write size
• (R) Write Raft log duration (including RocksDB details)
• (RM) Raft flow control duration
• (RM) Inter-TiKV RPC latency
• (R) Apply wait duration
• (R) Read entry cache duration (if happens)
• (RM) Apply loop queue length
• (RM) Apply loop wait rounds
• (R) Write KV RocksDB duration (including RocksDB details)

Background jobs

• (M) Backup I/O usage
• (M) Backup network bandwidth usage
• (M) Generating snapshot I/O usage #12838
• (M) Sending snapshot network bandwidth usage

Internal jobs from TiDB (ref pingcap/tidb#33963)

• (M) TiDB auto-analyze CPU and I/O usage
• (M) TiDB DDL reorganization (add index/change column) CPU and I/O usage, raftstore commands ratio
• (M) Checksum CPU and I/O usage

Diagnosis helper

The performance overview dashboard displays performance critical metrics. Some representitive newly added metrics can be put on the same dashboard as well.

Smart diagnosis service may use the metrics as input and generate reports about possible cause of the problem. But this is not in the TiKV project plan AFAIK.

Existing related issues

The following issues were created before, they may be some sub-tasks of this meta-issue. We hope this issue will cover most of the problems raised by the following issues.

• Scheduler: There's no conclusive way to determine the wait time of a request for scheduler worker #12359 (Missing scheduler wait duration)
• Roadmap for stage latency statistics #11525
• Output slow log for KvGet and KvBatchGet #8944 (We need to furthur consider how and where to output TiKV slow log)
• Trace client-side and server-side latency to diagnose RPC latency #11378 (Mentioning something about network latency)
• Implement tracing for TiKV #11872 (Tracing provides more detailed per-request time data, but is more complex and expensive)
• metrics: Accurate duration tracing of storage/scheduler message handling #8403 (The PR description lists some inaccuracy and missing parts of the metrics)

[sticnarf]

@OneSizeFitsQuorum Are you interested in the time breakdown inside async_snapshot? It may be useful to collect whether lease is expired and record the raft store loop wait duration if lease is expired.

[OneSizeFitsQuorum]

Yes, I can practice on it first. But I’m curious about what is Apply loop Queue Length and Apply loop wait rounds, will them be helpful for us to monitor the the applying status? If so it maybe useful for parallel apply demo too.

[sticnarf]

Yes, I can practice on it first. But I’m curious about what is Apply loop Queue Length and Apply loop wait rounds, will them be helpful for us to monitor the the applying status? If so it maybe useful for parallel apply demo too.

I was thinking Apply loop Queue Length as the total number of commands that is pending to be applied at the time when a new command is committed and sent to the apply threads. And meanwhile, we can record the value of the current "apply round" counter. The counter increases for each apply batch. So, we can know how many rounds of batches have passed before we are able to handle the command in the apply thread.

Probably they are helpful to account for the long apply wait time while the apply threads are vacant. But I am also a bit worried that these metrics are too tedious in most cases. (Maybe we can define levels for metrics too.)