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

系列文章——

     生产环境实践(一):保存运行时信息(堆栈、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数据库连接池参数说明

  • 2
    点赞
  • 10
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值