Java生产环境线上栈故障排查问题(COPY)

• jmap -dump
  • 例如， jmap -dump:format=b,file=heap.hprof 7
  • 该命令姿势会令JVM将整个heap信息dump到一个文件中。如果heap比较大，会导致这个过程比较耗时。而且，为了保证dump的信息是准确、可靠的，JVM会处在STW状态，致使服务不可用。
    • 可以通过-d64来解决，jmap -J-d64 -dump:format=b,file=dump.bin PID。
  • 通常dump下来的内存文件有几个G大小，如果dump文件比较小，说明jmap姿势不对，需要多执行几次jmap -dump才能得到正常结果。
    • 可以用gcore将整个内存 dump下来，然后使用jmap将core dump转为heap dump。
    • 方法，执行gcore PID得到C版本的core文件，再执行jmap -dump:format=b,file=heap.hprof /bin/java core.PID 即可。
• jmap -permstat
  • 该命令会令JVM去统计perm区的状况，整个过程比较的耗时，令JVM处于STW状态，致使服务不可用。
• jmap -histo:live
  • 该命令会令JVM执行GC操作，然后在进行统计信息。

• 利用JVM内建的指令对Java应用程序的资源和性能进行实时的命令行的监控，包括了对Heap size和垃圾回收状况的监控。详细查看堆内各个部分的使用量，以及加载类的数量。使用时，需加上查看进程的进程id、所选参数。
• 使用姿势，每秒输出一次进程7的JVM资源使用情况，共输出100次
  • jstat -gcutil 7 1000 100

• -XX:+HeapDumpOnOutOfMemoryError 
• -XX:HeapDumpPath=/home/admin/logs 
• -Xloggc:/home/admin/logs/gc.log 
• -XX:+PrintGCDetails 
• -XX:+PrintGCDateStamps
  

• CPU占用过高
• 物理内存富余量极少
• 磁盘I/O占用过高
• 发生换入换出过多
• 网络链接数过多

• Java堆是“Java虚拟机”从操作系统申请到的一大块内存，用于存放Java程序运行中创建的对象。
• 当Java堆满或者较满的情况下，会触发“Java虚拟机”的“垃圾收集”操作，将所有“不可达对象”（即程序逻辑不能引用到的对象）清理掉。
• 有时，由于程序逻辑或者Java堆参数设置的问题，会导致“可达对象”（即程序逻辑可以引用到的对象）占满了Java堆。
• 这时，Java虚拟机就会无休止地做“垃圾回收”操作，使得整个Java程序会进入卡死状态。

• 日志中会记录一些异常信息，例如超时、操作失败等信息，其中可能含有系统故障的关键信息。

• 可采用jstack工具可以获取可能有用的线索

排除其它程序过度占用系统资源的问题

排除服务本身占用系统资源过度的问题

观察服务内部的情况，排除掉各种常见故障类型。 

• 对于不能排除的方面，要根据该信息对应的“危险程度”来判断是应该“进一步深入”还是“暂时跳过”。例如：

• “服务Java堆占用100%”，建议“进一步深入”。

• “CPU核数为8的机器上，其它程序偶然占用CPU达200%”，建议“暂时跳过”。
  

• 如果idle较少，则按shift+p，将进程按照CPU占用率从高到低排序，逐一排查。
  
• 

• 
• 如果剩余物理内存较少（例如剩余1GB以下），则运行【vmstat -n 1】检查si/so（换入换出）情况
  
  • 

  • 第一行数值表示的是从系统启动到运行命令时的均值，可以暂时忽略。

  • 从第二行开始，每一行的si/so表示该秒内si/so的block数。如果多行数值都为零，则可以排除物理内存不足的问题。

  • 如果数值较大（例如大于1000 blocks/sec，block的大小一般是1KB）则说明存在较明显的内存不足问题。

  • 可以运行【top】输入shift+m，将进程按照物理内存占用（“RES”列）从大到小进行排序，然后对排前面的进程逐一排查。

如果目标服务是磁盘I/O较重的程序，则用【iostat -d 1】，检查磁盘I/O情况。若“目标服务对应的磁盘”读写量在预估之内（预估要注意cache机制的影响），则排除其它进程占用磁盘I/O过量的问题。

• • 
• 第一组数据是从该机器从开机以来的统计值。从第二组开始，都是每秒钟的统计值。通过【df】命令，可以看到Device与目录的关系。下图设备“sdb”就对应了目录“/disk2”。
  
  • 
• 假如发现目标服务所在磁盘读写量明显超过推算值，则应该找到大量读写磁盘的进程。

