日志配置
要在生产环境部署 Java 应用，配置日志输出是必备的预备工作。
应用日志
以 Spring Boot 应用为例，其 Starter 包已经引入了 logback、log4j 等应用框架，因此应用程序常用的配置项可以在 application.yml 进行设定。
1 | logging: |
值得注意的是：
严格管理日志级别，避免在生产环境输出开发测试阶段的调试信息，以免对业务系统造成压力。
复杂的配置项可以通过 xml 文件进行定义（如
classpath:log4j.xml），在application.yml引入即可。
JVM 日志
一般情况下 JVM 层面的事故出现时，将来不及使用 jstat 等命令查看事发原因，因此需要保留现场，把进程快照、堆栈快照等信息保存下来以供后续排查问题使用。以下是比较通用的 JVM 参数配置：
1 | JDK 8 |
1 | JDK 8+ |
可以总结为以下几个方面：
GC 日志：时间戳、STW 时间，对象年龄分布等。
Safe Point 日志（便于分析线程阻塞等问题）。
发生 OOM 时导出堆转储文件以及错误日志。
……
输入日志如下：
1 表示 GC 发生的时间，一般使用可读的方式打印；
2 表示日志表明是 G1 的“转移暂停: 混合模式”，停顿了约 223ms；
3 表明由 8 个 Worker 线程并行执行，消耗了 214ms；
4 表示 Diff 越小越好，说明每个工作线程的速度都很均匀；
5 表示外部根区扫描，外部根是堆外区。JNI 引用，JVM 系统目录，Classloaders 等；
6 表示更新 RSet 的时间信息；
7 表示该任务主要是对 CSet 中存活对象进行转移（复制）；
8 表示花在 GC 之外的工作线程的时间；
9 表示并行阶段的 GC 总时间；
10 表示其他清理活动；
11表示收集结果统计；
12 表示时间花费统计。
系统日志
如果 Java 程序还配置了 Systemd，还可以通过 journalctl 系列命令查看日志（如 journalctl -u test-svc.service -f 筛选出特定服务的日志）。
1 | journalctl -u test-svc.service -f |
1 | -- Logs begin at Thu 2020-09-17 14:56:01 CST. -- |
另一方面，有时 Java 进程会毫无预兆的退出，且没有任何遗言输出（比如由系统 oom-killer 在系统内存耗尽时被选择性杀死），此时可以使用 dmesg -T 查看：
无论由于何种原因退出，都能从以上方法中找到一些线索，但前提是不要为自己挖坑（比如在代码中加入 System.exit(); 等命令）。
保留现场
哪怕生产环境往往配备了监控系统，但其保留的信息未必能有针对性地为服务排查问题。因此在服务出现故障前，可以使用自动化方式将必要的信息保存下来，一般用到以下信息：
瞬时态：lsof、heap 这些没有时间序列概念的混杂信息，体积都比较大，无法进入监控系统产生有用价值，只能在某些时刻查看分析（线程、堆、网络快照）。
历史态：CPU、内存，这些数据可以体现出趋势性的问题，这些数据需要监控系统的协作（系统监控、业务监控、GC 日志数据采集等）。
服务器
网络
保留当前网络连接，使得后续可查看梳理各种网络连接状态，排查 TIME_WAIT、CLOSE_WAIT 或者其他连接过高的问题，比如连接没有主动关闭）：
1 | ss -antp > $DUMP_DIR/ss.dump 2>&1 |
保留网络状态（按照各个协议进行统计输出）：
1 | netstat -s > $DUMP_DIR/netstat-s.dump 2>&1 |
对于一些速度非常高得模块，比如 Kafka、Redis 经常出现跑满网卡的情况，容易挤占 Java 程序的资源，使用以下命令保留网络流量：
1 | sar -n DEV 1 2 > $DUMP_DIR/sar-traffic.dump 2>&1 |
进程
比如通过查看进程，看到打开了哪些文件，以进程的维度来查看整个资源的使用情况，包括每条网络连接、每个打开的文件句柄。同时也很容易看到连接到了哪些服务器、使用了哪些资源。
1 | lsof -p $PID > $DUMP_DIR/lsof-$PID.dump |
CPU
输出当前系统的 CPU 和负载（与上述信息有部分重合）：
1 | mpstat > $DUMP_DIR/mpstat.dump 2>&1 |
1 | vmstat 1 3 > $DUMP_DIR/vmstat.dump 2>&1 |
1 | sar -p ALL > $DUMP_DIR/sar-cpu.dump 2>&1 |
1 | uptime > $DUMP_DIR/uptime.dump 2>&1 |
磁盘
一般以计算为主的服务节点，I/O 资源会比较正常，但有时也会发生问题，比如：日志输出过多，或者磁盘本身出现问题等。此命令可以输出每块磁盘的基本性能信息，用来排查 I/O 问题。
1 | iostat -x > $DUMP_DIR/iostat.dump 2>&1 |
内存
大体展现操作系统的内存概况，比如 SWAP 影响了 GC，SLAB 区挤占了 JVM 的内存。
1 | free -h > $DUMP_DIR/free.dump 2>&1 |
其他
包括系统日志、内核参数等。
1 | ps -ef > $DUMP_DIR/ps.dump 2>&1 |
1 | dmesg > $DUMP_DIR/dmesg.dump 2>&1 |
1 | sysctl -a > $DUMP_DIR/sysctl.dump 2>&1 |
JVM
进程快照
即进程最后的“遗言”。
1 | jinfo $PID > $DUMP_DIR/jinfo.dump 2>&1 |
堆快照
jstat 将输出当前的 GC 信息。
1 | jstat -gcutil $PID > jstat-gcutil.dump 2>&1 |
可借助 jmap 来进行分析。
1 | jmap $PID > jmap.dump 2>&1 |
jmap 命令在 9 版本里被移除了，取而代之的是 jhsdb。
1 | jhsdb jmap --heap --pid $PID |
对于 jmap 无法执行的情况，可以使用 gcore 生成 core 文件、再生成 dump。
1 | gcore -o core $PID |
dump 文件一般需要下载到本地，使用 MAT 等工具分析内存泄漏等问题。
栈快照
jstack 将会获取当时的执行栈，一般取一次即可，能还原 Java 进程中的线程情况。
1 | jstack $PID > jstack.dump 2>&1 |
如果需要更精细的信息，可以结合 top：
1 | top -Hp $PID -b -n 1 -c > top-$PID.dump 2>&1 |
有时 jstack 并不能够运行（比如 Java 进程几乎不响应）。可以尝试向进程发送 kill -3 信号打印 jstack 的 trace 信息到日志文件中，是 jstack 的一个替补方案。
1 | kill -3 $PID |
把以上数据导出写成脚本，运行可生成 日志 ：
1 | !/bin/bash |
问题排查
定位异常线程
有时某些线上应用在运行一段时间后 CPU 使用率飙升，可能的原因是某些业务逻辑计算量太大或陷入死循环，也可能是 GC 的问题，此时就需要找出具体是由哪个线程触发的。
首先查看进程信息：
1 | top |
查看某个进程中占用 CPU 最多的线程：
1 | top -Hp $pid |
把线程 id 转换成十六进制表示：
1 | printf %x $tid |
查看 Java 进程的栈信息：
1 | jstack $pid > $pid.log |
查看生成的文件，找到十六进制表示的线程 id，找到发生问题的线程上下文：
1 | less $pid.log |
比如：
堆被填满但又没有发生 OOM，于是 GC 进程就一直执行回收，但回收效果不好、造成 CPU 升高应用假死。
此时要进一步对问题成因进行分析，就需要把内存信息导出到本地，使用其他工具进行分析。
内存泄漏现象
这里尤其指的是堆内存泄漏，堆外内存泄漏比较复杂，在其他章节再总结分析过程。
使用 jmap 命令可以看到大体的内存布局，以及每个区域中的内存使用情况。
1 | jmap -heap $PID > jmap-heap.dump 2>&1 |
另一方面需要关心的是堆中每种类型的对象占据内存的大小。比如某个对象数量很小，但占用的空间很大，这就说明存在大对象。
一般内存溢出的表现形式就是老年代占用持续上升，即使经过了多轮 FGC 也没有明显改善。内存泄漏是其中一种原因，其本质就有些对象并没有切断和 GC Roots 的关系。
以上方法只能大致看到一些统计信息，要作进一步排查可通过 VisualVM、MAT 等工具分析它们的联系（需要导出二进制格式的堆转储快照）。
1 | jmap -dump:format=b,file=heap.bin $PID # JDK 8 |
直接内存溢出
以下述描述场景为例。
现象描述
有一次发现某个服务占用的内存不断增长，直到虚拟机分配的内存上限，但是不会 OOM。如果开启了 SWAP，会发现被不断占用。
内存增长可以通过 top 命令去观察（RES 列的数值）；如果使用 jmap 命令去看内存占用，得到的只是堆的大小，只是很小的一部分。
使用
ps -p pid -o rss,vsz可以观测到除了虚拟内存比较高，实际使用的内存 RSS 也非常高，超过-Xmx的设定。使用
jps -v查看启动参数、使用java -XX:+PrintFlagsFinal 2>&1 | grep MaxHeapSize查看默认值，可发现实际内存使用远远超出最大内存设定。
要追踪 Native 内存的使用情况，可在启动参数上加入 -XX:NativeMemoryTracking=detail 即可启用，在运行状态下使用 jcmd：
1 | jcmd $PID VM.native_memory summary |
即使 NMT 能看到堆内内存、Code 区域或者使用 unsafe.allocateMemory 和 DirectByteBuffer 申请的堆外内存，但仍然不能解决问题。
Pmap
使用 pmap 命令查看进程的内存分配，通过 RSS 升序序排列，可以发现除了大块的堆内存以外，还有数量非常多的小块堆外内存，还有巨量小的物理内存块映射到不同的虚拟内存段上。
1 | pmap -x 2154 | sort -n -k3 |
1 | Address Kbytes RSS Dirty Mode Mapping |
GDB
可以通过 gdb 工具将堆外内存 dump 出来：读取 /proc 目录下的 maps 文件，能精准地知晓目前进程的内存分布。
以下脚本通过传入进程 id，能够将所关联的内存（加载到内存中的 class 文件、堆文件一块给 dump 下来）全部 dump 到文件中。这个命令会影响服务，要慎用。
1 | pid=$1;grep rw-p /proc/$PID/maps | sed -n 's/^\([0-9a-f]*\)-\([0-9a-f]*\) .*$/\1 \2/p' | while read start stop; do gdb --batch --pid $pid -ex "dump memory $1-$start-$stop.dump 0x$start 0x$stop"; done |
1 | [Thread debugging using libthread_db enabled] |
更多时候只需要 dump 一部分内存就可以。这个操作会影响服务，注意 dump 的内存块大小，线上要慎用。
复制 pman 的一块 64M 内存，比如 00007f2d70000000，然后去掉前面的 0，使用下面代码得到内存块的开始和结束地址。
1 | cat /proc/$PID/maps | grep 7f2d70000000 |
1 | 7f2d6fff1000-7f2d70000000 ---p 00000000 00:00 0 7f2d70000000-7f2d73ffc000 rw-p 00000000 00:00 0 |
dump 出这 64MB 的内存。
1 | gdb --batch --pid $PID -ex "dump memory a.dump 0x7f2d70000000 0x7f2d73ffc000" |
使用 strings 查看打印的内容（一些类似编码解码的操作）。
1 | strings -10 a.dump |
1 | 0R4f1Qej1ty5GT8V1R8no6T44564wz499E6Y582q2R9h8CC175GJ3yeJ1Q3P5Vt757Mcf6378kM36hxZ5U8uhg2A26T5l7f68719WQK6vZ2BOdH9lH5C7838qf1 |
可以发现一些原本应该存在于堆的内容使用了额外的内存进行分配，只可能是 Native 程序对堆外内存的操作。
Perf
Perf 除了能够进行一些性能分析，还能帮助找到相应的 Native 调用。首先开启监控栈函数调用。
1 | perf record -g -p $PID |
访问服务器的 8888 端口，将会把内存使用的阈值增加到 85%，程序会逐渐把这部分内存占满。
perf 运行一段时间后 Ctrl+C 结束会生成一个文件 perf.data，查看分析报告。
1 | perf report -i perf.data |
一般第三方 JNI 程序或者 JDK 内的模块，都会调用相应的本地函数。在 Linux 上这些函数库的后缀都是 so，比如 libzip.so、libpthread-2.17.so 等：
1 | Samples: 26K of event 'cpu-clock', Event count (approx.): 6583500000 |
其中 libzip.so 占据大量 CPU，查看 JDK 代码，发现 bzip 包使用了大量 native 方法 java.util.zip.Inflater#inflateBytesBytes，即大量的内存申请和销毁实在堆外发生的。
进程调用了申请了内存却没有调用 Deflater 释放内存。与 pmap 内存地址相比对，确实是 zip 造成的，应该检查业务代码中 zip 相关的操作。
GPerftools
还可以利用 GPerftools 的 Heap Profiler 功能定位 Native 函数。安装成功后输出两个环境变量：
1 | mkdir -p /opt/test |
在同一个终端启动应用程序，可见申请内存的动作都被记录到 /opt/test：
1 | java -jar ... |
再使用 pprof 分析这些文件：
1 | cd /opt/test |
1 | Total: 25205.3 MB |
也可以追踪到申请内存最多的函数 java.util.zip.Inflater#init。
未完待续。