BTrace实际案例分析_JAVA_编程开发_程序员俱乐部

class="MsoNormal">问题表象

问题描述

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=jdbc:oracle:thin:@127.0.0.1:1521:orcl

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方法的具体实现。

?

?

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进行获取的代码如下：

?

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方法那就说明该业务代码有连接泄露。

?

?

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

日志分析

输出结果

?

?

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)该方法没有释放连接，最终定位出了有问题的方法。