导读
本文介绍 Java 诸多优化实例: 第一, 排查堆上, 堆外内存泄露; 第二, 使用 arthas,jaeger,tcpdump,jstack 做性能优化; 第三, 排查进程异常退出的原因, 如被杀, System.exit,Java 调用的 C++ 发生 Crash,Java 内 Crash; 第四, 排查死锁的原因, 如 log4j 死锁, 封装不严谨导致的死锁
内存泄漏
内存泄露在 C++ 里排查很简单, 用钩子函数勾住内存分配和释放函数 malloc 和 free, 统计哪些 malloc 的内存没有 free, 就可以找出内存泄露的源头. 但在 Java 里问题复杂的多, 主要因为 Java 在内存之上有层 JVM 管理内存.
JVM 先从操作系统申请大内存, 接着自己管理这部分内存. 所以 Java 程序的内存泄露分为两种: 堆上内存泄露, 堆外内存泄露, 而堆外内存泄露又分为两种: Java 使用堆外内存导致的内存泄露, Java 程序使用 C++ 导致的内存泄露.
分析内存泄露首先需要确认是堆上泄漏还是堆外泄露. 可以通过 jmap -heap pid 确认, 如下图所示, 老年代 PS Old Generation 使用率占 99.99%, 再结合 gc log, 如果老年代回收不掉, 基本确认为堆上内存泄露, 也不排除进程本身需要这么多内存, 此时需要分析堆. 而堆外内存泄露的显著表现是 top 命令查出来的物理内存显著比通过 xmx 配置的最大内存大.
堆上内存泄漏
堆上内存泄露是最常见的, 申请的对象引用和内存全在 JVM 堆上, 而对象使用完后, 对象引用被其他长生命周期的对象一直拿着, 导致无法从堆上释放. 首先用 jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}, 导出堆里所有活着的对象. 然后用工具分析 heap.hprof.
分析堆上内存泄露的主流工具有两种: JDK 自带的 bin 目录下的 jvisualvm.exe,Eclipse 的 MemoryAnalyzer.MemoryAnalyzer 更强大, 可自动分析可疑的内存泄露. 使用 MemoryAnalyzer 时, 需要在 MemoryAnalyzer.INI 里通过 - Xmx 参数配置最大内存, 否则无法打开大堆. 接下来介绍堆上内存泄露的若干实例.
对象被静态对象引用
使用 MemoryAnalyzer 自动分析内存泄露, 报告如下, 可以看到 RaftServerMetrics 占了 44.68% 的内存, 所有实例大小 98M 内存, 且所有的 RaftServerMetrics 实例被一个 ConcurrentHashMap 引用.
接着在直方图里过滤 RaftServerMetrics, 共找到 2065 个实例.
然后右键 RaftServerMetrics->Merge shortest path to GC Roots ->with all references 查找所有引用 RaftServerMetrics 的地方, 结果如下, 可看到所有的 RaftServerMetrics 实例被变量 metricsMap 引用, 问题原因是 RaftServerMetrics 使用完后, 未从静态变量 metricsMap 里删除.
RPC 连接使用完后未关闭
MemoryAnalyzer 自动分析内存泄露时, 有时并不能准确的找到, 此时需要自己分析哪些对象占用内存过多. 下图是使用 jvisualvm.exe 打开堆的结果, 查看数目或者内存异常的对象, 可以看到很多对象数目都是 111580 个, 且最后一列显示的内存占用大, 从对象的包分析, 都和 netty 有关, 且是 client 相关的对象, 基本确认这些对象和内存泄露有关. 进一步分析代码, 发现大量 RPC 连接使用完后未关闭.
堆外内存泄露
Java 使用堆外内存
JDK 提供绕过 JVM 直接在操作系统申请内存的接口, 例如通过 Unsafe 类的 allocateMemory,freeMemory 直接分配, 释放内存, 内存对象的引用在堆上, 但内存在堆外. 排查此类内存泄露, 首先开启:
-XX:NativeMemoryTracking=detail
然后 jcmd pid VM.native_memory detail, 打出内存分配信息, 注意 NativeMemoryTracking 显示的内存不包含 C++ 分配的内存. 此处需要关注两个点, 第一, Total 行的 committed 数值是否等于进程占用的物理内存, 如果不等, 说明有 C++ 等 native code 分配的内存, 可参考 Java 调用 C++ 组件 分析; 第二, Native Memory Tracking 的 committed 数值是否过大, 如果过大, 说明有 Unsafe.allocateMemory 分配了太多内存.
Unsafe.allocateMemory 的使用场景有两个: 第一, 封装在 DirectByteBuffer 内; 第二, 业务直接使用 Unsafe.allocateMemory.
DirectByteBuff 通常被用于通信框架如 netty 中, 不仅可以减少 GC 压力, 而且避免 IO 操作时将对象从堆上拷贝到堆外. 为了快速验证是否 DirectByteBuffer 导致内存泄露, 可使用参数 - XX:MaxDirectMemorySize 限制 DirectByteBuffer 分配的堆外内存大小, 如果堆外内存仍然大于 MaxDirectMemorySize, 可基本排除 DirectByteBuffer 导致的内存泄露.
分析 DirectByteBuffer 的内存首先可用 Java Mission Control, 绑定到进程, 并查看 DirectByteBuffer 占的内存如 2.24GB. 此处也可直接用 MemoryAnalyzer 打开 dump 的堆, 统计所有 DirectByteBuffer 的 capacity 之和, 计算 DirectByteBuffer 申请的堆外内存大小.
然后用命令 jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}, 导出堆里所有活着的对象, 并用 MemoryAnalyzer 打开 dump 的堆, 分析所有的 DirectByteBuffe:Merge shortest path to GC Roots ->with all references.
如果排除 DirectByteBuffer, 那就是应用程序直接用 Unsafe 类的 allocateMemory 分配的内存, 例如 Spark 的 off heap memory[1]. 此时可排查代码所有 Unsafe.allocateMemory 的地方.
Java 调用 C++ 组件
例如 RocksDB 采用 C++ 实现, 并通过 JNI 提供给 Java 调用的接口, 如果 Java 通过 JNI 创建了新的 RocksDB 实例, RocksDB 会启动若干后台线程申请, 释放内存, 这部分内存都对 Java 不可见, 如果发生泄漏, 也无法通过 dump jvm 堆分析.
分析工具可采用 google 的 gperftools, 也可用 jemalloc, 本文采用 jemalloc, 首先安装 jemalloc 到 / usr/local/lib/libjemalloc.so.
Git clone https://github.com/jemalloc/jemalloc.gitgit checkout 5.2.1./configure --enable-prof --enable-stats --enable-debug --enable-fillmake && make install
然后在进程启动脚本里, 添加如下命令, LD_PRELOAD 表示 JVM 申请内存时不再用 glibc 的 ptmalloc, 而是使用 jemalloc.MALLOC_CONF 的 lg_prof_interval 表示每次申请 2^30Byte 时生成一个 heap 文件.
- <span style="font-size: 16px;">
- export LD_PRELOAD=/usr/local/lib/libjemalloc.so
- </span>
- <span style="font-size: 16px;">
- export MALLOC_CONF=prof:true,lg_prof_interval:30
- </span>
并在进程的启动命令里添加参数 - XX:+PreserveFramePointer. 进程启动后, 随着不断申请内存, 会生成很多 dump 文件, 可把所有 dump 文件通过命令一起分析: jeprof --show_bytes --PDF jdk/bin/java *.heap> leak.PDF.
leak.PDF 如下所示, 可看到所有申请内存的路径, 进程共申请过 88G 内存, 而 RocksDB 申请了 74.2% 的内存, 基本确定是不正常的行为, 排查发现不断创建新的 RocksDB 实例, 共 1024 个, 每个实例都在运行, 优化方法是合并 RocksDB 实例.
需要注意的是, 88G 是所有申请过的内存, 包含申请但已经被释放的, 因此通过该方法, 大部分情况下能确定泄露源头, 但并不十分准确, 准确的方法是在 C++ 代码里用钩子函数勾住 malloc 和 free, 记录哪些内存未被释放.
性能优化
arthas
perf 是最为普遍的性能分析工具, 在 Java 里可采用阿里的工具 arthas 进行 perf, 并生成火焰图, 该工具可在 docker 容器内使用, 而系统 perf 命令在容器里使用有诸多限制.
下载 arthas-bin.zip[2], 运行./a.sh, 然后绑定到对应的进程, 开始 perf: profiler start, 采样一段时间后, 停止 perf: profiler stop. 结果如下所示, 可看到 getServiceList 耗了 63.75% 的 CPU.
另外, 常用优化小建议: 热点函数避免使用 lambda 表达式如 stream.collect 等, 热点函数避免使用正则表达式, 避免把 UUID 转成 String 在协议里传输等.
jaeger
perf 适用于查找整个程序的热点函数, 但不适用于分析单次 RPC 调用的耗时分布, 此时就需要 jaeger.
jaeger 是 Uber 开源的一个基于 Go 的分布式追踪系统. jaeger 基本原理是: 用户在自己代码里插桩, 并上报给 jaeger,jaeger 汇总流程并在 UI 显示. 非生产环境可安装 jaeger-all-in-one[3], 数据都在内存里, 有内存溢出的风险. 在需要追踪的服务的启动脚本里 export JAEGER_AGENT_HOST={jaeger 服务所在的 host}.
下图为 jaeger 的 UI, 显示一次完整的流程, 左边为具体的插桩名称, 右边为每块插装代码耗时, 可以看到最耗时的部分在 including leader create container 和 including follower create container, 这部分语义是 leader 创建完 container 后, 两个 follower 才开始创建 container, 而创建 container 非常耗时, 如果改成 leader 和两个 follower 同时创建 container, 则时间减少一半.
tcpdump
tcpdump 常用来抓包分析, 但也能用来优化性能. 在我们的场景中, 部署 Ozone 集群(下一代分布式对象存储系统), 并读数据, 结果发现文件越大读速越慢, 读 1G 文件, 速度只有 2.2M 每秒, 使用 perf 未发现线索.
用命令 tcpdump -i eth0 -s 0 -A 'tcp dst port 9878 and tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x47455420' -w read.cap, 该命令在读 200M 文件时会将所有 GET 请求导出到 read.cap 文件, 然后用 wireshark 打开 read.cap, 并过滤出 HTTP 协议, 因为大部分协议都是 TCP 协议, 用于传输数据, 而 HTTP 协议用于请求开始和结束.
从下图的 wireshark 界面, 可看到读 200M 文件, 共有 10 个 GET 请求: GET /goofys-bucket/test.dbf HTTP/1.1, 每个 GET 请求读 20M 文件, 每个 GET 请求读完后回复: HTTP/1.1 200 OK. 第 1 个 GET 请求到达 S3gateway 时间为 0.2287 秒, 第 10 个 GET 请求到达 Ozone 集群时间为 1.026458 秒. 第 1 个 GET 请求完成时间为 1.869579 秒, 第 10 个 GET 请求完成时间为 23.640925 秒.
可见 10 个 GET 请求在 1 秒内全部到达 Ozone 集群, 但每个请求耗时越来越长. 因此只需要分析后续的 GET 请求读同样大小的数据块, 比前序 GET 请求多做了哪些事情即可.
最后通过分析日志和阅读代码发现, Ozone 采用的第三方库 commons-io 采用 read 实现 skip. 例如读第 10 个 GET 请求时, 实际只需要读[180M, 200M), 但 commons-io 实现 skip 前 180M 时, 会将前 180M 读出来, 导致第 10 个 GET 请求读完整的[0M, 200M), 因此 GET 请求越来越慢. 优化后, 性能提升一百倍.
jstack
jstack 用来查询线程状态, 但在极端情况下也可以用于性能优化. 在部署服务时, 发现进程迅速占满所有 CPU,24 核的机器进程使用 CPU 达到 2381%.
CPU 使用如此之高, 无法运行 arthas 进行 perf 分析, 只能采用其他策略. 首先用 top -Hp pid 命令打出进程 pid 的所有线程及每个线程的 CPU 消耗. 如下图, 第一列 PID 为线程号,%CPU 列代表 CPU 消耗, 注意该图只是展示作用, 该图的进程并不是使用 CPU 达到 2381% 的进程, 原进程的信息当初没保存.
然后计算出使用 CPU 最高的线程号的十六进制表示 0x417, 再用 jstack -l pid> jstack.txt 命令打出所有线程状态, 用 0x417 在 jstack.txt 查询消耗 CPU 最高的线程, 即下图所示 ThreadPoolExecutor 里的线程, 该线程一直处于 RUNNABLE, 且队列为 empty, 基本确认该部分线程出了问题, 因为正常的线程不会一直空转, 状态会有 TIMED_WAITING 的时刻.
因为线程堆栈不包含业务代码, 都是 JDK 的源码, 因此用线程堆栈搜索 JDK 相关问题, 最终发现是 JDK8 的 Bug:JDK-8129861, 该 Bug 在创建大小为 0 的线程池时容易触发, 因此在应用代码里, 将大小为 0 的线程池修改即可.
宕机
被其他进程杀
在生产环境发生过进程被清理脚本杀掉. 排查工具有两个: Linux 自带的 auditd 和 systemtap.
首先使用 auditd, 因为该工具简单易用, 不用安装. 使用 service auditd status 检查服务状态, 如果未启动可用 service auditd restart 启动. 然后使用命令: auditctl -a exit,always -F arch=b64 -S kill, 监听所有的 Kill 信号. 如下图所示, 从 type=OBJ_PID 行里可以看到: 捕捉到的 Kill 信号杀的进程号 opid=40442, 线程名 ocomm="rocksdb:pst_st", 注意这里打出的线程名而不是进程名.
从 type=SYSCALL 行里可以看到: a1=9 表示 kill -9; 发出 kill -9 的进程是 exe="/usr/bin/bash", 进程号是 pid=98003. 从这些信息并不能找到相应的进程, 因为脚本往往运行完就停止, 生命周期非常短.
接下来使用 systemtap 分析, systemtap 需要安装: yum install systemtap systemtap-runtime. 先写 systemtap 脚本 findkiller.stp, 如下所示, 该 systemtap 脚本捕捉杀进程 sig_pid 的 KILL 信号, 并使用 task_ancestry 打印发出 KILL 信号进程的所有祖先进程.
probe signal.send{if(sig_name == "SIGKILL" && sig_pid == target()) {printf("%s, %s was sent to %s (pid:%d) by %s (pid:%d) uid :%d\n", ctime(gettimeofday_s()), sig_name, pid_name , sig_pid, execname(), pid(), uid());printf("parent of sender: %s(%d)\n", pexecname(), ppid());printf("task_ancestry:%s\n", task_ancestry(pid2task(pid()), 1)); }}
然后 stap -p4 findkiller.stp 生成 ko 文件: stap_XX.ko, 有的机器需要将 ko 文件补上签名才能运行. 然后运行: nohup staprun -x 98120 stap_XX.ko>nohup.out 2>&1 &, 此处的 98120 即为脚本中的 target().
捕捉结果如下, 从图里可以看出发出 KILL 命令的进程是通过 crond 启动的, 也就是说定时任务运行了某些脚本杀了进程. 但仍然不知道定时任务启动了哪个脚本杀了进程.
接下来再用 auditd 排查, 使用命令: auditctl -a exit,always -F arch=b64 -S execve 捕捉所有的系统调用, 结果如下, 最后一行是捕捉到杀进程 opid=20286 的信号, 从图中可看出 kill 信号附近出现的都是 / data/tools/clean 命令.
/data/tools/clean 里调用了若干脚本, 在每个脚本里用打出当前脚本名和进程号到 crontab.pid 里. 并和 systemtap 抓到的进程号 62118 对比, 找到了 KILL 信号是从 kill_non_run_app.sh 脚本里发出.
调用 System 的 exit
如果在 Java 程序里显式调用 System.exit 结束进程, 可以用 arthas 排查. 首先写脚本 system_exit.as 如下.
- <span style="font-size: 16px;">
- options unsafe true
- </span>
- <span style="font-size: 16px;">
- stack java.lang.System exit -n 1
- </span>
运行命令 nohup ./as.sh -f system_exit.as 69001 -b> system_exit.out 2>&1 &, 即可监控进程 69001 调用的所有 System.exit.
Java 调用的 C++ 发生 Crash
此处发生的 Crash 案例和下文 Java 内 Crash 产生的原因一样, 但现象不一样, 大部分情况下, 是 Crash 在 C++ 代码, 只产生 core 文件, 不产生 Java 内 Crash 的 Crash log; 少量情况下 Crash 在 JVM 里, 产生 Java 内 Crash 的 Crash log.
如果 Java 通过 JNI 调用 C++ 代码, 在 C++ 里发生 Crash,JVM 有时不会产生任何信息就退出, 此时借助操作系统产生的 core file 分析进程退出原因, 但操作系统默认关闭该功能, 如下图所示 core file size 为 0 表示关闭该功能.
因此需要在进程的启动脚本里 (只影响当前进程) 设置 ulimit -c ulimited 来设置 core file 的大小, 启动进程后, 打开 / proc/{pid}/limits, 查看 Max core file size 的大小确认是否开启.
当发生 Crash 时, 会生成 core.pid 文件, 一般 core.pid 文件会非常大, 因为该文件包含了所有虚拟内存大小, 所以大于物理内存, 如下图所示 core.44729 共 53GB.
接下来使用命令 gdb bin/java core.44729 打开 core 文件, 发现是 rocksdb start thread 时挂的, 挂在 libstdc++ 里, 这是 glibc 库, 基本不可能出问题, 因此该堆栈可能是表象, 有其他原因导致 start thread 失败.
注意到打开 core 文件时, 有太多线程 - LWP 轻量级进程.
然后在 gdb 里用 info threads, 发现有三万多个线程, 都在 wait 锁状态, 基本确认三万多个线程, 导致内存太大, 创建不出来新的线程, 因此挂在 start thread 里.
接着分析三万多个线程都是什么线程, 随机选几十个线程, 打出每个线程的堆栈, 可以看到大部分线程都是 jvm 线程. 因为 rocksdb 创建出来的线程是:
从 / tmp/librocksdbjni8646115773822033422.so 来的; 而 jvm 创建出来的线程都是从 / usr/java/jdk1.8.0_191-amd64/jre/lib/amd64/server/libjvm.so 来的, 这部分线程占了大部分.
因此问题出在 Java 代码里, 产生 core.pid 文件的进程, 虽然没有产生 crash log, 但也是因为 Java 线程太多, 导致 C++ 代码创建线程时挂掉. 至于为什么 Java 线程太多请看 Java 内 Crash.
另外, core.pid 完整的保留了 C++ 组件 Crash 时的现场, 包括变量, 寄存器的值等, 如果真的因为 C++ 组件有 Bug 而 Crash, 例如空指针等. 首先自行找到 C++ 源码, 找出怀疑空指针的变量{variableName}, 通过在 gdb 里执行命令: p {variableName}, 可以看出每个变量的值, 从而找出空指针的变量.
Java 内 Crash
排查 Java 内 Crash 的原因如 OOM 等, 需要配置 JVM 的如下参数:
- -XX:ErrorFile
- -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath.
JVM 内发生 Crash 时, 会在 - XX:ErrorFile 配置的路径下生成 crash log. 而 - XX:+HeapDumpOnOutOfMemoryError,-XX:HeapDumpPath 用于发生 OOM 时生成 Dump 堆, 用于还原现场. 下图所示为产生的 crash log. 可以看到创建线程时发生 OutOfMemory 导致进程挂掉.
从下图 crash log 可以看到有两万四千个 Datanode State Machine Thread 线程都在等锁. 到此确认上文 Java 调用 C++ 发生 Crash 产生 core.pid 的进程和产生 crash log 的进程都是因为两万多个 Datanode State Machine Thread 挂掉.
接着分析为何有两万多个 Datanode State Machine Thread, 代码里可以看到该线程用线程池 newCacheThreadPool 创建. 该 newCacheThreadPool 在没有线程可用, 例如线程都在等锁的情况下, 会创建新的线程, 因此创建了两万多个线程. 接着分析 Datanode State Machine Thread 等的什么锁. 在进程的线程数超过 5000 时, 用 jstack -l pid> jstack.txt 打出所有线程的状态.
可以看到几乎所有 Datanode State Machine Thread 在等锁, 而只有一个 Datanode State Machine Thread - 5500 拿到了锁, 但是卡在提交 RPC 请求 submitRequest. 至此 Java 调用 C++ 发生 Crash 和 Java 内 Crash 的原因找到.
死锁
log4j 导致的死锁
jstack 打出的死锁信息如下所示. grpc-default-executor-14765 线程拿到了 log4j 的锁, 在等 RaftServerImpl 的锁; grpc-default-executor-14776 线程拿到了 RaftServerImpl 的锁, 在等 log4j 的锁, 导致这两个线程都拿到了对方等待的锁, 所以造成两个线程死锁. 可以看出, 仅仅打日志的 log4j, 不释放锁是最值得怀疑的地方. 最后发现 log4j 存在死锁的缺陷[4]. 该缺陷在 log4j2 得到解决, 升级 log4j 即可.
封装不严谨导致的死锁
jstack 打出的死锁信息如下所示. grpc-default-executor-3449 线程拿到了 RaftLog 的锁, 在等 DataBlockingQueue 的锁; SegmentedRaftLogWorker 拿到了 DataBlockingQueue 的锁, 在等 RaftLog 的锁.
这里最值得怀疑的是 SegmentedRaftLogWorker 拿到了 DataBlockingQueue 的锁却不释放, 因为 queue 的操作只是在队列里增, 删, 查元素. 如下图所示 DataBlockingQueue 的方法 poll, 使用的锁是自己封装的锁 AutoCloseableLock implement AutoCloseable, 锁的释放依赖于 AutoCloseableLock 重载的 close 方法.
再看 acquire 方法, 先用 lock.lock()拿到锁, 再创建新的 AutoCloseableLock 对象, 如果拿到锁后, 在创建新对象 AutoCloseableLock 时发生 OOM 等异常, 锁就无法释放.
参考
[1]https://www.waitingforcode.com/apache-spark/apache-spark-off-heap-memory/read
[2]https://github.com/alibaba/arthas/releases/tag/arthas-all-3.3.6
[3]https://www.jaegertracing.io/docs/1.18/getting-started/
[4]https://stackoverflow.com/questions/3537870/production-settings-file-for-log4j/
来源: http://www.tuicool.com/articles/riuuyaB