一次编码问题的排查

上周遇到的一个问题,代码里有通过scala.io.Source.fromFile 方式读取文件内容,并且没有指定编码格式,开始程序运行是ok的,后来添加了中文,发现在某些情况下会遇到乱码问题,并不是必然发生的,而是不同的人ssh登录到linux的测试环境启动应用可能会有不同的结果。这里记录一下当时的情况。

问题的排查,首先确认Source.fromFile这个api里面对编码的使用方式:

def fromFile(name: String)(implicit codec: Codec): BufferedSource =
    fromFile(new JFile(name))(codec)

不指定编码的话,系统使用了一个隐式参数作为默认编码,看一下它是什么:

scala>  def f(implicit c: io.Codec) = c
f: (implicit c: scala.io.Codec)scala.io.Codec

scala> f.name
res6: String = US-ASCII

这台linux上显示的是US-ASCII,而在我的mac上是UTF-8,看来是编码设置的问题,这个值应该是jvm的系统属性里编码相关的:

scala> System.getProperties.foreach(s => if (s.toString.indexOf("enc") != -1) println(s) )
(file.encoding.pkg,sun.io)
(sun.jnu.encoding,ANSI_X3.4-1968)
(file.encoding,ANSI_X3.4-1968)
(sun.io.unicode.encoding,UnicodeLittle)

测试了一下是file.encoding这个系统属性,修改这个属性为UTF-8后确实可以正常的。但是另一个同事登录这台linux后运行却跟我的情况不同,他登录后(使用同一账号)直接jvm的file.encoding默认就是UTF-8,这看起来有些奇怪。

jvm的系统属性,其实也是根据OS的环境变量得到的。虽然这台机器的LANGLC_*等指定了UTF-8,但并不意味jvm的file.encoding也一样:

$ locale
LANG=en_US.UTF-8
LC_CTYPE=UTF-8
LC_NUMERIC="en_US.UTF-8"
LC_TIME="en_US.UTF-8"
LC_COLLATE="en_US.UTF-8"
LC_MONETARY="en_US.UTF-8"
LC_MESSAGES="en_US.UTF-8"
LC_PAPER="en_US.UTF-8"
LC_NAME="en_US.UTF-8"
LC_ADDRESS="en_US.UTF-8"
LC_TELEPHONE="en_US.UTF-8"
LC_MEASUREMENT="en_US.UTF-8"
LC_IDENTIFICATION="en_US.UTF-8"
LC_ALL=

要确认file.encoding属性的话,可以使用locale charmap命令,我指定的结果显示:

$ locale charmap
ANSI_X3.4-1968

ANSI_X3.4-1968是系统默认的编码,而另一个同事显示的是”UTF-8″,又把怀疑落在ssh客户端上。我是在mac下直接通过ssh命令的方式登录,而他则是在windows下使用putty登录。各自打开ssh的 -verbose参数:

$ ssh -v xxx@ip

他的展示信息里出现了:

debug1: Sending env LC_ALL = en_US.UTF-8 
debug1: Sending env LANG = zh_CN.UTF-8 

而我的ssh客户端则没有这些信息,确实是ssh客户端配置所引起的差异。(关于LC_*LC_ALL等环境变量的关系后续有精力再整理)

检测最耗cpu的线程的脚本

这个脚本用于定位出当前java进程里最耗cpu的那个线程,给出cpu的占用率和当前堆栈信息。这个脚本仅限于linux上,我没有找到在mac下定位线程使用cpu情况的工具,如果你知道请告诉我一下。

先模拟一个耗cpu的java进程,启动一个scala的repl并在上面跑一段死循环:

scala> while(true) {}

脚本执行效果:

$ ./busythread.sh `pidof java`
tid: 431  cpu: %98.8
"main" prio=10 tid=0x00007f777800a000 nid=0x1af runnable [0x00007f7781c2e000]
    java.lang.Thread.State: RUNNABLE
    at $line3.$read$$iw$$iw$.<init>(<console>:8)
    at $line3.$read$$iw$$iw$.<clinit>(<console>)
    at $line3.$eval$.$print$lzycompute(<console>:7)
    - locked <0x00000000fc201758> (a $line3.$eval$)
    at $line3.$eval$.$print(<console>:6)
    at $line3.$eval.$print(<console>)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at scala.tools.nsc.interpreter.IMain$ReadEvalPrint.call(IMain.scala:739)
    at scala.tools.nsc.interpreter.IMain$Request.loadAndRun(IMain.scala:986)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest$$anonfun$loadAndRunReq$1.apply(IMain.scala:593)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest$$anonfun$loadAndRunReq$1.apply(IMain.scala:592)
    at scala.reflect.internal.util.ScalaClassLoader$class.asContext(ScalaClassLoader.scala:31)
    at scala.reflect.internal.util.AbstractFileClassLoader.asContext(AbstractFileClassLoader.scala:19)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest.loadAndRunReq(IMain.scala:592)
    at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:524)
    at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:520)

脚本内容:

#!/bin/bash

if [ $# -eq 0 ];then
    echo "please enter java pid"
    exit -1
fi

pid=$1
jstack_cmd=""

if [[ $JAVA_HOME != "" ]]; then
    jstack_cmd="$JAVA_HOME/bin/jstack"
else
    r=`which jstack 2>/dev/null`
    if [[ $r != "" ]]; then
        jstack_cmd=$r
    else
        echo "can not find jstack"
        exit -2
    fi
fi

#line=`top -H  -o %CPU -b -n 1  -p $pid | sed '1,/^$/d' | grep -v $pid | awk 'NR==2'`

line=`top -H -b -n 1 -p $pid | sed '1,/^$/d' | sed '1d;/^$/d' | grep -v $pid | sort -nrk9 | head -1`
echo "$line" | awk '{print "tid: "$1," cpu: %"$9}'
tid_0x=`printf "%0x" $(echo "$line" | awk '{print $1}')`
$jstack_cmd $pid | grep $tid_0x -A20 | sed -n '1,/^$/p'

脚本已放到服务器上,可以通过下面的方式执行:

$ bash <(curl -s https://hongjiang.info/busythread.sh)  java_pid

update: 感谢容若的反馈,很多环境的procps版本较低,top还不支持-o参数,排序那块用sort解决了,脚本已更新。

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的可参看这篇