标签归档:java

再谈随机数引起的阻塞问题

Java的随机数实现有很多坑,记录一下这次使用jdk1.8里新增的加强版随机数实现SecureRandom.getInstanceStrong() 遇到的问题。

之前在维护ali-tomcat的时候曾发现过jvm随机数算法选用不当导致tomcat的SessionID生成非常慢的情况,可以参考JVM上的随机数与熵池策略Docker中apache-tomcat启动慢的问题 这两篇文章。不过当时没有太追究,以为使用了-Djava.security.egd=file:/dev/./urandom就可以避免了,在这次项目里再次遇到随机数导致所有线程阻塞之后发现这块还挺多规则。

本次项目中使用的是jdk1.8,启动参数里设置了

-Djava.security.egd=file:/dev/./urandom

使用的随机数方式是Java8新增的:

SecureRandom.getInstanceStrong();

碰到故障时,线程阻塞在

"DubboServerHandler-xxx:20880-thread-1789" #28440 daemon prio=5 os_prio=0 tid=0x0000000008ffd000 nid=0x5712 runnable [0x000000004cbd7000]
java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:246)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:410)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:427)
    - locked <0x00000000c03a3c90> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:329)
    at sun.security.provider.NativePRNG$Blocking.engineGenerateSeed(NativePRNG.java:272)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:522)

因为这个地方有加锁,locked <0x00000000c03a3c90>,所以其它线程调用到这里时会等待这个lock:

"DubboServerHandler-xxx:20880-thread-1790" #28441 daemon prio=5 os_prio=0 tid=0x0000000008fff000 nid=0x5713 waiting for monitor entry [0x000000004ccd8000]
java.lang.Thread.State: BLOCKED (on object monitor)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:424)
    - waiting to lock <0x00000000c03a3c90> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:329)
    at sun.security.provider.NativePRNG$Blocking.engineGenerateSeed(NativePRNG.java:272)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:522)

去查 NativePRNG$Blocking代码,看到它的文档描述:

A NativePRNG-like class that uses /dev/random for both seed and random material. Note that it does not respect the egd properties, since we have no way of knowing what those qualities are.

奇怪怎么-Djava.security.egd=file:/dev/./urandom参数没起作用,仍使用/dev/random作为随机数的熵池,时间久或调用频繁的话熵池很容易不够用而导致阻塞;于是看了一下 SecureRandom.getInstanceStrong()的文档:

Returns a SecureRandom object that was selected by using the algorithms/providers specified in the securerandom.strongAlgorithms Security property.

原来有自己的算法,在 jre/lib/security/java.security 文件里,默认定义为:

securerandom.strongAlgorithms=NativePRNGBlocking:SUN

如果修改算法值为NativePRNGNonBlocking:SUN的话,会采用NativePRNG$NonBlocking里的逻辑,用/dev/urandom作为熵池,不会遇到阻塞问题。但这个文件是jdk系统文件,修改它或重新指定一个路径都有些麻烦,最好能通过系统环境变量来设置,可这个变量不像securerandom.source属性可以通过系统环境变量-Djava.security.egd=xxx来配置,找半天就是没有对应的系统环境变量。只好修改代码,不采用SecureRandom.getInstanceStrong这个新方法,改成了SecureRandom.getInstance("NativePRNGNonBlocking")

对于SecureRandom的两种算法实现:SHA1PRNGNativePRNGsecurerandom.source 变量的关系,找到一篇解释的很清楚的文章:Using the SecureRandom Class

On Linux:

1) when this value is “file:/dev/urandom” then the NativePRNG algorithm is registered by the Sun crypto provider as the default implementation; the NativePRNG algorithm then reads from /dev/urandom for nextBytes but /dev/random for generateSeed

2) when this value is “file:/dev/random” then the NativePRNG algorithm is not registered by the Sun crypto provider, but the SHA1PRNG system uses a NativeSeedGenerator which reads from /dev/random.

3) when this value is anything else then the SHA1PRNG is used with a URLSeedGenerator that reads from that source.

4) when the value is undefined, then SHA1PRNG is used with ThreadedSeedGenerator

