7点微信公众号:请点这里。7点测试网QQ总群:277957570。

7点测试网

 找回密码
 注册7点

QQ登录

只需一步,快速开始

查看: 941|回复: 0
打印 上一主题 下一主题

BTrace实际案例分析

[复制链接]
跳转到指定楼层
1#
发表于 2013-12-3 14:44:57 | 只看该作者 |只看大图 回帖奖励 |倒序浏览 |阅读模式
BTrace实际案例分析

问题表象


问题描述

1.最近有项目组的童鞋反馈,web页面频繁出现假死的状态。

2.web页面的假死出现是概率事件,且无法确定假死的引发原因。

3.是在一定的操作之后出现的,但是无法确定究竟是哪些操作引发这些操作。

问题分析


初步分析

我们都知道web容器一般都是单实例多线程的方式工作的,当页面发起请求后,tomcat发分配一个线程进行当前请求的处理,当出现页面假死,说明是由于某种原因导致了线程在等待某种资源,可以是IO、网络响应、数据库连接、等待锁等等,所以需要首先确定该线程是在等待什么资源。



经过初步分析,可以知道是线程阻塞导致web不能够及时返回给页面响应,导致页面出现假死的情况。所以首先确定导致线程阻塞的原因。



确定线程是由于什么原因导致的阻塞其实也是比较简单的,可以使用jstack工具,到出现阻塞现象后,使用jstack工具查看器堆栈,看下是等待什么。也可以使用Eclipse的debug功能,将当前线程suspend。在这里我采用第二种方式。



操作步骤

在本地以Debug方式启动Tomcat应用,模拟一些操作,尽量将假死项目重现,开发人员根据以往的映像去操作一些功能,过了若干时间后,果然出现了假死现象。由于是debug方式启动所以查看其debug视图,发现启动了3个http线程,下图中红色部分标示的位置。







通过右击suspend挂起线程,发现有一个线程确实被阻塞掉了





观察堆栈可以确定是到连接池中去获取连接,但是当前连接池中无可用的连接,导致线程阻塞出现页面假死现象。

进一步分析

很明显这个是由于连接泄露导致无可用连接,所引起的线程阻塞,页面假死。查看连接池配置:

driver=oracle.jdbc.driver.OracleDriver

url=jdbcracle:thin127.0.0.1:1521rcl

username=****

password=****

active=20

minidle=20

maxidle=20

maxwait=-1

出现连接泄露问题是较为难定位的问题,因为问题的表象离问题的根源较远,并没有直接的联系,所以只能凭经验和感觉去分析,另外出现该情况应当尽量将连接池连接个数配置改小,这样可以有效的拉近问题表象和问题根源之间的距离,减小问题重现的成本和最大化问题重现的概率。然后根据BTrace来进行分析。但是我们这里有BTrace这个利器来进行动态诊断。

诊断思路

只要跟踪所有的调用过BasicDataSource.getConnection这个方法的地方,然后在看看那些方法调用以后没有关系连接,而关闭连接的地方并非是Connection的close方法,需要对连接池的工作原理有一定的了解。







如上图,连接池持有Connection代理的引用,用来维护Connection,而Connection代理实现了JDBC,通过Connection代理来操作驱动程序,在oracle中是oracle.jdbc.driver.T4CConnection。





实际上连接池主要是通过PoolableConnection作为代理类,持有T4CConnection的引用,完成对数据的操作,并且自己实现了java.sql.Connection接口,我们看下close方法的具体实现。

Java代码
1./**  
2.     * Returns me to my pool.  
3.     */  
4.     public synchronized void close() throws SQLException {   
5.        if (_closed) {   
6.            // already closed   
7.            return;   
8.        }   
9.  
10.        boolean isUnderlyingConectionClosed;   
11.        try {   
12.            isUnderlyingConectionClosed = _conn.isClosed();   
13.        } catch (SQLException e) {   
14.            try {   
15.                _pool.invalidateObject(this); // XXX should be guarded to happen at most once   
16.            } catch(IllegalStateException ise) {   
17.                // pool is closed, so close the connection   
18.                passivate();   
19.                getInnermostDelegate().close();   
20.            } catch (Exception ie) {   
21.                // DO NOTHING the original exception will be rethrown   
22.            }   
23.            throw (SQLException) new SQLException("Cannot close connection (isClosed check failed)").initCause(e);   
24.        }   
25.  
26.        if (!isUnderlyingConectionClosed) {   
27.            // Normal close: underlying connection is still open, so we   
28.            // simply need to return this proxy to the pool   
29.            try {   
30.                _pool.returnObject(this); // XXX should be guarded to happen at most once   
31.            } catch(IllegalStateException e) {   
32.                // pool is closed, so close the connection   
33.                passivate();   
34.                getInnermostDelegate().close();   
35.            } catch(SQLException e) {   
36.                throw e;   
37.            } catch(RuntimeException e) {   
38.                throw e;   
39.            } catch(Exception e) {   
40.                throw (SQLException) new SQLException("Cannot close connection (return to pool failed)").initCause(e);   
41.            }   
42.        } else {   
43.            // Abnormal close: underlying connection closed unexpectedly, so we   
44.            // must destroy this proxy   
45.            try {   
46.                _pool.invalidateObject(this); // XXX should be guarded to happen at most once   
47.            } catch(IllegalStateException e) {   
48.                // pool is closed, so close the connection   
49.                passivate();   
50.                getInnermostDelegate().close();   
51.            } catch (Exception ie) {   
52.                // DO NOTHING, "Already closed" exception thrown below   
53.            }   
54.            throw new SQLException("Already closed.");   
55.        }   
56.}  


