Trace client-side and server-side latency to diagnose RPC latency

[sticnarf]

Feature Request

Time spent on RPC has always been the missing part of our metrics. There have been many cases when TiKV reports its process duration is short while the end user experiences high latency.

For example, TiDB has slow query logs and it is common for us to fail to find where the latency comes from. Sometimes, we blame the latency to the network and the RPC framework, without evidence.

If we record the client-side and server-side latency for each request, the client can easily know the time spent on the network and the RPC framework. This will help tease out the possible source of latency and guide us where to optimize. And it is vital to diagnose tail latency shown in slow query logs but not discoverable through metrics.

This can be implemented as part of full process tracing, but it seems #8981 has been inactive for months. But for this feature, a simpler implementation and protocol is enough.

[zhongzc]

But for this feature, a simpler implementation and protocol is enough.

Agreed. We can achieve this by recording more timestamps in the RPC process.

[sticnarf]

I implement it and test a TiDB cluster deployed on a single machine, and find the difference is larger than I expected...

The 99th difference can be up to two-digit milliseconds..

[cfzjywxk]

There are some related discussions in pingcap/tidb#28937.

[BusyJay]

Similar protocols can also be implemented for raft replications.

The latency should be split as send latency and receive latency. The sum is a RTT, and monitor them respectively may find potential pitfalls.

[sticnarf]

The latency should be split as send latency and receive latency. The sum is a RTT, and monitor them respectively may find potential pitfalls.

Single trip latency is more difficult because we will be comparing two instants on different computers. It may depend on the precision of NTP.

[BusyJay]

Time is usually synced. We can find the difference if there are gaps.

[sticnarf]

Time is usually synced. We can find the difference if there are gaps.

I worry the error may mislead us to wrong conclusions.

For example, if the clock of the receiver is 5ms slower (possible in a multi-region deployment) than the sender, we will find the send latency is shorter than the receive latency even if the actual latency is the same.

[BusyJay]

It seems time sync monitor is supported by node exporter, which can be used directly. https://github.com/prometheus/node_exporter/blob/master/docs/TIME.md