5) when the code explicitly asks for “SHA1PRNG” and the value is either “file:/dev/urandom” or “file:/dev/random” then (2) also occurs

6) when the code explicitly asks for “SHA1PRNG” and the value is some other “file:” url, then (3) occurs

7) when the code explicitly asks for “SHA1PRNG” and the value is undefined then (4) occurs

至于SHA1PRNG算法里,为何用urandom时,不能直接设置为file:/dev/urandom而要用变通的方式设置为file:///dev/urandom或者 file:/dev/./urandom,参考这里

In SHA1PRNG, there is a SeedGenerator which does various things depending on the configuration.

  1. If java.security.egd or securerandom.source point to “file:/dev/random” or “file:/dev/urandom”, we will use NativeSeedGenerator, which calls super() which calls SeedGenerator.URLSeedGenerator(/dev/random). (A nested class within SeedGenerator.) The only things that changed in this bug was that urandom will also trigger use of this code path.

  2. If those properties point to another URL that exists, we’ll initialize SeedGenerator.URLSeedGenerator(url). This is why “file:///dev/urandom”, “file:/./dev/random”, etc. will work.

一次编码问题的排查

上周遇到的一个问题,代码里有通过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等环境变量的关系后续有精力再整理)

用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里已经删除了这个类。

tomcat关闭应用时的清理工作(3): ThreadLocal

tomcat在关闭时,可能看到与ThreadLocal相关的警告:

Jan 24, 2014 7:18:52 AM org.apache.catalina.loader.WebappClassLoader checkThreadLocalMapForLeaks
SEVERE: The web application [] created a ThreadLocal with key of type 
[java.lang.ThreadLocal] (value [java.lang.ThreadLocal@4e61bc49]) and a value of type 
[com.alibaba.xxx.Entry] (value [...]) but failed to remove it when the web application was stopped. 
Threads are going to be renewed over time to try and avoid a probable memory leak.

用下面的例子来模拟一下

@WebServlet(name = "MainServlet", urlPatterns = { "/main" }, loadOnStartup = 1)
public class MainServlet extends HttpServlet {

    private static final long serialVersionUID = 1L;

    private static ThreadLocal<MyClass> tl = new ThreadLocal<MyClass>();

    public void doGet(HttpServletRequest req, HttpServletResponse resp)
            throws ServletException, IOException {

        MyClass m = tl.get();
        if (m == null) {
            tl.set(new MyClass());
        }
    }

}

class MyClass {}

请求一次之后,通过脚本会命令停止tomcat,会看到类似的日志:

七月 16, 2014 5:01:35 下午 org.apache.catalina.loader.WebappClassLoader checkThreadLocalMapForLeaks
严重: The web application [] created a ThreadLocal with key of type [java.lang.ThreadLocal] 
(value [java.lang.ThreadLocal@7da150]) and a value of type [org.r113.servlet3.MyClass] 
(value [org.r113.servlet3.MyClass@37e98b70]) but failed to remove it when the web application was stopped. 
Threads are going to be renewed over time to try and avoid a probable memory leak.

这个泄露其实是可能造成classloader的泄露,因为ThreadLocal引用了自定义的类MyClass,绑定到了当前的请求线程上,而请求线程又是线程池里的线程,生存周期可能会比较长。比如上面模拟的情况,要停止应用的时候,请求线程的ThreadLocal仍未释放,那么即使加载MyClass类的classLoader已经不会再被任何地方使用,可以被垃圾回收了,却因为这个MyClass被引用而得不到回收。

类初始化与并发问题

这个案例是2009年中文站线上曾发生过的事情,实际情况比较复杂,简化后我们可以用下面的例子做demo

// 定义一个锁对象
class Lock {} 

// 在这个类的静态构造块里做一些事情
class Danger {
    static {
        System.out.println("clinit begin...");
        try {
            Thread.sleep(2000);
        } catch (Exception e) {
        }

        synchronized (Lock.class) { 
            System.out.println("clinit done!");
        }
    } 
}

