Tomcat对keep-alive的实现逻辑

Tomcat的connector实现逻辑蛮复杂的，有很多种状态总记不住，每次遇到网络相关的问题都要翻一遍代码，这次结合一个案例看看tomcat的三种connector的实现方式。

这个案例在毕玄的blog里也提到了，背景是某应用上游有个用c写的模块与server端tomcat进行http通讯，这个应用tomcat配置的connector是apr模式。之前一直运行的很稳定，但一次前端扩容后，导致后端的tomcat全部阻塞在下面的堆栈上：

"http-apr-7001-exec-2" #28 daemon prio=5 os_prio=31 tid=0x00007fe1e43db800 nid=0x660b runnable [0x0000000124629000]
java.lang.Thread.State: RUNNABLE
 at org.apache.tomcat.jni.Socket.recvbb(Native Method)
 at org.apache.coyote.http11.InternalAprInputBuffer.fill(InternalAprInputBuffer.java:575)
 at org.apache.coyote.http11.InternalAprInputBuffer.parseHeader(InternalAprInputBuffer.java:464)
 at org.apache.coyote.http11.InternalAprInputBuffer.parseHeaders(InternalAprInputBuffer.java:312)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:969)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
 at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2442)
 at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2431)
 - locked <0x000000079581e018> (a org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
 at java.lang.Thread.run(Thread.java:745)

在我们最近这一年内推出的ali-tomcat版本里已经不推荐apr模式了，因为它带来的性能上的提升与运维和维护的成本比不值。一方面在使用时tcnative这个本地库的版本要与tomcat的版本匹配，否则不同的版本可能不工作(曾经出现过这样的运维故障)；二是我们曾遇到过apr导致jvm crash的情况；还有一个问题还是这个模块曾经被某个大牛修改过，继续维护的话团队里需要一个C/C++的人才行。

当时的情况有些紧急，看到堆栈阻塞在apr的本地调用上，通过pstack查看libapr的调用底层阻塞在poll或epoll_wait上，一下子没有思路，只好先让应用方升级到新版本的ali-tomcat上，采用BIO或NIO模式看看。

应用方切换到了新的版本后默认配置了BIO，线程池设置的是250，过不了一会儿大部分又阻塞在了下面的堆栈上：

"http-bio-7001-exec-977" daemon prio=10 tid=0x00007f3e0bb96800 nid=0x6ff5 runnable [0x00007f3e054d3000]
java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.read(SocketInputStream.java:129)
 at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:516)
 at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:501)
 at org.apache.coyote.http11.Http11Processor.setRequestLineReadTimeout(Http11Processor.java:167)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:948)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
 at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:314)
 - locked <0x00000006ed322ed8> (a org.apache.tomcat.util.net.SocketWrapper)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
 at java.lang.Thread.run(Thread.java:662)

从这个堆栈来看直觉上以为在读数据，问了以下应用方，上游主要通过POST方式调用tomcat，每次数据大约在几K到几十K，当时没有细问，误以为真的是发送过来的数据量达，都阻塞在数据读取上。采取了增加线程数大小的做法，先调到1000，发觉稳定在700-800之间，后应用负责人有些不放心，又调到了1500.

周末之后，应用虽然稳定，但BIO模式线程数开销的仍较大，通过ali-tomcat内置的监控功能可以看到线程池的状态：

$ curl http://localhost:8006/connector/threadpool
"http-bio-7001"
-----------------------------------------------------------------
| thread_count  |  thread_busy  | min_pool_size | max_pool_size |
-----------------------------------------------------------------
|     1121      |     1091      |      10       |     1500      |
-----------------------------------------------------------------

BIO模式下在使用的线程有1091个，应用方尝试采用NIO模式，观察了一段时间，同等压力下，线程数有大幅度下降：

$ curl http://localhost:8006/connector/threadpool
"http-nio-7001"
-----------------------------------------------------------------
| thread_count  |  thread_busy  | min_pool_size | max_pool_size |
-----------------------------------------------------------------
|      483      |      44       |      10       |     1500      |
-----------------------------------------------------------------

对于这么明显的下降，一方面怀疑BIO模式的瓶颈在哪儿，另一方面也觉得与业务的场景有关，正巧这个场景适用NIO模式。了解到他们使用了keep-alive，之前对于keep-alive的实现仅在NIO模式下有跟踪过，对于BIO和APR模式下如何实现的keep-alive没有很深入的了解，正好借这次问题排查详细的跟踪了一下另外两种模式下对keep-alive的实现。

在说keep-alive的实现之前，先贴张之前分享ali-tomcat的ppt的一张图：

