生产环境实践(三)：堆栈日志分析

系列文章——

     生产环境实践(一)：保存运行时信息(堆栈、CPU、内存、IO等)

     生产环境实践(二)：Linux常用运维工具

     生产环境实践(三)：堆栈日志分析

上文《生产环境实践(二)：Linux常用运维工具》带大家熟悉了各种性能分析工具，本篇则让我们看看之前获取到的JAVA进程堆栈数据怎么帮助我们排查生产线上问题的。

• jstack命令保存java线程dump

  # 保存 java threads dump
  jstack $pid >> $file_path/stack.log
  

• jmap命令保存java堆dump

  # 保存 java heap dump
  jmap -dump:live,format=b,file=$file_path/heap.hprof $pid
  

Thread Dump

打开stack.log，观察发现类似下图信息。

1. 线程名称

2. 守护线程标志

   daemon表示该线程为守护线程，非守护线程该列为空。

3. 优先级

   prio表示线程优先级默认为5，10表示最高。

4. 线程ID

   nid表示十六进制的线程ID，可以结合top -Hp $pid中十进制的线程ID，方面查找占用CPU资源的线程。

5. 线程状态

   waiting on condition：等待资源

   waiting for monitor entry：等待获取监视器

   in Object.wait()：对象等待中

   runnable：执行中

6. Thread.State

   NEW：尚未启动的线程。

   RUNNABLE：可运行线程的状态。正在Java虚拟机中执行，但它可能正在等待来自操作系统的其他资源，例如处理器。

   BLOCKED：等待监视器锁被阻止的线程状态。处于阻塞状态的线程正在等待监视器锁。同步块/方法阻塞或者IO阻塞等原因放弃CPU使用权导致阻塞。

   WAITING：等待线程的线程状态。调用 Object.wait, Thread.join, LockSupport.park，处于等待状态的线程正在等待另一个线程执行特定的动作。

   TIMED_WAITING：具有指定等待时间的等待线程的线程状态。调用Object.wait(long), Thread.join(long), LockSupport.parkNanos, LockSupport.parkUntil。

实例：Waiting to lock 和 Blocked

"pool-2-thread-2" #65 prio=5 os_prio=0 tid=0x0000000029f59000 nid=0x14c0 waiting for monitor entry [0x000000003896d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:147)
	- waiting to lock <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)
	at org.hibernate.event.internal.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:118)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:209)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:194)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:114)
	at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:90)

• 线程状态为BLOCKED阻塞，waiting for monitor entry等待获取监视器，waiting to lock <0x00000005c40a8b00>表示等待0x00000005c40a8b00的锁。
• 继续在dump日志中搜索0x00000005c40a8b00，发现存在大量的waiting to lock该地址的记录。
• 搜索locked <0x00000005c40a8b00>查找谁占用了锁资源。

"pool-2-thread-4" #67 prio=5 os_prio=0 tid=0x0000000029f5a000 nid=0x8f8 waiting on condition [0x0000000038b6d000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000005c3b33dc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at org.apache.tomcat.dbcp.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:586)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:438)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:359)
	at org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1532)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:65)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:213)
	- locked <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)

• 观察发现线程pool-2-thread-4获取了0x00000005c40a8b00的锁，然后获取数据库连接处于等待状态。搜索parking to wait for <0x00000005c3b33dc0>发现存在25条记录之多，证明数据库连接池被耗尽了，连接池的使用情况参考堆dump。

Heap DUMP

MAT是分析Java堆内存的一个工具，全称是 The Eclipse Memory Analyzer Tool，用来帮助分析内存泄漏和减少内存消耗。使用MAT分析Java堆快照，可以快速计算出对象的保留大小（Retained Sizes），查找到阻止对象被回收的原因，MAT会自动生成一个包含内存泄漏疑点的报告。

使用Memory Analyzer Tool工具打开heap.hprof文件，选择"Leak Suspects Report"然后点击"Finish"。

来到界面上方的功能栏，从左到右依次为：

