Tomcat7压测(2)

  • Tuesday, Feb 14, 2017

目的

  • 本篇将请求的耗时调大，主要为了观察线程池及等待队列都满了的情况下，Tomcat的表现及反应。

初步压测描述

先描述下一开始进行这部分压测遇到的问题。首先根据Tomcat7官方文档描述：

Each incoming request requires a thread for the duration of that request. If more simultaneous requests are received than can be handled by the currently available request processing threads, additional threads will be created up to the configured maximum (the value of the maxThreads attribute). If still more simultaneous requests are received, they are stacked up inside the server socket created by the Connector, up to the configured maximum (the value of the acceptCount attribute). Any further simultaneous requests will receive “connection refused” errors, until resources are available to process them.

预期服务端同一时刻可以接受的请求数量应该是maxThread+accptCount。但当将Tomcat参数调整为maxThread=1和acceptCount=2时，通过netstat -nat查看客户端与服务端建立的TCP连接数量，状态为ESTABLISHED的有4条（预期应该是2+1=3条），再仔细查看发现其中只有一条的Recv-Q为0，说明只有这条正在处理，其他3条请求都堆积了。

通过修改maxThread和acceptCount参数发现，状态为ESTABLISHED的TCP连接中，Recv-Q为0的条数与maxThread相等（符合预期，说明这几个TCP连接所发送的请求正被服务处理），而Recv-Q不为0的数目总等于acceptCount+1。进而查看Tomcat源码，发现：

static {
        replacements.put("acceptCount", "backlog");
        replacements.put("connectionLinger", "soLinger");
        replacements.put("connectionTimeout", "soTimeout");
        replacements.put("rootFile", "rootfile");
    }

所以acceptCount只是映射为Socket的backlog参数，由此来控制TCP底层连接队列的数量。在tomcat-connector的微调(1): acceptCount参数这篇博客得到验证。 进而了解了backlog参数的相关资料。

linux诡异的半连接(SYN_RECV)队列长度(一)

linux诡异的半连接(SYN_RECV)队列长度(二)

tcp的半连接与完全连接队列

总结几点就是：

  1. backlog在Linux 2.2之后表示的是已完成三次握手但还未被应用程序accept的队列长度，即全连接队列长度。

  2. backlog不能超过net.core.somaxconn整个参数，所以全连接队列长度等于min(backlog,somaxconn);

  3. 半连接队列长度（max_qlen_log），内核版本小于2.6.20的话max_qlen_log是直接由sysctl_max_syn_backlog决定的，否则是

    table_entries = min(min(somaxconn,backlog),tcp_max_syn_backlog)
roundup_pow_of_two(table_entries + 1)
//这个计算方式可能有点问题，因为实际测试好像有点差别，具体可以查 看上面引用的资料。

因此，Tomcat在BIO下同时能接受的请求数量为maxThread+acceptCount，根据官方描述超过的请求会直接返回connect refused，但我这边测试的结果是：

当状态为ESTABLISHED的TCP连接已经达到maxThread+acceptCount时，此时全连接队列已满，再过来的请求会卡在SYN_RECV状态（处于半连接队列），即收到客户端SYN包但并不做响应，直到全连接队列有空位才响应客户端SYN+ACK包，在这种情况下客户端会重试发送SYN包直到超时。当半连接队列满了的时候，再过来的请求会被直接拒绝掉（根据服务端的net.ipv4.tcp_abort_on_overflow等参数决定表现）。

但是以上并没有解决为什么Recv-Q不为0的数目总等于accptCount+1这个问题。一番瞎折腾后并没有结论，不过有了几个推测：

  • 和Tomcat的acceptorThreadCount配置有关，该参数的定义是The number of threads to be used to accept connections，即会启动acceptorThreadCount个Acceptor线程去接收请求，然后判断Tomcat线程池是否有剩余线程去处理该个请求。猜想会不会被该Acceptor线程接受的请求会离开全连接队列？不过将acceptorThreadCount这个参数设置为2时，Recv-Q不为0的数目依旧等于accptCount+1。（不过这个可能跟CPU核数有关&#%&#*￥&
  • 另一个猜测是全连接队列的长度=acceptCount+1,不过这个+1是在哪个环节操作的还待验证