这张表格引用自apache-tomcat官方网站，对于connector的三种模式有很好的对比，上次分享时着重讲NIO模式的实现，所以对NIO也不是完全非阻塞(读body和写response是模拟阻塞行为)的地方用红色突出了一下。这次我们先着重关注一下表格里的 “Wait for next Request” 这一项。它表示的是当开启keep-alive的情况下三种模式对等待下一次请求是否阻塞。

1) BIO模式下的keep-alive实现：

首先在BIO的专门负责socket建立的Acceptor线程的逻辑里，将socket封装成一个task(对应的是JIoEndpoint.SocketProcessor这个类)提交给线程池处理。而这个task(即SocketProcessor)的run方法逻辑大致是：

try{

    ...
    state = handler.process(...); // 这里是具体的处理逻辑
    ...

    if (state == SocketState.OPEN){
        socket.setKeptAlive(true);
        socket.access();
        launch = true;
    }
    ...

}finally{
    if(launch) {
        executor.execute(new SocketProcessor(...)); // 再次封装为同类型的task，并再次提交给线程池
    }
}

注意上面的逻辑，如果请求是开启keep-alive的话，socket在请求结束后仍处于OPEN状态，下一次请求仍可以复用当前socket而不必重新创建，在 finally 块里会判断连接状况如果是keep-alive会再次封装为同样的任务提交给线程池，重复这段逻辑，相当于一个循环，只不过每次执行的线程不一定相同。如果socket上已经没有请求了，最终socket会因超时或客户端close造成的EOFException而关闭。

有一个简单的方法来判断keep-alive是否被有效利用，如果socket被复用得当的话，socket(对应的是SocketWrapper这个类)的实例数应该是大大小于请求task(对应的是SocketProcessor这个类)实例数。比如我们先模拟不复用scoket的情况：

$ curl http://localhost:7001/main
$ curl http://localhost:7001/main

$ jmap -histo `pidof java` | sed -n -e '1,3p' -e '/SocketWrapper/p' -e '/SocketProcessor/p'

 num     #instances         #bytes  class name
----------------------------------------------
 516:             2            128  org.apache.tomcat.util.net.SocketWrapper
 587:             4             96  org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor

上面执行了2次curl，建立了2次连接，因为http1.1默认就开启了keep-alive，所以根据前面try-finally里逻辑，一次连接的过程被创建的SocketProcessor实例数会比它实际的请求数多1个。所以这2次curl命令(每次的请求为1)，没有复用socket，共创建了2个SocketWrapper实例和4个SocketProcessor实例。正好是2倍关系。

如果复用socket，则SocketProcessor实例数应该比SocketWrapper的实例数多不止一倍，比如下面用zsh模拟10次请求：

n=0; 
while (( n < 10 ));do  
    n=$((n+1)); 
    echo -ne "GET /main HTTP/1.1/nhost: localhost:7001/n/n";
    sleep 1;
done | telnet localhost 7001

这10次请求是复用的同一个socket，在每次请求中间间隔了1秒，结束后再查看SocketProcessor和SocketWrapper的实例数:

$ jmap -histo `pidof java` | sed -n -e '1,3p' -e '/SocketWrapper/p' -e '/SocketProcessor/p'

 num     #instances         #bytes  class name
----------------------------------------------
348:            11            264  org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor
669:             1             64  org.apache.tomcat.util.net.SocketWrapper

这次就一个socket的实例，task的实例数则是请求数+1，即11个。现实情况种这两个实例数差出1~2个数量级也常见(说明socket被复用的比较多)。

BIO模式下keep-alive为什么线程利用率不高？

再回到这次应用的例子中，为什么切换到BIO模式的情况下，被使用的线程数有1091个左右，而NIO的则只有44个，差距这么大的原因是什么？

其实上面给出的官方对比的表格里已经有答案了，BIO在处理下一次请求的时候是阻塞的，而NIO是非阻塞的。所谓阻塞是线程会一直挂在这个连接上等待新的数据到来。

正好这个应用的情况是开启keep-alive保持长连接，然后每隔1秒钟向tomcat发送一次数据。

如果要模拟他们的情况，可以用下面的脚本：

while :; do 
    echo -ne "POST /main HTTP/1.1/nhost: localhost:7001/nContent-length:4/n/nData/n";
    sleep 1;
done | telnet localhost 7001

按说几K到几十K的数据最多不超过几十毫秒，也就是说socket在90%以上的时间是空闲状态，而BIO却一直有一个线程会阻塞在上面，白白浪费。

这里有个细节，其实根据前边的JIoEndpoint.SocketProcessor的try-finally代码段，它不一定是阻塞在同一个线程上，取决于线程池的实现，但总会占用一个线程资源。现在看一下在等待下一次请求时的线程是怎么阻塞的：

$ { echo -e "GET /main HTTP/1.1/nhost: localhost:7001/n"; sleep 10 }  | telnet localhost 7001