• Overview

  概要界面

  
  • Details：显示了一些统计信息，包括整个堆内存的大小、类（Class）的数量、对象（Object）的数量、类加载器（Class Loader)的数量。
  • Biggest Objects by Retained Size：使用饼图的方式直观地显示了在JVM堆内存中最大的几个对象，当光标移到饼图上的时候会在左边Inspector和Attributes窗口中显示详细的信息。
  • Actions：这里显示了几种常用到的操作，算是功能的快捷方式，包括 Histogram、Dominator Tree、Top Consumers、Duplicate Classes，具体的含义和用法见下面；
  • Reports：列出了常用的报告信息，包括 Leak Suspects和Top Components，具体的含义和内容见下；
  • Step By Step：以向导的方式引导使用功能。

• Histogram

  直方图，可以查看每个类的实例（即对象）的数量和大小。

  

  可以选择分组方式，例如Group by package按照类的package分组。

• dominator_tree

  支配树，列出Heap Dump中处于活跃状态中的最大的几个对象，默认按 retained size进行排序，因此很容易找到占用内存最多的对象。

  

• OQL

  MAT提供了一个对象查询语言（OQL），跟SQL语言类似，将类当作表、对象当作记录行、成员变量当作表中的字段。通过OQL可以方便快捷的查询一些需要的信息，是一个非常有用的工具。

  

  例如SELECT x FROM java.io.File x 表示列出java.io.File的实例。

• thread_overview

  此工具可以查看生成Heap Dump文件的时候线程的运行情况，用于线程的分析。

  

• Find Object by address

  通过十六进制的地址查找对应的对象。

  

实例：连接池使用情况

上文ThreadDump中的实例一：Waiting to lock 和 Blocked有提到连接池等待造成阻塞。让我们通过MAT分析heap.hprof中连接池的使用情况。

从pool-2-thread-4的线程dump中找到关键类org.apache.tomcat.dbcp.dbcp2.PoolingDataSource

"pool-2-thread-4" #67 prio=5 os_prio=0 tid=0x0000000029f5a000 nid=0x8f8 waiting on condition [0x0000000038b6d000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000005c3b33dc0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at org.apache.tomcat.dbcp.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:586)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:438)
	at org.apache.tomcat.dbcp.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:359)
	at org.apache.tomcat.dbcp.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at org.apache.tomcat.dbcp.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1532)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
	at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
	at org.hibernate.engine.transaction.internal.jdbc.JdbcIsolationDelegate.delegateWork(JdbcIsolationDelegate.java:65)
	at org.hibernate.id.MultipleHiLoPerTableGenerator.generate(MultipleHiLoPerTableGenerator.java:213)
	- locked <0x00000005c40a8b00> (a org.hibernate.id.MultipleHiLoPerTableGenerator)

点击dominator_tree，选择分组方式Group by package，在树形图找到PoolingDataSource。

右键 List objects -> with outgoing references

点击_pool观察左侧Attributes栏。关键信息如下——

• idleObjects

  空闲连接队列，右键Go into观察变量count的值等于0，表示空闲连接队列没有节点。

• minIdle

  最小空闲连接数，默认为0。

• maxIdle

  最大空闲连接数，默认为8。

• returnedCount

  归还连接计数器，useCount = borrowedCount - returnedCount，计算结果表示当前正在使用的连接数为8个。

• borrowedCount

  借出连接计数器，useCount = borrowedCount - returnedCount，计算结果表示当前正在使用的连接数为8个。

• maxWaitMillis

  等待获取连接的最大时长。-1表示无限等待。

• maxTotal

  最大连接数，默认为8。

结论——

根据堆dump中的参数值进行分析得出，最大只有8个数据库连接并且所有连接而且都在使用中。超时时间设置成无限等待，因此造成一系列的阻塞问题。

进一步查找原因为该应用升级所致，WEB服务器从支持Tomcat7升级到支持Tomcat8，Tomcat7/8分别使用数据源为dbcp/dbcp2，而配置仍然使用的是dbcp，因此造成配置无效。

附录——

common-dbcp2数据库连接池参数说明