压测

服务端环境
Tomcat配置 **maxThreads="2”minSpareThreads="0"connectionTimeout="200000"enableLookups="false"acceptCount="2”**acceptorThreadCount="1”
环境 Docker容器内
服务描述 当收到一个请求后，将处理该请求的线程sleep10s,然后返回response。因为该服务本身几乎不占用任何系统资源，所以在CPU，Mem，IO上是不会产生瓶颈的（实际压测证实），且因为该场景下控制了每个请求的耗时，QPS不高，所以在网络IO上也不会产生瓶颈。因此会影响QPS的只有Tomcat线程池的参数和Tomcat的性能
服务耗时 10s

场景1:

服务器无正在处理请求

用curl http://172.16.200.18:8891/Jweb/1从客户端发送一条请求

服务器在空负载的情况下，抓包请求表现如图。先是三次握手建立连接，然后发送HTTP请求和接受HTTP请求，之后四次挥手断开连接。其中第4个包为客户端发送的Http Request，经过了10s后收到第6个包，即服务端返回的Response。10s刚好和服务端请求处理时间吻合，符合预期。

因为服务端收到客户端的FIN包时，发现自己也已经没有数据要传给客户端了，所以会将ACK包和FIN包合在一起发送给客户端(网上资料说这种情况是少数，坑，但发现现在大部分内核都是这样处理的)已验证。

场景2：

服务器Tomcat线程池被占满，即有2个正在处理的请求

先在客户端192.168.41.108用./wrk -t1 -c2 -d5m --timeout 5m --latency http://172.16.200.18:8891/Jweb/1模拟两个不间断的请求。

通过netstat -nat查看服务端连接:

服务端netstat
tcp        0      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      192.168.41.108:48627    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48628    ESTABLISHED

发现两个TCP连接都为ESTABLISHED状态，对应从192.168.41.108过来的两个请求，且这两个连接的Recv-Q为0，所以表示正在被服务端处理。

接着从客户端172.16.20.6用curl http://172.16.200.18:8891/Jweb/1发送一条请求，查看客户端连接发现该请求建连成功，处于ESTABLISHED状态。

客户端netstat
tcp4       0      0  172.16.20.6.60645      172.16.200.18.8891     ESTABLISHED

此时再查看服务端连接

tcp        1      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      192.168.41.108:48627    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48628    ESTABLISHED
tcp       88      0 172.16.200.18:8891      172.16.20.6:60681       ESTABLISHED

有三条TCP连接，其中从172.16.20.6发来的请求Recv-Q不为0，所以处于全连接队列，等待服务端处理。直到服务端处理完了当前请求，192.168.41.108:48627和192.168.41.108:48628几乎同时处理完。此时轮到处理172.16.20.6:60681请求，同时192.168.41.108又发来了两条请求，其中一条进入全连接队列等待。具体查看如下服务端连接状态：

tcp        1      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      172.16.20.6:60681       ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48630    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48629    ESTABLISHED

查看客户端172.16.20.6抓包情况

对比第4个和第6个包，因为该请求经过一段时间的排队，所以在Request后经过了18s才收到Response。符合预期

再观察192.168.41.108的wrk压测数据:

[root@meitu_6 wrk]# ./wrk -t1 -c2 -d5m --timeout 5m --latency http://172.16.200.18:8891/Jweb/1
Running 5m test @ http://172.16.200.18:8891/Jweb/1
  1 threads and 2 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    10.18s     1.33s   20.01s    98.25%
    Req/Sec     0.00      0.00     0.00    100.00%
  Latency Distribution
     50%   10.00s
     75%   10.00s
     90%   10.01s
     99%   20.01s
  57 requests in 5.00m, 6.72KB read
Requests/sec:      0.19
Transfer/sec:      22.92B

整段压测持续了5m=300s，因为服务端每10s能处理2个请求，所以预期应该处理完的请求应该是$$ 300/10*2=60 $$。但是因为每个请求耗时是略大于10s的（网络传输等其他耗时），所以最后两个请求应该来不及接受response。因此请求总数应该是60-2=58。又由于中间插入处理了一条来自172.16.20.6的请求，所以请求总数为$$ 58-1=57 $$ 。符合预期

