标签归档:tomcat

tomcat-connector的微调(2): maxConnections, maxThreads

1) 最大连接数

tomcat的最大连接数参数是maxConnections,这个值表示最多可以有多少个socket连接到tomcat上。BIO模式下默认最大连接数是它的最大线程数(缺省是200),NIO模式下默认是10000,APR模式则是8192(windows上则是低于或等于maxConnections的1024的倍数)。如果设置为-1则表示不限制。

在tomcat里通过一个计数器来控制最大连接,比如在Endpoint的Acceptor里大致逻辑如下:

while (running) {
    ...    
    //if we have reached max connections, wait
    countUpOrAwaitConnection(); //计数+1,达到最大值则等待

    ...
    // Accept the next incoming connection from the server socket
    socket = serverSock.accept();

    ...
    processSocket(socket);

    ...
    countDownConnection(); //计数-1
    closeSocket(socket);
}

计数器是通过LimitLatch锁来实现的,它内部主要通过一个java.util.concurrent.locks.AbstractQueuedSynchronizer的实现来控制。

我们在server.xml里对Connector增加maxConnections="1"这个参数,然后模拟2个连接:

for i in {1..2}; do ( 
    {
        echo -ne "POST /main HTTP/1.1\nhost: localhost:7001\n\n"; 
        sleep 20
    } | telnet localhost 7001
)&;  done

然后通过jstack可以看到acceptor线程阻塞在countUpOrAwaitConnection方法上:

"http-bio-7001-Acceptor-0" #19 daemon prio=5 os_prio=31 tid=0x00007f8acbcf1000 nid=0x6903 waiting on condition [0x0000000129c58000]
 java.lang.Thread.State: WAITING (parking)
 at sun.misc.Unsafe.park(Native Method)
 - parking to wait for  <0x0000000740353f40> (a org.apache.tomcat.util.threads.LimitLatch$Sync)    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
 at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
 at org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait(LimitLatch.java:115)
 at org.apache.tomcat.util.net.AbstractEndpoint.countUpOrAwaitConnection(AbstractEndpoint.java:755)
 at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:214)
 at java.lang.Thread.run(Thread.java:745)

对于NIO和APR的最大连接数默认值比较大,适合大量连接的场景;如果是BIO模式线程池又设置的比较小的话,就需要注意一下连接的处理是否够快,如果连接处理的时间较长,或新涌入的连接量比较大是不太适合用BIO的,调大BIO的线程数也可能存在利用率不高的情况

2) 最大线程数

如果没有对connector配置额外的线程池的话,maxThreads参数用来设置默认线程池的最大线程数。tomcat默认是200,对一般访问量的应用来说足够了。

tomcat-connector的微调(1): acceptCount参数

对于acceptCount这个参数,含义跟字面意思并不是特别一致(个人感觉),容易跟maxConnections,maxThreads等参数混淆;实际上这个参数在tomcat里会被映射成backlog:

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

backlog表示积压待处理的事物,是socket的参数,在bind的时候传入的,比如在Endpoint里的bind方法里:

public void bind() throws Exception {

    serverSock = ServerSocketChannel.open();
    ...
    serverSock.socket().bind(addr,getBacklog());
    ...
}

这个参数跟tcp底层实现的半连接队列和完全连接队列有什么关系呢?我们在tomcat默认BIO模式下模拟一下它的效果。

模拟的思路还是简单的通过shell脚本,建立一个长连接发送请求,持有20秒再断开,好有时间观察网络状态。注意BIO模式下默认超过75%的线程时会关闭keep-alive,需要把这个百分比调成100,这样就不会关闭keep-alive了。修改后的connector如下,最后边的三行参数是新增的:

<Connector port="8080" protocol="HTTP/1.1"
    connectionTimeout="20000"
    redirectPort="8443"        

    maxThreads="1"
    disableKeepAlivePercentage="100"
    acceptCount="2"
/>

上面的配置里我们把tomcat的最大线程数设置为1个,一直开启keep-alive,acceptCount设置为2。在linux上可以通过ss命令检测参数是否生效:

$ ss -ant  
State       Recv-Q Send-Q     Local Address:Port     Peer Address:Port
LISTEN      0      2          :::7001                :::*