public class Test {
    public static void main(String[] args) {
        // 启动新线程
        new Thread() { 
            public void run() {
                synchronized (Lock.class) { 
                    System.out.println("new thread start!");
                    try {
                        Thread.sleep(1000);
                    } catch (Exception e) {
                    } 
                    new Danger();
                }
                System.out.println("new thread end!"); 

            }
        }.start();

        // 当前线程sleep 500毫秒
        try {
            Thread.sleep(500);
        } catch (Exception e) {
        } 
        // 当前线程创建了Danger对象实例
        System.out.println(new Danger()); 
        // 会走到这里吗?
        System.out.println("DONE!");
    } 
}

运行上面的程序时,java进程挂在那儿不动了,我们通过jstack去观察的话,它先给出死锁检查是没有找到:

Deadlock Detection:
No deadlocks found.

然后看看两个线程的堆栈信息:

Thread 17643: (state = BLOCKED)
    - Test$1.run() @bci=24, line=28 (Interpreted frame)

Thread 17634: (state = BLOCKED)
    - Danger.<clinit>() @bci=24, line=12 (Interpreted frame)
    - Test.main(java.lang.String[]) @bci=23, line=41 (Interpreted frame)

虽然jvm没有把这两个线程看做是死锁,但实际情况是和死锁类似的。在jvm的实现规范里:

当多个线程需要初始化一个类,仅有一个线程会进⾏,其他线程需要等待。当活动的线程完成初始化之后, 它必须通知其他等待线程

所以这个被hang住的问题简单来说就是:线程1持有了锁(Lock.class对象),然后sleep了一会儿;与此同时线程2创建Danger对象,在创建对象的过程中先进行类初始化,在类初始化过程中又因为需要获取锁(Lock.class对象)而等待线程1释放(Lock.class对象);在线程1睡醒了之后,也去创建Danger对象,同样,因为Danger对象当前的状态是处于类初始化进行中的状态,线程1要等待正在初始化Danger类的那个线程要先把类初始化完成才能构造对象。于是造成了相互等待的境况。

在以前的分享的jvm内存管理的ppt里曾提到过这个例子,也可以参考一下这个ppt

同事周忱 曾用pstack看过到底hang在什么地方,参考他的gist,在ubuntu上pstack不太好用,可以直接使用jstack -m来看

----------------- 17643 -----------------
0x00007f897f250d84  __pthread_cond_wait + 0xc4
0x00007f897ea5ec85  _ZN13ObjectMonitor4waitElbP6Thread + 0x785
0x00007f897e865c1b  _ZN13instanceKlass15initialize_implE19instanceKlassHandleP6Thread + 0x31b
0x00007f897e865f19  _ZN13instanceKlass10initializeEP6Thread + 0x49
0x00007f897e8999d4  _ZN18InterpreterRuntime4_newEP10JavaThreadP19constantPoolOopDesci + 0x214
0x00007f897501d98a  * Test$1.run() bci:24 line:28 (Interpreted frame)
0x00007f89750004f7  <StubRoutines>
0x00007f897e8a67bf  _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x54f
0x00007f897e8a5802  _ZN9JavaCalls12call_virtualEP9JavaValue11KlassHandleP6SymbolS4_P17JavaCallArgumentsP6Thread + 0x1c2
0x00007f897e8a585f  _ZN9JavaCalls12call_virtualEP9JavaValue6Handle11KlassHandleP6SymbolS5_P6Thread + 0x4f
0x00007f897e8dcfc6  _ZL12thread_entryP10JavaThreadP6Thread + 0x86
0x00007f897eb8bfc0  _ZN10JavaThread17thread_main_innerEv + 0xc0
0x00007f897ea69ec2  _ZL10java_startP6Thread + 0x132

