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的调用底层阻塞在pollepoll_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秒,结束后再查看SocketProcessorSocketWrapper的实例数:

$ 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.SocketProcessortry-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才提供了。

原创文章,转载请注明: 转载自并发编程网 – ifeve.com本文链接地址: Tomcat对keep-alive的实现逻辑

  • Trackback 关闭
  • 评论 (1)
  1. 还没用过 tomcat。

return top