可以看到7001端口是LISTEN状态,send-q的值是2,也就是我们设置的backlog的值。如果我们不设置,tomcat默认会设置为100,java则默认是50。

然后用下面的脚本模拟一次长连接:

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

这个时候看服务器端socket的状况,是ESTABLISHED,并且Recv-QSend-Q都是没有堆积的,说明请求已经处理完

$ netstat -an | awk 'NR==2 || $4~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4       0      0  127.0.0.1.7001         127.0.0.1.54453        ESTABLISHED

现在我们模拟多个连接:

$ for i in {1..5}; do 
    ( 
        {
          echo -ne "POST /main HTTP/1.1\nhost: localhost:7001\n\n"; 
          sleep 20
        } | telnet localhost 7001
    )&;  
  done 

上面发起了5个链接,服务器端只有1个线程,只有第一个连接上的请求会被处理,另外4次连接,有2个连接还是完成了建立(ESTABLISHED状态),还有2个连接则因为服务器端的连接队列已满,没有响应,发送端处于SYN_SENT状态。下面列出发送端的tcp状态:

$ netstat -an | awk 'NR==2 || $5~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4       0      0  127.0.0.1.51389        127.0.0.1.7001         SYN_SENT
tcp4       0      0  127.0.0.1.51388        127.0.0.1.7001         SYN_SENT
tcp4       0      0  127.0.0.1.51387        127.0.0.1.7001         ESTABLISHED
tcp4       0      0  127.0.0.1.51386        127.0.0.1.7001         ESTABLISHED
tcp4       0      0  127.0.0.1.51385        127.0.0.1.7001         ESTABLISHED

再看tomcat端的状态:

$ netstat -an | awk 'NR==2 || $4~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4      45      0  127.0.0.1.7001         127.0.0.1.51387        ESTABLISHED
tcp4      45      0  127.0.0.1.7001         127.0.0.1.51386        ESTABLISHED
tcp4       0      0  127.0.0.1.7001         127.0.0.1.51385        ESTABLISHED

有3个链接,除了第一条连接请求的Recv-Q是0,另外两个连接的Recv-Q则有数据堆积(大小表示发送过来的字节长度)。注意,在ESTABLISHED状态下看到的Recv-QSend-Q的大小与在LISTEN状态下的含义不同,在LISTEN状态下的大小表示队列的长度,而非数据的大小。

从上面的模拟可以看出acceptCount参数是指服务器端线程都处于busy状态时(线程池已满),还可接受的连接数,即tcp的完全连接队列的大小。对于完全队列的计算,在linux上是:

min(backlog,somaxconn) 

backlog参数和proc/sys/net/core/somaxconn这两个值哪个小选哪个。

不过acceptCount/backlog参数还不仅仅决定完全连接队列的大小,对于半连接队列也有影响。参考同事飘零的blog,在linux 2.6.20内核之后,它的计算方式大致是:

table_entries = min(min(somaxconn,backlog),tcp_max_syn_backlog)
roundup_pow_of_two(table_entries + 1)

第二行的函数roundup_pow_of_two表示取最近的2的n次方的值,举例来说:假设somaxconn为128,backlog值为50,tcp_max_syn_backlog值为4096,则第一步计算出来的为50,然后roundup_pow_of_two(50 + 1),找到比51大的2的n次方的数为64,所以最终半连接队列的长度是64。

所以对于acceptCount这个值,需要慎重对待,如果请求量不是很大,通常tomcat默认的100也ok,但若访问量较大的情况,建议这个值设置的大一些,比如1024或更大。如果在tomcat前边一层对synflood攻击的防御没有把握的话,最好也开启syn cookie来防御。

tomcat进程意外退出: oom-killer

在非jvm crash引起的tomcat进程意外退出的故障里,oom-killer是见过的比例最多的情况,排查这类问题时应首先判断是否由oom-killer所致。这个问题在答疑中遇到好几次,记录一下给新人了解。

定位oom-killer通常比较简单,直接通过dmesg即可看到:

$  sudo dmesg | grep java | grep -i oom-killer
[6989889.606947] java invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
[7061818.494917] java invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
[7108961.621382] java invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0