而获取连接的代码是通过PoolingDataSource的getConnection进行获取的代码如下:

Java代码
1./**  
2.     * Return a {@link java.sql.Connection} from my pool,  
3.     * according to the contract specified by {@link ObjectPool#borrowObject}.  
4.     */  
5.    public Connection getConnection() throws SQLException {   
6.        try {   
7.            Connection conn = (Connection)(_pool.borrowObject());   
8.            if (conn != null) {   
9.                conn = new PoolGuardConnectionWrapper(conn);   
10.            }   
11.            return conn;   
12.        } catch(SQLException e) {   
13.            throw e;   
14.        } catch(NoSuchElementException e) {   
15.            throw new SQLNestedException("Cannot get a connection, pool error " + e.getMessage(), e);   
16.        } catch(RuntimeException e) {   
17.            throw e;   
18.        } catch(Exception e) {   
19.            throw new SQLNestedException("Cannot get a connection, general error", e);   
20.        }   
21.    }   
可以非常清楚的看到,就是通过该方法释放连接到连接池中,供后续的业务代码进行调用。
到这里基本的思路已经出来了,只要跟踪PoolingDataSource的getConnection方法和PoolableConnection的close方法就可以知道究竟哪些业务代码只调用了获取连接而没有调用close方法进行释放连接,导致连接泄露。

BTrace利器


通过编写BTrace脚本进行分析跟踪,只要业务代码在调用完getConnection方法后调用了close就说明没有问题,也就是getConnection方法和close方法成对出现,如果只调用了getConnection方法而没有调用close方法那就说明该业务代码有连接泄露。

Java代码
1.import com.sun.btrace.annotations.*;   
2.import static com.sun.btrace.BTraceUtils.*;   
3.  
4.@BTrace public class BTraceConnection {   
5.      
6.    @Export private static long openedCount;   
7.      
8.    @Export private static long closedCount;   
9.      
10.    @OnMethod(clazz="/.*PoolingDataSource/", method="getConnection", location=@Location(kind.RETURN))   
11.    public static void m(@return Object obj) {   
12.            openedCount++;   
13.                println("One connection is opened!");   
14.                println(obj);   
15.            Threads.jstack();   
16.    }   
17.      
18.    @OnMethod(clazz="/.*PoolableConnection/", method="close")   
19.    public static void d(@Self Object obj) {   
20.            closedCount++;   
21.                println("One connection is closed!");   
22.                println(obj);   
23.            Threads.jstack();   
24.    }   
25.      
26.    @OnExit  
27.    public static void f(){   
28.          print("Total opened connection:");   
29.          println(openedCount);   
30.          print("Total closed connection:");   
31.          println(closedCount);   
32.    }   
33.      
34.}  
将连接池个数修改为3,启动应用,使用jps输出应用pid,

运行命令btrace <pid> BTraceConnection.java > trace.log

日志分析


输出结果

Java代码
1.One connection is opened!   
2.org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@1d6fc56  
3.org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)   
4...................   
5.com.***************************.dao.UserDAO.checkUserState(UserDAO.java:142)   
6...................   
7.java.lang.Thread.run(Thread.java:619)   
8.One connection is opened!   
9...................   
10.Total opened connection:61  
11.Total closed connection:57  
部分无用内容有删减,发现总共获取了61次connection,释放了57次connection,com.***************************.dao.UserDAO.checkUserState(UserDAO.java:142)该方法没有释放连接,最终定位出了有问题的方法。
分享到:  QQ好友和群QQ好友和群 QQ空间QQ空间 腾讯微博腾讯微博 腾讯朋友腾讯朋友
收藏收藏 分享分享
您需要登录后才可以回帖 登录 | 注册7点

本版积分规则

QQ|小黑屋|手机版|Archiver|7点测试网 ( 京ICP备09084002号

GMT+8, 2018-2-21 11:16 , Processed in 0.227666 second(s), 27 queries .

Powered by Discuz! X3.1

© 2001-2013 Comsenz Inc.

快速回复 返回顶部 返回列表