场景3：

服务器Tomcat线程池被占满，即有2个正在处理的请求，且有3个正在排队的请求，即全连接队列满

为什么全连接队列长度为3（Tomcat配置的acceptCount=2），参见开头的初步压测描述。

先在客户端192.168.41.108用./wrk -t1 -c5 -d5m --timeout 5m --latency http://172.16.200.18:8891/Jweb/1模拟五个不间断的请求。

查看服务端连接：

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      192.168.41.108:48942    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48943    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48946    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48945    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48944    ESTABLISHED

可以看见有5条TCP连接，其中两条正在被服务端处理，三条处于全连接队列，此时全连接队列已满。

再从客户端172.16.20.6用curl http://172.16.200.18:8891/Jweb/1发送一条请求，查看客户端连接发现该请求建联成功，处于ESTABLISHED状态。

tcp4       0     88  172.16.20.6.61166      172.16.200.18.8891     ESTABLISHED

查看服务端连接：

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      172.16.20.6:61166       SYN_RECV
tcp        0      0 172.16.200.18:8891      192.168.41.108:48942    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48943    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48946    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48945    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48944    ESTABLISHED

来自172.16.20.6的请求处于SYN_RECV状态。

分析在客户端172.16.20.6抓的包：

  • 首先1-3个包表示三次握手成功，因此客户端连接状态为ESTABLISHED
  • 第4个包，客户端发送了HTTP Request
  • 但是服务端并没有对第4个包进行响应。因此过了45ms客户端发了第5个包，进行了第一次重传(Retransmission)，重传了第4个包。但是服务端依旧没有响应ACK包，因此又重传了第6、7、8三个包。
  • 此时收到了来自172.16.200.18的第9个包，被标记为Spurious Retansmission，即服务端伪重传了第2个包（SYN包）。再看服务端将这条TCP连接被标记为SYN_RECV，说明服务端其实是没有收到第3个包或者对第3个包做处理的。查看下方图片对服务端的抓包，第35个包是客户端发给服务端的对SYN的ACK包，说明服务端是有收到对SYN的ACK包的，但是由于全连接队列满了，所以并没有对这个包做处理。因此服务端以为还没有收到这个ACK包，进而重传了SYN包。
  • 收到来自服务端的Spurious RetansmissionSYN包后，客户端重传了对服务端SYN的ACK包，即第10个包。
  • 但是由于服务端全连接队列依旧是满的，所以仍没有处理这个ACK包，依旧处于SYN_RECV。
  • 之后客户端继续重传第4个包（即HTTP Request请求）,总共重传了13次（每次重传的间隔是有规律的，是倍增直到一个上限值，根据配置有不同，具体的不展开）
  • 服务端由于全连接队列一直处于满的状态，所以一直也没有处理客户端的ACK包，并假设是客户端没有收到SYN包，因此总共也重传了3次SYN包。
  • 直到第26个包，客户端达到了某种限制（可能是TCP重传次数或者timeout，因为客户端是mac，查看了几个内核参数都有点不符，暂时不知道是哪种限制）所以向服务端发送了RST包，重置了本次连接。
  • 对比下图对服务端的抓包分析，可以验证以上结论。
  • 一个疑问是，客户端整个重传持续了17s，而服务端10s就可以处理完一个请求，在这一瞬间服务端会从全连接队列中取2个请求继续处理，此时全连接队列会出现空位。但是为什么服务端并没有直接处理来自客户端的ACK包并将其放入全连接队列，而是接受了来自192.168.41.108的新的请求？会不会是因为**服务端收到SYN的ACK包时，发现全连接队列满了，是否直接将这个ACK包抛弃？**在场景4做验证。