或者在日志中按java关键字搜索,会看到类似下面的日志:

[7250516.311246] Out of memory: Kill process 15041 (java) score 869 or sacrifice child
[7250516.311255] Killed process 15041, UID 505, (java) total-vm:2307028kB, anon-rss:1780636kB, file-rss:872kB

不过这里有个问题,日志的格式,不能之间看出被kill时的信息,除非你确定被kill的java进程id就是之前tomcat的进程id(在ali-tomcat会记录在一个文件里)。

在高版本的dmesg命令里,有一个很人性化的参数-T来以正常的时间格式来显示日志的,但很多时候会碰到比较低的版本:

$ rpm -qf /bin/dmesg
util-linux-2.13-0.56.el5

小于util-linux-2.20版本的无法使用这个参数,只有变通的通过下面的方式转换一下,从stackoverflow上学到的:

dmesg_with_human_timestamps () {
$(type -P dmesg) "$@" | perl -w -e 'use strict;
    my ($uptime) = do { local @ARGV="/proc/uptime";<>}; ($uptime) = ($uptime =~ /^(\d+)\./);
    foreach my $line (<>) {
        printf( ($line=~/^\[\s*(\d+)\.\d+\](.+)/) ? ( "[%s]%s\n", scalar localtime(time - $uptime + $1), $2 ) : $line )
    }'
}
alias dmesg=dmesg_with_human_timestamps

把上面的函数和alias加到.bashrc里,source一下,可以得到正常的日期格式了:

$ dmesg | grep "(java)"

[Thu Aug 28 20:50:14 2014] Out of memory: Kill process 18078 (java) score 872 or sacrifice child
[Thu Aug 28 20:50:14 2014] Killed process 18078, UID 505, (java) total-vm:2390108kB, anon-rss:1784964kB, file-rss:2048kB
[Fri Aug 29 14:48:06 2014] Out of memory: Kill process 15041 (java) score 869 or sacrifice child
[Fri Aug 29 14:48:06 2014] Killed process 15041, UID 505, (java) total-vm:2307028kB, anon-rss:1780636kB, file-rss:872kB

开启oom-killer的话,在/proc/pid下对每个进程都会多出3个与oom打分调节相关的文件,如果想要关闭,可能涉及运维的管理,要跟各方沟通好。临时对某个进程可以忽略oom-killer可以使用下面的方式:

$ echo -17 > /proc/$(pidof java)/oom_adj

更多有关oom-killer的可参看这篇

Docker中apache-tomcat启动慢的问题

在docker/centos系统里启动官方的tomcat时,发现启动过程很慢,需要几十秒,即使只用官方默认自带的几个应用启动也一样。
一查日志,发现是session引起的随机数问题导致的:

INFO: Deploying web application directory /data/server/install/apache-tomcat-7.0.55/webapps/ROOT
Aug 29, 2014 1:14:02 AM org.apache.catalina.util.SessionIdGenerator createSecureRandom
INFO: Creation of SecureRandom instance for session ID generation 
        using [SHA1PRNG] took [27,537] milliseconds.

这个问题之前在之前的这篇JVM上的随机数与熵池策略 已经分析过了,我们在ali-tomcat里为避免随机数引起的阻塞,设置过使用非阻塞熵池策略:

if [[ "$JAVA_OPTS" != *-Djava.security.egd=* ]]; then
    JAVA_OPTS="$JAVA_OPTS -Djava.security.egd=file:/dev/./urandom"
fi

修改过后,立刻从之前的27秒降到了0.5秒:

INFO: Deploying web application directory /data/server/install/apache-tomcat-7.0.55/webapps/ROOT
Aug 29, 2014 2:10:13 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deployment of web application directory /data/server/install/apache-tomcat-7.0.55/webapps/
    ROOT has finished in 515 ms

关于tomcat的Advanced IO

前几天对某个团队分享tomcat的时候,有人提到tomcat早前也有aio的概念,我以为是基于java7的NIO2,但对方说是早期版本就有的。我只对7比较熟悉,之前的版本不太了解,没有确认。今天google了一下估计是理解错误,把tomcat里的Advanced IO误以为Async IO