----------------- 17634 -----------------
0x00007f897f2510fe  __pthread_cond_timedwait + 0x13e
0x00007f897ea5d004  _ZN13ObjectMonitor6EnterIEP6Thread + 0x294
0x00007f897ea5de87  _ZN13ObjectMonitor5enterEP6Thread + 0x297
0x00007f897e89ced9  _ZN18InterpreterRuntime12monitorenterEP10JavaThreadP15BasicObjectLock + 0x99
0x00007f897501e299  * Danger.<clinit>() bci:24 line:12 (Interpreted frame)
0x00007f89750004f7  <StubRoutines>
0x00007f897e8a67bf  _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x54f
0x00007f897e8a6055  _ZN9JavaCalls4callEP9JavaValue12methodHandleP17JavaCallArgumentsP6Thread + 0x25
0x00007f897e8658ac  _ZN13instanceKlass27call_class_initializer_implE19instanceKlassHandleP6Thread + 0xbc
0x00007f897e8658f5  _ZN13instanceKlass22call_class_initializerEP6Thread + 0x25
0x00007f897e865a9f  _ZN13instanceKlass15initialize_implE19instanceKlassHandleP6Thread + 0x19f
0x00007f897e865f19  _ZN13instanceKlass10initializeEP6Thread + 0x49
0x00007f897e8999d4  _ZN18InterpreterRuntime4_newEP10JavaThreadP19constantPoolOopDesci + 0x214
0x00007f897501d998  * Test.main(java.lang.String[]) bci:23 line:41 (Interpreted frame)
0x00007f89750004f7  <StubRoutines>
0x00007f897e8a67bf  _ZN9JavaCalls11call_helperEP9JavaValueP12methodHandleP17JavaCallArgumentsP6Thread + 0x54f
0x00007f897e8a6055  _ZN9JavaCalls4callEP9JavaValue12methodHandleP17JavaCallArgumentsP6Thread + 0x25
0x00007f897e8b27de  _ZL17jni_invoke_staticP7JNIEnv_P9JavaValueP8_jobject11JNICallTypeP10_jmethodIDP18JNI_ArgumentPusherP6Thread.isra.126.constprop.151 + 0x1ce
0x00007f897e8bae80  jni_CallStaticVoidMethod + 0x160
0x00007f897fa27f7b      ????????

效果不如pstack那么直观,但也可以发现instanceKlass::initialize_impl和ObjectSynchronizer::waitUninterruptibly方法,由此线索可再结合jvm代码进一步深究。

JVM上的随机数与熵池策略

在apache-tomcat官方文档:如何让tomcat启动更快 里面提到了一些启动时的优化项,其中一项是关于随机数生成时,采用的“熵源”(entropy source)的策略。

他提到tomcat7的session id的生成主要通过java.security.SecureRandom生成随机数来实现,随机数算法使用的是”SHA1PRNG”

private String secureRandomAlgorithm = "SHA1PRNG";

在sun/oracle的jdk里,这个算法的提供者在底层依赖到操作系统提供的随机数据,在linux上,与之相关的是/dev/random/dev/urandom,对于这两个设备块的描述以前也见过讨论随机数的文章,wiki中有比较详细的描述,摘抄过来,先看/dev/random

在读取时,/dev/random设备会返回小于熵池噪声总数的随机字节。/dev/random可生成高随机性的公钥或一次性密码本。若熵池空了,对/dev/random的读操作将会被阻塞,直到收集到了足够的环境噪声为止

/dev/urandom 则是一个非阻塞的发生器:

dev/random的一个副本是/dev/urandom (”unlocked”,非阻塞的随机数发生器),它会重复使用熵池中的数据以产生伪随机数据。这表示对/dev/urandom的读取操作不会产生阻塞,但其输出的熵可能小于/dev/random的。它可以作为生成较低强度密码的伪随机数生成器,不建议用于生成高强度长期密码。

另外wiki里也提到了为什么linux内核里的随机数生成器采用SHA1散列算法而非加密算法,是为了避开法律风险(密码出口限制)。

回到tomcat文档里的建议,采用非阻塞的熵源(entropy source),通过java系统属性来设置:

-Djava.security.egd=file:/dev/./urandom

这个系统属性egd表示熵收集守护进程(entropy gathering daemon),但这里值为何要在devrandom之间加一个点呢?是因为一个jdk的bug,在这个bug的连接里有人反馈及时对 securerandom.source 设置为 /dev/urandom 它也仍然使用的 /dev/random,有人提供了变通的解决方法,其中一个变通的做法是对securerandom.source设置为 /dev/./urandom 才行。也有人评论说这个不是bug,是有意为之。

我看了一下我当前所用的jdk7的java.security文件里,配置里仍使用的是/dev/urandom

