问题描述

最初出现的时候，是在每天的早上8-10这个时间范围内，服务A上的有一个接口时不时报警，内容不一，有 connect timeout 、 connect reset、connect reject等，其中connect reject比较频繁。在后续观察中，发现tomcat的nio线程一般正常运行下为100以下，但是在异常重启前一个小时内会飙升至1000也就是配置的最大线程数。

问题处理

初步分析

线上部署的服务A有4个pod，每台机器的配置是1g。是springboot项目，tomcat配置如下

server:
  tomcat:
    uri-encoding: UTF-8 
    accept-count: 1000
    max-connections: 2000
    max-threads: 1000
    min-spare-threads: 10
  connection-timeout: 60000

乍一看线程数量有一点多。之后看了一下是不是有问题的接口逻辑，主要交互节点如下

1、接收请求，根据token查缓存获取用户数据
2、feign调用用户服务获取用户信息
3、根据获取的信息查数据库，然后组装结果返回

整体逻辑看着也很简单，feign调用耗时也不是很高。查缓存的话，应该也没有问题，不然就单是一个服务的问题了。那就是查库的问题了，我把执行sql分析了一下，走了索引，表的数据量也不是很大，那是哪一步出问题了。。

http配置即服务整体情况

接口处理时间变长的一种情况是，并发请求太大，导致服务请求处理不过来(如果接口有限流配置那么其实就直接拒掉了，这个服务没有配置)。我在ES上看了一个服务的峰值请求量，秒级不超过一千。异常接口峰值秒级也只有3、4百，分到每台机器上也就100多，1000个线程怎么都处理的过来吧。除非其他接口请求量也大，而且处理时间长，占用了线程。但是我在ES上看了一下接口处理耗时，报警的那一会的确有耗时变长的情况，请求量的确也有所上升。
此外，我看了一个物理机的tcp配置

net.core.somaxcon  // 128
net.ipv4.tcp_max_back_log  // 1000

这两配置有点小了。

此时，我的推测如下：

1、connect timeout 是因为处理请求不过来
2、connect reset 是因为 http全连接半连接池太小，被请求占满导致
3、connect reject 服务不可用

经过灰度测试，发现不明显。connect reject 仍出现。

整体排查

服务重启

connect reject出现的原因，理论上是服务寄了。但是怎么能知道它寄没寄呢。突然想到，这个服务有注册到注册中心，也就是eureka。上去一下，没有下线信息，但是报错那个时间点有上线信息。

在这里插入图片描述

于是，推测那个时间点是不是服务重启了。看了一下线上服务的日志，发现日志归档了，gc信息也归档了。然后看技术上线记录，发现没人手动上线，于是推测是服务自动重启，然后找运维确定了一下，的确有重启记录。容器默认配置3分钟内5次心跳没通过重启。。

gc

gc信息
将运行时的gc日志文件分析后，发现gc很频繁。而且full gc后内存下降不是很明显。但是gc停顿时间最长就1.7秒，不可能3秒内都不可用，所以gc有问题，但可能不是主要问题。

CPU

jvm和cpu使用情况

可以看到，使用情况还是挺高的。具体看进行的CPU情况，发现基本是在100%。

// 看进行下哪个线程使用的cpu比较高
top -Hp 进程id 
// 10进制 转为 16进制
printf '%x\n' 线程id
// 定位线程的信息  d8为上面转换后的16进制
jstack 进程id | grep '0xd8'

jstack信息

这里拍的有点糊哈，最终定位到是 AsyncReporter 190行代码，我这里zipkin版本是2.7.10，对应的就是flush节点。
这里服务配置的是zipkin收集方式是kafka，大小是默认的1000000,可以认为是1M，时间的话配置了60s’.

在这里插入图片描述

然后在线上用arthas看了一下方法运行信息

最后推测出可能是AsyncReporter第265行的问题，因为一直没到配置的最大大小(1M)，导致一直在死循环。

// ByteBoundedQueue#offer   131行
@Override
public boolean offer(S next, int nextSizeInBytes) {
  int x = messageSizeInBytes(nextSizeInBytes);
  int y = maxBytes;
  int includingNextVsMaxBytes = (x < y) ? -1 : ((x == y) ? 0 : 1); // Integer.compare, but JRE 6

  if (includingNextVsMaxBytes > 0) return false; // can't fit the next message into this buffer

  addSpanToBuffer(next, nextSizeInBytes);
  messageSizeInBytes = x;

  if (includingNextVsMaxBytes == 0) bufferFull = true;
  return true;
}
// 这里可以看到，只有刚好填充满，bufferFull才可能等于true
// BoundedAsyncReporter#flush（）  
void flush(BufferNextMessage<S> bundler) {
      if (closed.get()) throw new IllegalStateException("closed");

      pending.drainTo(bundler, bundler.remainingNanos());

      // record after flushing reduces the amount of gauge events vs on doing this on report
      metrics.updateQueuedSpans(pending.count);
      metrics.updateQueuedBytes(pending.sizeInBytes);

      // loop around if we are running, and the bundle isn't full
      // if we are closed, try to send what's pending
      if (!bundler.isReady() && !closed.get()) return;
      
      // ...省略
}      

// 这里的  bundler.isReady() 判断逻辑如下
boolean isReady() {
   return bufferFull || remainingNanos() <= 0;
 }
 // 也就是说，如果时间没到，且没满，那么返回false，此时 flush方法return。这样就开始死循环了，类似while(true)。
 // 如果超时时间比较短，例如默认的1s，那其实也能接受。但是这里我们自己改了默认值，配置了60s，
 // 也就是说在这一分钟内，如果大小刚好卡死，例如当前buffer使用了950kb，下一个100kb，
 // 两者相加不等于1000kb，此时剩余时长都在死循环，CPU自然使用率高了。

修改配置，变为默认值后灰度发布

优化后的代码

这里可以看到，明显降低了，使用率基本在1%左右，原先都是10%以上。。后面去看了一下最新版本实现，发现这个bug已经修复了。

在这里插入图片描述

可以看到，这里大于最大值后也会认为满了，而不是一定要等于最大值。。

JVM

一天堆和非堆使用情况

可以看到，这里的堆使用也不能说有啥大的问题，最多full gc有点多吧，相对而言。但是非堆的话，明显感觉有点问题，理论上来说应该是稳定的。它这里有起伏。

arthas看内存使用情况

后面用arthas执行memory看了一下内存使用情况，发现没设置mataspace的大小。所以理论上来说它可以无限占用物理机内存。图片可以看到，目前已经用了1.9g了，不太合理。
metaspace主要放的是类的信息，所以推测是不是在运行过程中在动态创建类。dump线上的堆栈信息，用visualvm打开。默认是类实例数正向排序的。

默认visualvm打开