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

我们的一个程序 假设名字为 Photo Pull 主要解决以下问题 从各种第三方来源上获取联系人照片 将照片重新调整至所需的缩略图大小 将结果发送到 S3 看起来似乎这个程序能够理所当然的稳定运行 但事实刚好与之相反 这是我们最容易出问题的程序 之一 不是因为代码有问题 而是 Java 运行时会导致问题 漂亮的代码 糟糕的行为 我们遇到的第一个问题是 Photo Pull 运行后内存占用量持续增大 几个小时后 这个进程将消耗掉 系统的所有内存 直到被 Linux OOM killer 杀掉或被 Storm 重启 常用的 Java 内存使用诊断工具起不了什么作用 所有我们了解到的是 非堆内存存在大量泄露 而 堆内存保持在几百 MB 然而 有一个统计学的方法来确定内存泄露的原因 导致内存泄露的组件也会使内存占用量超过任 意一个阈值 如果我们在堆栈中多次跟踪 anOutOfMemoryError 错误 我们就有很大可能确定内 存泄露的原因 现在唯一的问题是 这个进程不能自己发现内存被耗尽 只有被 Linux 杀死时才知 道 这个问题的解决方法是使用 ulimit 命令来为该程序设置一个内存使用上限 这个上限值要显著低于 系统内存 例如 1 ulimit m 1024 1024 该命令是在 FreeBSD 系统上将程序使用内存限制为 1G 以内 内存使用上限设置完成后 让程序运 行一段时间 直到崩溃 通过堆栈跟踪 我们发现一个本地栈帧 1 com sun imageio plugins jpeg JPEGImageReader initJPEGImageReader 该函数是在 jdk src share native sun awt image jpeg imageioJPEG c 文件中 属于 OpenJDK 6 源代码 简单查看一下 发现如下问题 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 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 杀死 我们重新在本地运行程序 最终获得如下信息 1 2 3 4 5 6 7 8 A fatal error has been detected by the Java Runtime Environment SIGSEGV 0 xb at pc 0 x00007fb120713242 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 0 xe242 sem post 0 x12 由此产生的 hs err pid log 文件缺乏 Java 堆栈跟踪 而由 JVM 产生的堆栈转储只包含最底层的框 架 尽管如此 我们开始查找引起 POSIX 线程库触发段错误的条件 向 sem post 传递 18 字节的信 号量 得到如下内容 1 2 3 4 5 6 7 8 9 10 11 12 13 e230 mov eax DWORD PTR rdi e232 cmp eax 0 x7fffffff e237 je e26c e239 lea esi rax 0 x1 e23c lock cmpxchg DWORD PTR rdi esi e240 jne e232 e242 cmp QWORD PTR rdi 0 x8 0 x0 Here e247 je e262 e249 mov eax 0 xca e24e mov esi 0 x1 e253 or esi DWORD PTR rdi 0 x4 e256 mov edx 0 x1 e25b syscall e25d test rax rax e260 js e265 e262 xor eax eax e264 ret e265 mov eax 0 x16 e26a jmp e271 14 15 16 17 18 19 20 21 22 23 24 e26c mov eax 0 x4b e271 mov rdx QWORD PTR rip 0 x209d08 e278 mov DWORD PTR fs rdx eax e27b or eax 0 xffffffff e27e ret 这一失败本身 是相当令人吃惊的 只有早期在 e230 处有几个指令访问 rdi 寄存器成功 即使只有 8 个字节数据在内存中 但 JVM 将 rdi 寄存器放置在 0 x00007fb11046e000 添加八个字节不可 能跨越页边界 幸运的是 JVM 转储也给了我们一个内存映射 事实证明 这个内存地址指向到 一个本地共享库 1 2 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 就像用一个婴儿车去当成汽车使用 它会