漂亮的代码,糟糕的行为——解决Java运行时的内存问题

我们的一个程序,假设名字为“Photo Pull”,主要解决以下问题:

  • 从各种第三方来源上获取联系人照片
  • 将照片重新调整至所需的缩略图大小
  • 将结果发送到S3

看起来似乎这个程序能够理所当然的稳定运行.但事实刚好与之相反,这是我们最容易出问题的程序之一——不是因为代码有问题,而是Java运行时会导致问题。

漂亮的代码, 糟糕的行为

我们遇到的第一个问题是Photo Pull运行后内存占用量持续增大。几个小时后,这个进程将消耗掉系统的所有内存,直到被Linux OOM-killer杀掉或被Storm重启。

常用的Java内存使用诊断工具起不了什么作用。所有我们了解到的是,非堆内存存在大量泄露,而堆内存保持在几百MB。

然而,有一个统计学的方法来确定内存泄露的原因。导致内存泄露的组件也会使内存占用量超过任意一个阈值。如果我们在堆栈中多次跟踪anOutOfMemoryError 错误,我们就有很大可能确定内存泄露的原因。现在唯一的问题是,这个进程不能自己发现内存被耗尽,只有被Linux杀死时才知道。

这个问题的解决方法是使用ulimit命令来为该程序设置一个内存使用上限,这个上限值要显著低于系统内存,例如:

ulimit -m $((1024*1024))

该命令是在FreeBSD系统上将程序使用内存限制为1G以内。内存使用上限设置完成后,让程序运行一段时间,直到崩溃。

通过堆栈跟踪,我们发现一个本地栈帧:

com.sun.imageio.plugins.jpeg.JPEGImageReader.initJPEGImageReader()

该函数是在jdk/src/share/native/sun/awt/image/jpeg/imageioJPEG.c文件中,属于OpenJDK 6源代码。简单查看一下,发现如下问题:

/* ... snip to line 1450 */
    /* We use our private extension JPEG error handler.
     */
    jerr = malloc (sizeof(struct sun_jpeg_error_mgr));

    /* ... snip to line 1476 */

    /* Establish the setjmp return context for sun_jpeg_error_exit to use. */
    if (setjmp(jerr->setjmp_buffer)) {
        /* If we get here, the JPEG code has signaled an error. */
        char buffer[JMSG_LENGTH_MAX];
        (*cinfo->err->format_message) ((struct jpeg_common_struct *) cinfo,
                                      buffer);
        JNU_ThrowByName(env, "javax/imageio/IIOException", buffer);
        return 0;
    }

在1452行C代码给一个错误的handler分配了空间,但之后一直没有释放,导致抛出IIOException异常.目前还不清楚cinfo是否也存在泄露。

检查OpenJDK 7中的同一个文件,发现bug只存在于OpenJDK 6中。将代码移植到Java 7中,运行了几个小时后没有发现内存泄露。

分段查找错误

在发现内存泄漏原因几个小时后,程序的一个组件崩溃了,过了一会儿另外一个也崩溃了。Storm尽职尽责地重新启动它们,但是没有找到组件为什么被杀死的信息——没有日志记录,没有内存增长,也没有迹象表明是被Storm杀死。我们重新在本地运行程序,最终获得如下信息:

# A fatal error has been detected by the Java Runtime Environment:
#
# SIGSEGV (0xb) at pc=0x00007fb120713242, pid=11629, tid=140394149959424
#
# JRE version: 7.0_25-b15
# Java VM: Java HotSpot(TM) 64-Bit Server VM (23.25-b01 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# C [libpthread.so.0+0xe242] sem_post+0x12

由此产生的hs_err_pid*.log文件缺乏Java堆栈跟踪,而由JVM产生的堆栈转储只包含最底层的框架。尽管如此,我们开始查找引起POSIX线程库触发段错误的条件.向sem_post传递18字节的信号量,得到如下内容:

    e230: mov    eax,DWORD PTR [rdi]
    e232: cmp    eax,0x7fffffff
    e237: je     e26c <sem_post+0x3c>
    e239: lea    esi,[rax+0x1]
    e23c: lock cmpxchg DWORD PTR [rdi],esi
    e240: jne    e232 <sem_post+0x2>
    e242: cmp    QWORD PTR [rdi+0x8],0x0        # Here
    e247: je     e262 <sem_post+0x32>
    e249: mov    eax,0xca
    e24e: mov    esi,0x1
    e253: or     esi,DWORD PTR [rdi+0x4]
    e256: mov    edx,0x1
    e25b: syscall
    e25d: test   rax,rax
    e260: js     e265 <sem_post+0x35>
    e262: xor    eax,eax
    e264: ret
    e265: mov    eax,0x16
    e26a: jmp    e271 <sem_post+0x41>
    e26c: mov    eax,0x4b
    e271: mov    rdx,QWORD PTR [rip+0x209d08]
    e278: mov    DWORD PTR fs:[rdx],eax
    e27b: or     eax,0xffffffff
    e27e: ret

这一失败本身,是相当令人吃惊的.只有早期在e230处有几个指令访问rdi寄存器成功,即使只有8个字节数据在内存中。但JVM将rdi寄存器放置在0x00007fb11046e000。 添加八个字节不可能跨越页边界。 幸运的是,JVM转储也给了我们一个内存映射。事实证明,这个内存地址指向到一个本地共享库:

7fb11046d000-7fb11046e000 rw-p 00007000 ca:01 77 /lib/x86_64-linux-gnu/libnss_dns-2.15.so
7fb11046f000-7fb110473000 r--s 0008a000 ca:01 396307 /opt/jdk1.7.0/jre/lib/jsse.jar

rdi指向内存映射中有缺陷一页的起始位置。这表明在e230执行时存在的一些内容在e242执行时被释放。

但也有可能是调用者不打算使用这个地址,我们注意到rdi恰好是当前堆栈帧之上大约2^32个字节处。但是,我们仍然不知道问题出在哪里。

在重现程序崩溃10次后,我们得到了一个稍微不同的情况。再一次,我们得到一个指向POSIX线程函数的垃圾指针。 但是这一次,我们也从转储中得到了一个Java堆栈跟踪。

事实证明,JRE的代码只是委托给libccm,就像用一个婴儿车去当成汽车使用。它会破坏POSIX线程,或者导致JVM持续的占用内存。

我们如何处理

最终的解决方案远没有查找问题原因本身让人感到兴奋。我们发现使用Apache Commons Imaging图像处理类库代替Java ImageIO库就可以解决问题。 但是,一般来说,解决一个复杂的问题的时候,分析问题往往比修复问题花费更多的时间和精力。

原文链接: fullcontact 翻译: ImportNew.com - norwind
译文链接: http://www.importnew.com/10163.html
[ 转载请保留原文出处、译者和译文链接。]

关于作者: norwind

(新浪微博:@norwindnew

查看norwind的更多文章 >>



相关文章

发表评论

Comment form

(*) 表示必填项

1 条评论

  1. www.rebelmouse.com 说道:

    These shampoos have been designed to work on oily skins
    and the zinc is very good at fighting acne disorder.

    Thumb up 0 Thumb down 0

跳到底部
返回顶部