• 假如发现连接数较多，可以用【netstat -natp|awk ‘{print $7}’|sort|uniq -c|sort -rn】按照PID统计TCP连接的数量，然后对连接数较多的进程逐一排查。
  
  • 如何“逐一排查”
    • 假如定位到是某个外部程序占用过量系统资源，则依据进程的功能和配置情况判断是否合乎预期。
    • 假如符合预期，则考虑将服务迁移到其他机器、修改程序运行的磁盘、修改程序配置等方式解决。
    • 假如不符合预期，则可能是运行者对该程序不太了解或者是该程序发生了BUG。
    • 外部程序通常可能是Java程序也可能不是Java程序，如果是Java程序，可以把它当作目标服务一样进行排查；而非Java程序不做详细说明，可参考选用下面几个工具：
      • 系统提供的调用栈的转储工具【pstack】，可以了解到程序中各个线程当前正在干什么，从而了解到什么逻辑占用了CPU、什么逻辑占用了磁盘等。
      • 系统提供的调用跟踪工具【strace】，可以侦测到程序中每个系统API调用的参数、返回值、调用时间等。从而确认程序与系统API交互是否正常等。
      • 系统提供的调试器【gdb】，可以设置条件断点侦测某个系统函数调用的时候调用栈是什么样的。从而了解到什么逻辑不断在分配内存、什么逻辑不断在创建新连接等。
  • 如何“找到大量读写磁盘的进程”
    
    • 如果Linux系统比较新（kernel v2.6.20以上）可以使用iotop工具获知每个进程的io情况，较快地定位到读写磁盘较多的进程。
    • 通过【ls -l /proc/*/fd | grep 该设备映射装载到的文件系统路径】查看到哪个进程打开了该设备的文件，并根据进程身份、打开的文件名、文件大小等属性判断是否做了大量读写。
    • 可以使用pstack取得进程的线程调用栈，或者strace跟踪磁盘读写API来帮助确认某个进程是否在做磁盘做大量读写。

• 假如目标服务占用的CPU较高（>100%，即大于一个核的计算量），则shift+h观察线程级别的CPU使用分布。
• 如果CPU使用分散到多个线程，而且每个线程占用都不算高（例如都<30%），则排除CPU占用过高的问题。
• 如果CPU使用集中到一个或几个线程，而且很高（例如都>95%），则用【jstack pid > jstack.log】获取目标服务中线程调用栈的情况。top中看到的占用CPU较高的线程的PID转换成16进制（字母用小写），然后在jstack.log中找到对应线程，检查其逻辑：假如对应线程是纯计算型任务（例如GC、正则匹配、数值计算等），则排除CPU占用过高的问题。当然如果这种线程占用CPU总量如果过多（例如占满了所有核），则需要对线程数量做控制（限制线程数 < CPU核数）。
• 假如对应线程不是纯计算型任务（例如只是向其他服务请求一些数据，然后简单组合一下返回给用户等），而该线程CPU占用过高（>95%），则可能发生了异常。
  • 例如：死循环、数据结构过大等问题，确定具体原因的方法见参考“第三步：目标进程内部观察”。

• 由于Java进程中有Java级别的内存占用，也有Native级别的内存占用，所以Java进程的“物理内存使用(RES)”比“-Xmx参数指定的Java堆大小”大一些是正常的（例如1.5~2倍左右）。

• 假如“物理内存使用(RES)”超出预期较多（例如2倍以上），并且确定JNI逻辑不应该占用这么多内存，则可能是NIO或JNI代码出现了BUG，暂时对这种情况不做过多讨论。

• 假如占用比例较高（例如超过98%），则服务存在Java堆占满的问题。这时候可以用jmap+mat进行分析定位内存中占用比例的情况，从而较快地定位到Java堆满的原因。
• 用jmap+mat进行分析定位内存中占用比例的情况
  • 先通过【jmap -dump:file=dump.map pid】取得目标服务的Java堆转储，然后找一台空闲内存较大的机器在VNC中运行mat工具。
  • mat工具中打开dump.map后，可以方便地分析内存中什么对象引用了大量的对象（从逻辑意义上来说，就是该对象占用了多大比例的内存）。

• tail -1000 stdout.log.2020-02-02 | grep -i exception 

• 用【jstack pid > jstack.log】获取目标服务中“锁情况”和“各线程调用栈”信息，并分析 检查jstack.log中是否有deadlock报出，如果没有则排除deadlock情况。
  

  • *Found one Java-level deadlock:*

    *=============================*

    *“Thread-0″:*

    * waiting to lock monitor 0x1884337c (object 0x046ac698, a java.lang.Object),*

    * which is held by “main”*

    *“main”:*

    * waiting to lock monitor 0x188426e4 (object 0x046ac6a0, a java.lang.Object),*

    * which is held by “Thread-0″*

    * *
    *Java stack information for the threads listed above:*
    *===================================================*
    *“Thread-0″:*
    * at LockProblem$T2.run(LockProblem.java:14)*
    * - waiting to lock <0x046ac698> (a java.lang.Object)*
    * - locked <0x046ac6a0> (a java.lang.Object)*
    *“main”:*
    * at LockProblem.main(LockProblem.java:25)*
    * - waiting to lock <0x046ac6a0> (a java.lang.Object)*
    * - locked <0x046ac698> (a java.lang.Object)*
    * *
    *Found 1 deadlock.*

• 如果发现deadlock则根据jstack.log中的提示定位到对应代码逻辑。通过分析堆栈情况，可以定位到可以信息，并猜测故障的原因，通过日志检查、监控检查、用测试程序尝试复现等方式确认猜测是否正确。
• 如果需要更细致的证据来确认，可以通过BTrace、strace、jmap+MAT等工具进行分析，最终确认问题所在。
  • 

BTrace - 用于监测Java级别的方法调用情况。

• 可以对运行中的Java虚拟机插入调试代码，从而确认方法每次调用的参数、返回值、花费时间等。第三方免费工具。

strace - 用于监视系统调用情况。

• 可以得到每次系统调用的参数、返回值、耗费时间等。Linux自带工具。

jmap+MAT - 用于查看Java级别内存情况。

• *1000 threads at*
  *“Timer-0″ prio=6 tid=0x189e3800 nid=0x34e0 in Object.wait() [0x18c2f000]*
  * java.lang.Thread.State: TIMED_WAITING (on object monitor)*
  * at java.lang.Object.wait(Native Method)*
  * at java.util.TimerThread.mainLoop(Timer.java:552)*
  * - locked [***] (a java.util.TaskQueue)*
  * at java.util.TimerThread.run(Timer.java:505)*

• *38 threads at*
  *“Thread-44″ prio=6 tid=0×18981800 nid=0x3a08 waiting for monitor entry [0x1a85f000]*
  * java.lang.Thread.State: BLOCKED (on object monitor)*
  * at SlowAction$Users.run(SlowAction.java:15)*
  * - waiting to lock [***] (a java.lang.Object)*

  * *
  *1 threads at*
  *“Thread-3″ prio=6 tid=0x1894f400 nid=0×3954 runnable [0x18d1f000]*
  * java.lang.Thread.State: RUNNABLE*
  * at java.util.LinkedList.indexOf(LinkedList.java:603)*
  * at java.util.LinkedList.contains(LinkedList.java:315)*
  * at SlowAction$Users.run(SlowAction.java:18)*
  * - locked [***] (a java.lang.Object)*

某个应当被缓存的对象多次被创建（数据库连接）

• 99 threads at
  “resin-tcp-connection-*:3231-321″ daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor entry [0x00000000507ff000]
  java.lang.Thread.State: BLOCKED (on object monitor)
  at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
  - waiting to lock <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
  at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
  at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
  * *
  1 threads
  at “resin-tcp-connection-*:3231-149″ daemon prio=10 tid=0x000000004d67e800 nid=0x66d7 runnable [0x000000005180f000]
  java.lang.Thread.State: RUNNABLE
  …
  at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:46)
  at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
  - locked <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
  at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
  at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
  at …

很多线程都在等待外部服务的响应

• 100 threads at
  “Thread-0″ prio=6 tid=0x189cdc00 nid=0×2904 runnable [0x18d5f000]
  java.lang.Thread.State: RUNNABLE
  atjava.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.read(SocketInputStream.java:150)
  at java.net.SocketInputStream.read(SocketInputStream.java:121)…
  at RequestingService$RPCThread.run(RequestingService.java:24)

很多线程都在等待FutureTask完成，而FutureTask在等待外部服务的响应

• 100 threads at
  “Thread-0″ prio=6 tid=0×18861000 nid=0x38b0 waiting on condition [0x1951f000]
     java.lang.Thread.State: WAITING (parking)
   at sun.misc.Unsafe.park(Native Method)
   - parking to wait for [***] (a java.util.concurrent.FutureTask$Sync)
   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
   at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:248)
   at java.util.concurrent.FutureTask.get(FutureTask.java:111)
   at IndirectWait$MyThread.run(IndirectWait.java:51)
   
  100 threads at
  “pool-1-thread-1″ prio=6 tid=0x188fc000 nid=0×2834 runnable [0x1d71f000]
  java.lang.Thread.State: RUNNABLEat java.net.SocketInputStream.socketRead0(Native Method)
  at java.net.SocketInputStream.read(SocketInputStream.java:150)
  at java.net.SocketInputStream.read(SocketInputStream.java:121)…
  at IndirectWait.request(IndirectWait.java:23)
  at IndirectWait$MyThread$1.call(IndirectWait.java:46)
  at IndirectWait$MyThread$1.call(IndirectWait.java:1)
  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
  at java.util.concurrent.FutureTask.run(FutureTask.java:166)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
  at java.lang.Thread.run(Thread.java:722)