#
# Select the source of seed data for SecureRandom. By default an
# attempt is made to use the entropy gathering device specified by
# the securerandom.source property. If an exception occurs when
# accessing the URL then the traditional system/thread activity
# algorithm is used.
#
# On Solaris and Linux systems, if file:/dev/urandom is specified and it
# exists, a special SecureRandom implementation is activated by default.
# This "NativePRNG" reads random bytes directly from /dev/urandom.
#
# On Windows systems, the URLs file:/dev/random and file:/dev/urandom
# enables use of the Microsoft CryptoAPI seed functionality.
#
securerandom.source=file:/dev/urandom

我不确定jdk7里,这个 /dev/urandom 也同那个bug报告里所说的等同于 /dev/random;要使用非阻塞的熵池,这里还是要修改为/dev/./urandom 呢,还是jdk7已经修复了这个问题,就是同注释里的意思,只好验证一下。

使用bug报告里给出的代码:

import java.security.SecureRandom;
class JRand {
    public static void main(String args[]) throws Exception {
        System.out.println("Ok: " +
            SecureRandom.getInstance("SHA1PRNG").nextLong());
    }
}

然后设置不同的系统属性来验证,先是在我的mac上:

% time java -Djava.security.egd=file:/dev/urandom  JRand
Ok: 8609191756834777000
java -Djava.security.egd=file:/dev/urandom JRand  
0.11s user 0.03s system 115% cpu 0.117 total

% time java -Djava.security.egd=file:/dev/./urandom  JRand
Ok: -3573266464480299009
java -Djava.security.egd=file:/dev/./urandom JRand  
0.11s user 0.03s system 116% cpu 0.116 total

可以看到/dev/urandom/dev/./urandom 的执行时间差不多,有点纳闷,再仔细看一下wiki里说的:

FreeBSD操作系统实现了256位的Yarrow算法变体,以提供伪随机数流。与Linux的/dev/random不同,FreeBSD的/dev/random不会产生阻塞,与Linux的/dev/urandom相似,提供了密码学安全的伪随机数发生器,而不是基于熵池。而FreeBSD的/dev/urandom则只是简单的链接到了/dev/random。

尽管在我的mac上/dev/urandom并不是/dev/random的链接,但mac与bsd内核应该是相近的,/dev/random也是非阻塞的,/dev/urandom是用来兼容linux系统的,这两个随机数生成器的行为是一致的。参考这里

然后再到一台ubuntu系统上测试:

% time java -Djava.security.egd=file:/dev/urandom  JRand
Ok: 6677107889555365492
java -Djava.security.egd=file:/dev/urandom JRand  
0.14s user 0.02s system 9% cpu 1.661 total

% time java -Djava.security.egd=file:/dev/./urandom  JRand
Ok: 5008413661952823775
java -Djava.security.egd=file:/dev/./urandom JRand  
0.12s user 0.02s system 99% cpu 0.145 total

这回差异就完全体现出来了,阻塞模式的熵池耗时用了1.6秒,而非阻塞模式则只用了0.14秒,差了一个数量级,当然代价是转换为对cpu的开销了。

// 补充,连续在ubuntu上测试几次/dev/random方式之后,导致熵池被用空,被阻塞了60秒左右。应用服务器端要避免这种方式。

tomcat每隔一小时full gc的问题

关于gc信息的收集,除了在启动时设置gclog选项,对于已经启动的java进程,也可以通过jstat去查看gc发生的原因。

$ jstat -gccause  java_pid 1s

S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
0.00 100.00  31.17  74.24  98.80      7    0.045     1    0.176    0.221 Allocation Failure   No GC
0.00 100.00  32.61  74.24  98.83      7    0.045     1    0.176    0.221 Allocation Failure   No GC
73.65   0.00  0.00  74.24  99.73      8    0.052     2    0.176    0.228 No GC      System.gc()
0.00   0.00   1.44  87.57  65.40      8    0.052     2    0.395    0.447 System.gc()          No GC
0.00   0.00   1.44  87.57  65.40      8    0.052     2    0.395    0.447 System.gc()          No GC
0.00   0.00   1.44  87.57  65.40      8    0.052     2    0.395    0.447 System.gc()          No GC