上面模拟了一次连接，请求结束后先不释放，保持10秒钟，以便我们执行jstack来看此时的线程情况：

$ jstack `pidof java` | grep "socketRead0" -B2 -A10

"http-bio-7001-exec-4" #28 daemon prio=5 os_prio=31 tid=0x00007f8a742c4000 nid=0x7d03 runnable [0x0000000128ceb000]
java.lang.Thread.State: RUNNABLE
 at java.net.SocketInputStream.socketRead0(Native Method)
 at java.net.SocketInputStream.read(SocketInputStream.java:150)
 at java.net.SocketInputStream.read(SocketInputStream.java:121)
 at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:516)
 at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:501)
 at org.apache.coyote.http11.Http11Processor.setRequestLineReadTimeout(Http11Processor.java:167)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:946)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
 at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
 - locked <0x00000007973b0298> (a org.apache.tomcat.util.net.SocketWrapper)
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

看到这个堆栈信息和之前应用切换到BIO之后的情况一模一样，之前以为客户端发来的数据很多，这里是正在读取数据中，实际这里是没有请求数据过来，线程阻塞在这里等待数据。

正是因为BIO的实现方式让线程一直阻塞在长连接上，而这应用的长连接在绝大部分时间内又是没有数据的，造成了线程的浪费，而APR和NIO则不会让线程一直阻塞在长连接上，提高了线程的利用率。

2) APR模式下的keep-alive实现：

APR有点类似NIO，也有Poller线程的角色。在处理下一次请求的时候，不会像BIO那样阻塞。下面看一下在处理socket时的大致逻辑，摘自AbstractHttp11Processor.process方法做了简化，这个类是BIO/NIO/APR三种模式处理socket逻辑时的基类，在开启keep-alive的情况下会一直循环：

while ( keepAlive && !error && otherConditions ) {

    // Parsing the request header
    try {
        setRequestLineReadTimeout();

        if (!getInputBuffer().parseRequestLine(keptAlive)) {
            if (handleIncompleteRequestLineRead()) {
                break; //第一个break
            }
        }
        ...
    } catch (IOException e) {
        error = true;
    }

    ...
    prepareRequest();
    adapter.service(request, response); // 提交到后边的servlet容器
    endRequest();
    ...        

    if (breakKeepAliveLoop(socketWrapper)) {
        break; //第二个break
    }
}        

APR模式在处理完一次请求后，再次进入循环时会在第一个break点跳出(得不到下次请求)，把线程让出来，后续socket再有请求时poller线程会再封装一个任务(对应SocketProcessor类)，不过APR模式下acceptor在收到socket之后会先封装成一个SocketWithOptionsProcessor的task，它的作用只是把socket跟poller关联起来，真正处理请求时是靠poller。

下面模拟3次请求：

$ n=0; 
$ while (( n < 3 ));do  
    n=$((n+1)); 
    echo -ne "GET /main HTTP/1.1/nhost: localhost:7001/n/n";
    sleep 1;
  done | telnet localhost 7001

观察相关几个类的实例数：

$ jmap -histo `pidof java` | sed -n -e '1,3p' -e '/SocketWrapper/p' -e '/Endpoint.*Processor/p'

 num     #instances         #bytes  class name
----------------------------------------------
 619:             1             72  org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper
 620:             3             72  org.apache.tomcat.util.net.AprEndpoint$SocketProcessor
 975:             1             24  org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor   

socket所对应AprSocketWrapper实例为1，说明只有一个连接；SocketWithOptionsProcessor实例也为1，poller真正处理请求逻辑时还是用SocketProcessor封装的逻辑，这里3次请求对应3个实例数。注意有时候可能因为young-gc干扰你看到的实例数，可以把heap设置大一些避免。

既然APR模式对下一次请求并不是阻塞，线程会释放出来，为何应用方还是出现了阻塞呢？因为当时的环境已经不能复现了，无法准确判断当时的网络情况，但APR模式在处理header和body的时候都是阻塞的，所以一种很大的可能是当时client发送数据时，没有发送完全，造成connector阻塞在jni.Socket.recvbb方法上。可以模拟一下这个情况：

$ { echo -ne "POST /main HTTP/1.1/nhost: localhost:7001"; sleep 15 } | telnet localhost 7001

上面模拟的POST请求没有发送完整，header部分还没有结束，这时通过jstack来看线程的情况：

$ jstack `pidof java` | grep "recvbb" -B2 -A7

