0
点赞
收藏
分享

微信扫一扫

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

 

Java代码  

1. /**
2.      * Returns me to my pool.
3.      */
4. public synchronized void close() throws
5. if
6. // already closed
7. return;  
8.         }  
9.   
10. boolean
11. try
12.             isUnderlyingConectionClosed = _conn.isClosed();  
13. catch
14. try
15. 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
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
27. // Normal close: underlying connection is still open, so we
28. // simply need to return this proxy to the pool
29. try
30. 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
37. catch(RuntimeException e) {  
38. throw
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. 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
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
6. try
7.             Connection conn = (Connection)(_pool.borrowObject());  
8. if (conn != null) {  
9. new
10.             }   
11. return
12. catch(SQLException e) {  
13. throw
14. catch(NoSuchElementException e) {  
15. throw new SQLNestedException("Cannot get a connection, pool error "
16. catch(RuntimeException e) {  
17. throw
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
2. import static
3.   
4. @BTrace public class
5.       
6. @Export private static long
7.       
8. @Export private static long
9.       
10. @OnMethod(clazz="/.*PoolingDataSource/", method="getConnection", location=@Location(kind.RETURN))  
11. public static void m(@return
12.             openedCount++;  
13. "One connection is opened!");  
14.                 println(obj);  
15.             Threads.jstack();  
16.     }  
17.       
18. @OnMethod(clazz="/.*PoolableConnection/", method="close")  
19. public static void d(@Self
20.             closedCount++;  
21. "One connection is closed!");  
22.                 println(obj);  
23.             Threads.jstack();  
24.     }  
25.       
26. @OnExit
27. public static void
28. "Total opened connection:");  
29.           println(openedCount);  
30. "Total closed connection:");  
31.           println(closedCount);   
32.     }  
33.       
34. }

 

 

将连接池个数修改为3,启动应用,使用jps输出应用pid,

 

 

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

日志分析

输出结果

 

 

BTrace实际案例分析_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)该方法没有释放连接,最终定位出了有问题的方法。

举报

相关推荐

0 条评论