有一些应用周期性的发生full gc,即使没有多大访问量的情况,在tomcat里可能有2种原因:

1) 预防内存泄露的监听器 JreMemoryLeakPreventionListener 每隔一小时触发一次System.gc

Class clazz = Class.forName("sun.misc.GC");
Method method = clazz.getDeclaredMethod(
                        "requestLatency",
                        new Class[] {long.class});
method.invoke(null, Long.valueOf(3600000)); // 一小时

去看sun.misc.GCrequestLatency方法,传入的参数表示一次gc请求的延迟时间。会有个低优先级的daemon线程设置一个不超过这个延迟时间的object-inspection的周期

/**
 * Makes a new request for a garbage-collection latency of the given
 * number of real-time milliseconds.  A low-priority daemon thread makes a
 * best effort to ensure that the maximum object-inspection age never
 * exceeds the smallest of the currently active requests.
 *
 * @param   latency
 *          The requested latency
 *
 * @throws  IllegalArgumentException
 *          If the given <code>latency</code> is non-positive
 */
public static LatencyRequest requestLatency(long latency) {
    return new LatencyRequest(latency);
}

Daemon线程里,会在object-inspection周期之后执行System.gc()的。在tomcat 7028 和 6036 之后的版本里,把延迟时间调整了,不会再每小时调用一次了:

method.invoke(null, Long.valueOf(Long.MAX_VALUE - 1));

2) rmi.dgc 在JDK6里默认是1小时

参考这里,可以通过系统参数修改:

-Dsun.rmi.dgc.client.gcInterval=72000000
-Dsun.rmi.dgc.server.gcInterval=72000000

java nio channel抛出ClosedByInterruptException的情况

java nio里的channel是实现自InterruptibleChannel接口的,这个接口的注释里有说明,当正在操作这个channel的线程被其他线程中断,则会close这个channel,当前(被中断的)线程抛出一个ClosedByInterruptException异常。

我们今天在排查一个问题时,用户线程执行了下面的调用过程(从上往下):

org.apache.catalina.connector.CoyoteOutputStream.flush ---》
org.apache.tomcat.util.net.NioChannel.write ---》
sun.nio.ch.SocketChannelImpl.write ---》
java.nio.channels.spi.AbstractInterruptibleChannel.end  // 这里抛出异常

来看一下这个sun.nio.ch.SocketChannelImpl.write 方法内部,它的详细代码可以看这里) 这里简化一些:

 public int  write(ByteBuffer buf) throws IOException {
  ...
  synchronized (writeLock) {
      ...
      try {
          begin();
          ...
      } finally {
          ...
          end(n > 0 || (n == IOStatus.UNAVAILABLE));
          ...
      }
  }
}

主要看一下它里面的beginend,先看end方法,异常抛出的地方:

protected final void end(boolean completed)
    throws AsynchronousCloseException
{
    blockedOn(null);
    Thread interrupted = this.interrupted;
    if (interrupted != null && interrupted == Thread.currentThread()) {
        interrupted = null;
        throw new ClosedByInterruptException();  
    }
    if (!completed && !open)
        throw new AsynchronousCloseException();
}

可以看到ClosedByInterruptException异常抛出的前提是当前线程被标记为已中断的;而这个判断是在begin方法里做的:

protected final void begin() {
    if (interruptor == null) {
        interruptor = new Interruptible() {
                public void interrupt(Thread target) {
                    synchronized (closeLock) {
                        if (!open)
                            return;
                        open = false;
                        interrupted = target;
                        try {
                            AbstractInterruptibleChannel.this.implCloseChannel();
                        } catch (IOException x) { }
                    }
                }};
    }
    blockedOn(interruptor);
    Thread me = Thread.currentThread();
    if (me.isInterrupted()) // 检测当前线程是否已中断
        interruptor.interrupt(me);
}

begin方法里,检查当前线程如果是中断状态,用引用记录起来(为了后边比较使用),并关闭了channel。

现在用scala模拟一下这个异常:

$ cat server

import java.nio._
import java.net._
import java.nio.channels._

val serverSock = ServerSocketChannel.open()
serverSock.socket().bind(new InetSocketAddress(54321))