服务端处理完一个请求时的连接状态，此时172.16.20.6:61166这条连接依旧处于半连接队列，状态为SYN_RECV,但有一条新的连接192.168.41.108:48952插入了全连接队列（该连接未进入半连接队列）：

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      172.16.20.6:61166       SYN_RECV
tcp        0      0 172.16.200.18:8891      192.168.41.108:48946    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48945    TIME_WAIT
tcp       50      0 172.16.200.18:8891      192.168.41.108:48951    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48948    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48944    TIME_WAIT
tcp       50      0 172.16.200.18:8891      192.168.41.108:48952    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48947    ESTABLISHED

来自172.16.20.6的连接重置后：

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      192.168.41.108:48946    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48945    TIME_WAIT
tcp       50      0 172.16.200.18:8891      192.168.41.108:48951    ESTABLISHED
tcp       50      0 172.16.200.18:8891      192.168.41.108:48948    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48944    TIME_WAIT
tcp       50      0 172.16.200.18:8891      192.168.41.108:48952    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:48947    ESTABLISHED

场景4：

服务器Tomcat线程池被占满，即有2个正在处理的请求，且有3个正在排队的请求，即全连接队列满，第6个请求处于SYN_RECV状态，没有更多的请求

首先从192.168.41.108用for i in {1..5};do curl http://172.16.200.18:8891/Jweb/1& done模拟5个并发请求。

查看服务端连接：

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp      179      0 172.16.200.18:8891      192.168.41.108:49201    ESTABLISHED
tcp      179      0 172.16.200.18:8891      192.168.41.108:49203    ESTABLISHED
tcp      179      0 172.16.200.18:8891      192.168.41.108:49202    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:49200    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:49199    ESTABLISHED

5条ESTABLISHED连接，3条处于全连接队列，2条正在被处理。

再从客户端172.16.20.6用curl http://172.16.200.18:8891/Jweb/1发送一条请求，查看客户端连接发现该请求建连成功，处于ESTABLISHED状态。

tcp4       0      0  172.16.20.6.62147      172.16.200.18.8891     ESTABLISHED

查看服务度连接

tcp        3      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      172.16.20.6:62147       SYN_RECV
tcp      179      0 172.16.200.18:8891      192.168.41.108:49201    ESTABLISHED
tcp      179      0 172.16.200.18:8891      192.168.41.108:49203    ESTABLISHED
tcp      179      0 172.16.200.18:8891      192.168.41.108:49202    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:49200    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:49199    ESTABLISHED

来自172.16.20.6的请求处于SYN_RECV ，与场景3相同。 10s后，服务端处理完一条请求，查看服务端连接：

tcp        2      0 0.0.0.0:8891            0.0.0.0:*               LISTEN
tcp        0      0 172.16.200.18:8891      192.168.41.108:49201    ESTABLISHED
tcp      179      0 172.16.200.18:8891      192.168.41.108:49203    ESTABLISHED
tcp        0      0 172.16.200.18:8891      192.168.41.108:49202    ESTABLISHED
tcp       88      0 172.16.200.18:8891      172.16.20.6:62147       ESTABLISHED

发现来自172.16.20.6的请求进入了全连接队列。

再看客户端的抓包分析

  • 前17个包和场景3表现相同
  • 在服务端处理完当前请求后，由于此时服务端全连接队列出现了空位，因此处理了172.16.20.6的ACK包，并将该连接放入全连接队列，所以此时该连接变成ESTABLISHED状态。（**有个疑问是此时服务端是立即处理之前传过来的HTTP Request包，还是等待下一个包？**个人估计应该是等待下一个包，在处理SYN的ACK包前，也就是服务端连接处于SYN_RECV时，该连接发来的其他包应该都是被丢弃的，通过对比第18个包和17个包的时间间隔只有0.1ms级别猜测在服务端收到第17个包前已经将连接置为ESTABLISHED）
  • 第18个包是服务端对客户端的HTTP Request包响应的ACK包，根据Tsecr判断是对第17个包的ACK。
  • 之后便是正常的Request处理。
  • 观察第20个包和第17个包差了20s，是因为这个请求进入全连接队列后等待了10s后又被Tomcat处理了10s,因此等待了 \(10+10=20\) s。
  • 所以，当全连接队列满的时候，处于半连接队列的TCP连接的ACK包并没有被丢弃，而是大概存在于一个队列中等待处理吧。（需要查看内核源码验证）
  • 不过当全连接出现空位时，并不是立即从半连接队列取出一个连接处理并放入全连接队列。我估计是有个定时器定时查看全连接队列是否有空闲位置，有的话才从半连接队列取出连接放入全连接队列（我猜的,需要查看内核源码验证…）。