Adavanced IO是指APR或NIO模式下可以提供一些扩展,主要是通过Comet以及sendfile实现异步IO的效果。Comet是个过渡技术,相比websocketspdy有些过时。sendfile对于较大的静态文件比较有用,但不支持AJP协议。在APR和NIO下实现方式也不同,APR模式下是有一个专门的线程负责,通过jni调用tcnative里的sendfile本地实现;而NIO模式下则是通过FileChannel.transferTo来实现。

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

模拟tomcat bio模式下线程池利用率超过75%关闭keep-alive的情况

模拟一下在BIO模式下,当线程利用率超过75%时,将自动关闭keep-alive的场景。

通过curl命令来观察,默认情况下curl会开启keep-alive选项,不过注意curl复用socket的话是在同一进程内多次访问目标同一地址时才会复用,两次执行curl的话并不会复用,比如:

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

上面连续执行curl命令并不会复用socket,socket会随着进程的消失而关闭,下次新的进程会重新创建连接。可以通过tcpdump观察,上面两次连接是不同的socket:

$ sudo tcpdump -l -i lo0 port 7001

23:43:19.236948 IP6 localhost.62625 > localhost.afs3-callback
......
23:43:26.071504 IP6 localhost.62626 > localhost.afs3-callback
......

在同一个curl进程里多次访问同一地址的话,会复用socket,通过-v参数就可以观察到:

$ curl -v  http://localhost:7001/main  http://localhost:7001/main
* Hostname was NOT found in DNS cache
*   Trying ::1...
* Connected to localhost (::1) port 7001 (#0)
> GET /main HTTP/1.1
> User-Agent: curl/7.37.1
> Host: localhost:7001
> Accept: */*
>
< HTTP/1.1 200 OK
* Server Apache-Coyote/1.1 is not blacklisted
< Server: Apache-Coyote/1.1
< Transfer-Encoding: chunked
< Date: Mon, 18 Aug 2014 15:49:28 GMT
<
* Connection #0 to host localhost left intact
ok
* Found bundle for host localhost: 0x7fa7d8c08c50
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (::1) port 7001 (#0)
> GET /main HTTP/1.1
> User-Agent: curl/7.37.1
> Host: localhost:7001
> Accept: */*
>
< HTTP/1.1 200 OK
* Server Apache-Coyote/1.1 is not blacklisted
< Server: Apache-Coyote/1.1
< Transfer-Encoding: chunked
< Date: Mon, 18 Aug 2014 15:49:28 GMT
<
* Connection #0 to host localhost left intact
ok

注意,在第二次请求开头有一句:Re-using existing connection! 表明复用了上次的socket,使用tcpdump也会看到确实是同一个socket端口连的tomcat。

默认情况下,线程池的最大线程数是200个,BIO模式下当线程利用率超过75%的时候,server会对新来的连接不再使用keep-alive。我们先模拟建立151个连接(默认开启keep-alive的):

for i in {1..151}; do 
    ( 
        {echo -ne "GET /main HTTP/1.1\nhost: localhost:7001\n\n"; sleep 20} 
        | telnet localhost 7001
    )&;  
done

上面的zsh脚本模拟了151个连接(脚本里for循环里使用后台子进程方式启动模拟任务,通过jobs命令也可查看到),每次新建立socket并在服务器端响应后保持连接20秒(这也是服务器端默认keep-alive的超时时间)。tomcat对这151个连接保持keep-alive,BIO模式下会有151个线程耗在上面,即使socket上请求已处理完,后续没有新的请求也不会让出线程,而一直阻塞在上面。这时刚好达到了 151/200 ≈ 0.75 的临界值,那么后续建立的socket将不能再享用keep-alive

现在在这个临界值上,再执行curl命令模拟新的连接:

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

* Hostname was NOT found in DNS cache
*   Trying ::1...
* Connected to localhost (::1) port 7001 (#0)
> GET /main HTTP/1.1
> User-Agent: curl/7.37.1
> Host: localhost:7001
> Accept: */*
>
< HTTP/1.1 200 OK
* Server Apache-Coyote/1.1 is not blacklisted
< Server: Apache-Coyote/1.1
< Transfer-Encoding: chunked
< Date: Mon, 18 Aug 2014 15:22:50 GMT
< Connection: close
<
* Closing connection 0
ok
* Hostname was found in DNS cache
*   Trying ::1...
* Connected to localhost (::1) port 7001 (#1)
> GET /main HTTP/1.1
> User-Agent: curl/7.37.1
> Host: localhost:7001
> Accept: */*
>
< HTTP/1.1 200 OK
* Server Apache-Coyote/1.1 is not blacklisted
< Server: Apache-Coyote/1.1
< Transfer-Encoding: chunked
< Date: Mon, 18 Aug 2014 15:22:50 GMT
< Connection: close
<
* Closing connection 1
ok

注意,这次连接有2次请求,但看不到Re-using existing connection! 关键字,每次请求结束,服务器都显式的关闭了连接,即在header里看到的:Connection: close字段。表明超过75%之后,新建立的连接都不会再使用keep-alive。

关于application/x-www-form-urlencoded编码

同事遇到在servlet端通过request对象getInputStream读取POST过来的数据,却读不到的问题,怀疑是tomcat的问题。查了一下Content-typeapplication/x-www-form-urlencoded,估计是被解析成了parameters,果然在他获取流之前,有过request.getParameter的操作。

熟悉servlet的话,这个问题应该算常识了。它其实跟容器无关,所有的servlet容器都是这样的行为。几年前在实现一个网关代理的时候就遇到过这个问题,当时使用的是jetty,发现POST过来的数据读不到,也是application/x-www-form-urlencoded编码,断点跟踪发现是在获取流之前有过request.getParameter,数据会被解析,并且后续数据流不可再被读取。

在servlet规范3.1.1节里,对POST数据何时会被当做parameters有描述:

1. The request is an HTTP or HTTPS request.
2. The HTTP method is POST.
3. The content type is application/x-www-form-urlencoded.
4. The servlet has made an initial call of any of the getParameter family of methods on the request object.

If the conditions are met, post form data will no longer be available for reading directly from the request object’s input stream.

规范里已经明确的声明当请求满足: 1) http/https, 2) POST, 3) Content-type 是application/x-www-form-urlencoded, 4) 调用过getParameter方法;则数据会被当做请求的paramaters,而不能再通过 request 的 inputstream 直接读取。