val  ch:SocketChannel = serverSock.accept()

println("ok,received")

Thread.currentThread().interrupt() //中断当前线程
try{
    ch.socket().getOutputStream().write(200)
}catch{
    case e:Throwable => println(e)
}

上面的这段脚本,用nio模拟了一个server等待客户端的链接,当链接过来的时候,中断当前线程,然后继续channel进行处理的时候会捕获到ClosedByInterruptException异常。

启动上面的脚本

$ scala server

在另一个终端下模拟一次client请求:

$ telnet localhost 54321

这时会看到server端的输出信息:

$ scala server
ok,received
java.nio.channels.ClosedByInterruptException

java可以创建多少个线程

记得以前在jvm的群里讨论过,与系统环境设置有关,我在mac os上试验的。

% sysctl kern.num_taskthreads  
kern.num_taskthreads: 2048

用repl来模拟一下,在启动repl后线程大概有20个左右,现在看看还可以启动多少个线程:

scala> import java.util.concurrent.atomic.AtomicInteger

scala> val n = new AtomicInteger(0)

scala> val run = new Runnable(){
        override def run() { n.incrementAndGet ;Thread.sleep(1000000) }}

scala> try{ while(true){ val t = new Thread(run); t.start } } catch{
            case e:Throwable => println("count: " + n.get) 
        }
count: 2025

运行过程中jvm可能还有其他线程也会启动,总的线程数加起来正好2048(或者接近).

如果系统参数设置一个很大的值,那java可创建的线程数就只与内存相关了。

如果指定的-Xss越大,java进程在non-heap区域为每个线程分配的初始也越大。栈空间分配的初始值通常比Xss设定的要小,VM并不会一上来就分配与之对等的内存。

另外一点有趣的是,如果你分配给jvm的堆空间(heap size)太大,系统中如果没有足够多的剩余空间的话,non-heap可分配的就越小,可创建的线程数也反而少了。也就是说heap与non-heap是竞争关系。参考这里

二月份杭州GreenTea JUG的收获

5.25号的greentea活动有事没去参加,这是2月份那次greentea杭州的活动记录,当时有两个会场,只听了一个会场的。

昨天下午去华星时代广场参加了greentea java用户组,听了周忱的《java程序员也要懂cpu》
莫枢的《Intrinsic Methods in Hotspot VM》,以及王铮的《有关jvm profile的工作》还是很有收获的。
因为相对偏底层,平时不太涉及,尤其王铮的分享,传递了一个观念,硬件的设计与软件是很有差异的;在软件中的性能问题在硬件中或许根本不存在,硬件天生是并行的,软件则是串行的。

Intrinsic方法简单的说就是jvm对某些声明为了intrinsic的方法进行特殊的处理,不按照java里提供的代码逻辑或者jni里的实现,而是按照特定平台优化后的指令来处理,比如System.arraycopy 虽然声明为native(让人误以为可能比java实现更慢),但实际它是一个intrinsic的方法,它实际比你自己在java中来实现数组拷贝要更高效的。甚至在vm里用同样的实现逻辑,被标记为intrinsic的也依然可能比未标记intrinsic的要高效。

jdk中有哪些Intrinsic方法,可以在vmSymbols文件里找到,但温绍说他测试某些intrinsic的方法反而慢了
这个需要在特定的平台,特定的cpu,需要几个条件都符合,而目前并没有每个版本的jdk中哪些intrinsic的详尽描述的文档。

莫枢除了对Intrinsic方法的介绍,还回答了一下避免让两个数据在同一个cache line在java8里的实现:采用
@Contented 注释来避免false sharing的问题,不必在程序中写丑陋的padding 变量来实现了。

另外对Hotspot去除permgen的进度,需要到java8才会去除了。还纠正了我对hotspot jdk7中String.intern一个误区;String.intern 并不是直接存放在老生代,是在heap中,依然会经过新生代到老生代的过程,在young gc后才移到老生代。这也是对permgen移除的一部分工作,在jdk7里先release了这部分。

莫枢还演示了一个工具CLHSDB,除了普通的定位内存地址,还可以采用js来实现扩展它的命令。