最近有人咨询这么一个问题: 他们提供某个服务, 这个服务的耗时偶尔突然变长. 比如平时这个服务的P99的延迟是800毫秒左右, 而最近这个服务的P99延迟已经接近4秒. 它们自己也做了很多功课, 发现延迟开始增加的大概时间就是他们有新客户接入的时间, 所以他们觉得是请求数量增加导致P99延迟变长. 于是他们去问容量规划团队去加机器, 但是容量规划团队看了他们的CPU使用率也不高, 内存使用量也不高, 拒绝了他们的要求. 他们又去查看变慢请求的具体日志, 发现了某些特征的日志: 有些2行日志中间平时应该很短, 但是一旦出问题, 这二行日志中间会有比平时长的多的时间间隙.

下面是一个具体的例子:

06:48:31.28    /api/query/v1/metrics?responseFormat=FLAT
06:48:34.48    Total Attempt #1 for client MyEventClient for AsyncRetrier

可以看到这2行日志中间隔了3.2秒, 而正常情况下, 这2行的中间通常少于10毫秒.

对于这类问题, 通常有哪些解题思路呢?

问题分析

对于延迟变长的问题, 通常我们会主要考虑下面情况:

1. 服务本身的问题, 比如关键资源的竞争, 锁竞争, JVM 的GC, 新加了大量的耗时逻辑等;
2. 外部依赖延迟变长, 比如依赖的数据库服务器变慢, 依赖的下游服务变慢, 依赖的网络变慢等;

服务本身问题分析

对于服务本身造成的延迟变长, 也有很多情况.

1. 假如说服务本身增加了很多耗时的业务逻辑, 这种延迟会体现在所有的请求上面, 而不是偶尔的某些请求.

2. 假如说是JVM GC 造成的变长, 尤其像这种3秒的延迟, 通常会有更明显的特征:

   1. GC 日志会很好的体现, CPU使用率也会体现.
   2. 凡是经历当时GC的所有请求都会遇到延迟变长的情况.

   而我们看到的实际情况并不符合.

3. 假如说有锁竞争导致延迟变长, 并且会导致延迟3秒, 那么当时着锁竞争应该很激烈, 会体现在CPU上面, 事实并没有体现.
4. 假如其它关键资源的竞争导致延迟变长, 那么应该有另外一个线程拥有这种关键资源, 并且占用了3秒, 但我们并不知道有没有这种情况, 所以暂时无法判断. 但是一般对于一个繁忙的应用服务器, 这种情况不会偶尔发生, 会频繁复现.

所以, 如若服务本身的情况, 大多数都会有其它指标体现出来, 也有些情况比较复杂, 比较难判断.

外部依赖问题

通常对于外部依赖, 我们都有2处度量的点:

1. 在当前服务调用外部服务的点, 这里的延迟包含自己服务IO的调度, 网络延迟, 以及下游真正的延迟.
2. 在下游服务的入口点, 也就是下游服务自己暴露的延迟信息, 这里仅是下游的服务的延迟.

如果对于#2已经可以看到延迟增加, 那么可以初步定位就是下游服务造成的.
如果下游服务延迟没有增加, 反而#1增加了, 那么可能是网络延迟或者服务器本身IO调度的延迟. 如果是网络延迟造成的, 那么通常网络会影响到所有经过这段网络的服务, 也就是不单单是这个服务受到了影响, 而是很多服务会受到影响. 如果是本身IO调度的问题, 那么通常可能跟大多数从这个网络出入的下游服务都会受到影响, 主要考虑跟有症状的下游相近流量的下游服务.

noise neighbor 影响

如今很多服务都是在 container 里面部署的, 一个宿主机可能部署很多container. 尽管当前应用服务器的CPU使用率很低, 但是那个时间点可能遇到相同宿主机的请它container 在大量使用CPU, 导致当前container 虽然CPU使用率很低, 但是它的进程/线程很难拿到CPU的时间片, 导致延迟变长.

但是这种情况要求延迟变长的应用很多都和 noise neighbor 在一块, 导致经常出这种问题.