所以不论tomcat、jetty还是其他servlet容器都遵循这个方式。不过话说回来,为什么application/x-www-form-urlencoded编码的数据会被当做parameter来解析呢?

使用http上传数据可以用GET或POST,使用GET的话,只能通过uri的queryString形式,这会遇到长度的问题,各个浏览器或server可能对长度支持的不同,所以到要提交的数据如果太长并不适合使用GET提交。

采用POST的话,既可以在uri中带有queryString也可以将数据放在body中。body内容可以有多种编码形式,其中application/x-www-form-urlencoded编码其实是基于uri的percent-encoding编码的,所以采用application/x-www-form-urlencoded的POST数据和queryString只是形式不同,本质都是传递参数。

在tomcat的Request.parseParameters方法里,对于application/x-www-form-urlencoded是有做判断的,对这种编码会去解析body里的数据,填充到parameters里,所以后续想再通过流的方式读取body是读不到的(除非你没有触发过getParameter相关的方法)。

在HTML4之前,表单数据的编码方式只有application/x-www-form-urlencoded这一种(现在默认也是这种方式),因为早期的时候,web上提交过来的数据也是非常简单的,基本上以key-value形式为主,所以表单采用application/x-www-form-urlencoded这种编码形式也没什么问题。

在HTML4里又引入了multipart/form-data编码,对于这两种编码如何选择,请参考这里

tomcat启动遇到NoSuchMethodError错误的排查思路

某个应用在日常环境运行ok,在预发布时却启动错误,异常日志如下:

Caused by: java.lang.NoSuchMethodError: 
org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory.
<init>(Ljava/util/concurrent/Executor;Ljava/util/concurrent/Executor;II)V

at com.taobao.xxx.client.rpc.net.XXXConnector.<init>(XXXConnector.java:43)