总结

  1. Tomcat服务端能保持ESTABLISHED状态的连接数量为maxThread+acceptCount+1,至于这个+1是怎么来的，目前我也母鸡。
  2. 当Tomcat服务端保持的连接数达到maxThread+acceptCount+1时，再过来的请求会处于半连接队列，对于半连接队列的连接，客户端会不停的重发包直到超时或超次数，或者全连接队列出现了空位且该连接被放入全连接队列（优先级不是最高，即不是全连接队列一有空位就马上主动从半连接队列取一个放入全连接队列。）。
  3. 当全连接队列满了的情况下，还不停有请求过来时，再过来的请求会被放入半连接队列，但是服务端会有剔除的策略（策略是怎么样的我也不知道….），会主动向半连接队列中的一些连接发RST包断开这些连接。
  4. 当全连接队列和半连接队列都满了的情况下，对客户端再发来的SYN包，服务端不会响应ACK包。
  5. 当TCP连接没有建立成功就被RST掉的时候，客户响应的会是Connection reset by peer，Chrome浏览器响应like this:

个人总结

  1. 初步了解了WireShark和tcpdump的使用及相互配合。
  2. 初步了解了docker环境的部署，包括镜像的build，对docker实例的操作。
  3. 对TCP协议有了更深的理解。包括三次握手，四次挥手及各种状态，之后要系统的总结一下。感觉这篇更偏向与对TCP连接的测试。。。
  4. 对Tomcat源码有了进一步的了解，主要在connector和executor这一块，虽然还在很浅的层次。以及目前还只是了解BIO模式，NIO和apr还需探索。
  5. 修为还不够，看到linux内核代码还是一头雾水。。。
  6. 对ab和wrk压测工具有更深的理解，萌生了自己写一个压测工具的想法，初步想要使用go来写（感觉是个大坑…）。
  7. 再说下对压测的想法：当压测目标不是很明确的时候，如果没有很详细的计划来执行压测（像我这段时间对Tomcat的压测就是没有详细计划的，只有一个大概目标，想到什么压测什么），就会产生很多压测数据不符合预期的情况，两种情况，一个是预期出错了，一个是压测数据出错了。在这个过程中我两种情况都遇到过，但是为了验证是哪个出错花费了我绝大部分压测的时间。虽然学到了很多东西，但过程是痛苦的，因为很多时候是毫无头绪的，猜到一种可能就验证一种可能。为了避免压测数据出错，我认为有几点：
  • 确保压测的环境是稳定的，包括网络，CPU，内存，IO等等可能涉及的资源，且要确保在相同场景下，这些资源的配置是一样的，尽量做到在整个压测过程中所有场景下这些资源都达到一致。
  • 理清整个服务的流程链路再进行压测。确保能快速定位到是哪一个环境出现了异常。
  • 保证所有涉及到的资源只服务于当前压测的服务。

再就说说压测计划，查过网上一些压测计划，发现太过规整有点偏向于形式化了，不是很喜欢（懒）。我认为压测计划主要是描述清楚各个压测场景就足够了，尽量做到场景覆盖所有情况，且针对每个场景都有与其对比的其他场景。然后将这些场景设立的原因及场景描述写清楚（因为一些细节真的很容易忘记，虽然有些细节可能在你想到后写下来前就忘记了。。。所以更应该记下来）。 8. 然后再就是要注重是实践吧，很多东西你不去做真的不知道，就算你想去找，网上可能还真的没有，比如一些很细节的东西，可能有些人经历过，但不是每个人都会将其记下并传到网上，且还能被搜索引擎顶到前列。 9. 之前想了很多点要写的，你看写到这里就忘记了。。。 10. 再附上报告中被压测项目的源码做个记录，几乎是裸的:https://github.com/Yesphet/Jweb

本文地址