"http-apr-7001-exec-6" #33 daemon prio=5 os_prio=31 tid=0x00007fc8b2044000 nid=0x7e07 runnable [0x0000000120a20000]
java.lang.Thread.State: RUNNABLE
 at org.apache.tomcat.jni.Socket.recvbb(Native Method)
 at org.apache.coyote.http11.InternalAprInputBuffer.fill(InternalAprInputBuffer.java:575)
 at org.apache.coyote.http11.InternalAprInputBuffer.parseHeader(InternalAprInputBuffer.java:464)
 at org.apache.coyote.http11.InternalAprInputBuffer.parseHeaders(InternalAprInputBuffer.java:312)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:969)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
 at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2442)
 at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2431)

跟应用当时的情况是吻合的，当然如果client发送过程中如果body部分数据没有发送完整也会让tomcat阻塞在recvbb这个方法上。

3) NIO模式下的keep-alive实现：

NIO的大致结构也可以参考之前分享ali-tomcat的ppt里的图

对于keep-alive情况下处理下一次请求，NIO跟APR类似，线程不会一直阻塞在socket上。对于header的处理，NIO也同样不会阻塞，只有在body的读取时，NIO采取模拟阻塞的方式。可以模拟一下，在一个servlet里对post过来的数据回写过去:

public void doPost(HttpServletRequest request, HttpServletResponse resp) throws IOException {
    PrintWriter wr = resp.getWriter();
    BufferedReader br = new BufferedReader(new InputStreamReader(request.getInputStream()));
    String line = null;
    while ((line = br.readLine()) != null) {
        wr.write(line);
    }
    wr.write("done");
}

模拟请求：

$ { 
    echo -ne "POST /main HTTP/1.1/nhost: localhost:7001/nContent-length:5/n/na";
    sleep 15
  } | telnet localhost 7001

请求里描述的数据长度是5，但只给出了一个字符，出于数据未发送完的状态，这时来看服务器端线程状况：

"http-nio-7001-exec-1" #26 daemon prio=5 os_prio=31 tid=0x00007f8693c52800 nid=0x7a07 waiting on condition [0x00000001268f6000]
java.lang.Thread.State: TIMED_WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for  <0x0000000795ca3b50> (a java.util.concurrent.CountDownLatch$Sync)
 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
 at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
 at org.apache.tomcat.util.net.NioEndpoint$KeyAttachment.awaitLatch(NioEndpoint.java:1566)
 at org.apache.tomcat.util.net.NioEndpoint$KeyAttachment.awaitReadLatch(NioEndpoint.java:1568)
 at org.apache.tomcat.util.net.NioBlockingSelector.read(NioBlockingSelector.java:185)
 at org.apache.tomcat.util.net.NioSelectorPool.read(NioSelectorPool.java:246)
 at org.apache.tomcat.util.net.NioSelectorPool.read(NioSelectorPool.java:227)
 at org.apache.coyote.http11.InternalNioInputBuffer.readSocket(InternalNioInputBuffer.java:422)
 at org.apache.coyote.http11.InternalNioInputBuffer.fill(InternalNioInputBuffer.java:794)
 at org.apache.coyote.http11.InternalNioInputBuffer$SocketInputBuffer.doRead(InternalNioInputBuffer.java:819)
 at org.apache.coyote.http11.filters.IdentityInputFilter.doRead(IdentityInputFilter.java:124)
 at org.apache.coyote.http11.AbstractInputBuffer.doRead(AbstractInputBuffer.java:346)
 at org.apache.coyote.Request.doRead(Request.java:422)
 at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:290)
 at org.apache.tomcat.util.buf.ByteChunk.substract(ByteChunk.java:449)
 at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:315)
 at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:200)
 at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
 at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
 at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
 - locked <0x0000000795c96f28> (a java.io.InputStreamReader)
 at java.io.InputStreamReader.read(InputStreamReader.java:184)
 at java.io.BufferedReader.fill(BufferedReader.java:161)
 at java.io.BufferedReader.readLine(BufferedReader.java:324)
 - locked <0x0000000795c96f28> (a java.io.InputStreamReader)
 at java.io.BufferedReader.readLine(BufferedReader.java:389)
 at org.r113.servlet3.MainServlet.doPost(MainServlet.java:37)

线程并不是阻塞在原生的IO方法上，而是NioBlockingSelector.read方法上，这个方法从名字就可以看出它用NIO实现的阻塞式selector(里面的read和write方法注释也有明确说明)；相当于通过锁的方式来模拟阻塞方式，正如之前表格里红色字体突出的。

为什么NIO在读取body时要模拟阻塞？

tomcat的NIO完全可以以非阻塞方式处理IO，为什么在读取body部分时要模拟阻塞呢？这是因为servlet规范里定义了ServletInputStream在读数据时是阻塞模式，这里相关的争论可以google。

在servlet3.0里引入了异步，但仅针对传统IO，对应用来说仍有很多限制，所以servlet3.1又引入了非阻塞IO，但这要tomcat8才提供了。