是调用netty的NioClientSocketChannelFactory的构造方法时找不到对应的方法,根据提示信息,这个方法的签名应该是这样:

NioClientSocketChannelFactory(Executor, Executor, int, int) 

绝大部分情况下,都是因为多个版本的jar包同时存在产生的冲突,去用户的war下搜索一下。

 for file in *.jar; do 
    echo $file;
    /opt/taobao/java/bin/jar tvf $file | grep NioClientSocketChannelFactory;  
 done

找到了两个jar里都包含那个类,这两个jar也是两个不同的netty版本:

netty-3.6.3.Final.jar
jboss.jboss-netty-3.2.5.Final.jar

分别解开,看看哪个版本里是有那个构造方法的,先看3.6.3 版本:

$/opt/taobao/java/bin/javap  org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory | grep Executor | grep int

public org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory(java.util.concurrent.Executor, java.util.concurrent.Executor, int);
public org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory(java.util.concurrent.Executor, java.util.concurrent.Executor, int, int);
public org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory(java.util.concurrent.Executor, int, org.jboss.netty.channel.socket.nio.WorkerPool);
public org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory(java.util.concurrent.Executor, int, org.jboss.netty.channel.socket.nio.WorkerPool, org.jboss.netty.util.Timer);

里面是包含了我们需要的那个方法的。再看 3.2.5 版本:

$/opt/taobao/java/bin/javap  org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory | grep Executor | grep int

public org.jboss.netty.channel.socket.nio.NioClientSocketChannelFactory(java.util.concurrent.Executor, java.util.concurrent.Executor, int);

签名里只有1个int参数,没有我们要用的那个。

可以判断这次是因为classloader优先加载了jboss.jboss-netty-3.2.5.Final.jar这个文件而导致问题的,那为何日常环境的机器上却没问题呢?对于classloader而言,找文件的过程取决于文件系统返回的顺序,简单的说,在linux上取决于两个inode的顺序,在这台预发布机器上,正好 3.2.5 版本的 inode 在前:

$ stat netty-3.6.3.Final.jar
  File: `netty-3.6.3.Final.jar'
  Size: 1202373     Blocks: 2368       IO Block: 4096   regular file
Device: 805h/2053d  Inode: 66912666    Links: 1
Access: (0644/-rw-r--r--)  Uid: (  594/   admin)   Gid: (  594/   admin)
Access: 2014-08-06 13:21:56.000000000 +0800
Modify: 2014-07-14 16:13:44.000000000 +0800
Change: 2014-08-06 13:21:54.000000000 +0800    

$ stat jboss.jboss-netty-3.2.5.Final.jar
  File: `jboss.jboss-netty-3.2.5.Final.jar'
  Size: 792314      Blocks: 1568       IO Block: 4096   regular file
Device: 805h/2053d  Inode: 66912474    Links: 1
Access: (0644/-rw-r--r--)  Uid: (  594/   admin)   Gid: (  594/   admin)
Access: 2014-08-06 13:21:56.000000000 +0800
Modify: 2014-07-14 16:14:18.000000000 +0800
Change: 2014-08-06 13:21:53.000000000 +0800

3.2.5版本的jar文件inode小于3.6.3版本的jar文件,被classloader优先找到了。

用ThreadLocal解决SimpleDateFormat的性能问题

SimpleDateFormat是非线程安全的,在并发下碰到的案例见过好几次了。若场景对性能要求很高,创建大量生命周期很短暂的实例对象也是不小开销(主要是SimpleDateFormat内部比较复杂),可以考虑采用ThreadLocal来优化,以前曾见到过这种优化方式,忘了出处,在tomcat的代码里也有这样的用法,下面代码是tomcat7的DateTool工具类里的:

    public static final ThreadLocal<DateFormat> rfc1123Format = new ThreadLocal<DateFormat>() {
    @Override
    public DateFormat initialValue() {
        DateFormat result = new SimpleDateFormat(RFC1123_PATTERN, Locale.US);
        result.setTimeZone(GMT_ZONE);
        return result;
    }
};

调用的时候,每个线程可以通过rfc1123Format.get().format(...) 来使用。不过tomcat8里已经删除了这个类。