一个坑爹的故障

告诉别人一个不实的事情,还不如不告诉别人这个事情。因为这个不实的事实会影响到一个人的世界观,对事情的看法和判断。我们从小就接收这种教育。大家都懂的。。。。。

团队里面有个同事遇到一个问题,大致情况这样的。Web工程用了C3P0/Spring/Ibatis框架,用了Maven管理类库和发布,Web容器启动后初始化时会从数据库加载数据到内存中,本机在Eclipse/Jetty环境下运行没有任何问题。

程序发布到测试机器上,启动Jetty非常慢,进程卡死在某个地方。。。dump JVM 线程信息如下:

 
"ModelService thread" daemon prio=10 tid=0x00002aaab4993000 nid=0x9fb in Object.wait() [0x0000000040fee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007f2d22b70> (a com.mchange.v2.resourcepool.BasicResourcePool)
	at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
	at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
	- locked <0x00000007f2d22b70> (a com.mchange.v2.resourcepool.BasicResourcePool)
	at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
	at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:113)
	at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy
.java:210)
	at $Proxy7.prepareStatement(Unknown Source)
	at com.ibatis.sqlmap.engine.execution.SqlExecutor.prepareStatement(SqlExecutor.java:497)
	at com.ibatis.sqlmap.engine.execution.SqlExecutor.executeQuery(SqlExecutor.java:175)
	at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.sqlExecuteQuery(MappedStatement.java:221)
	at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeQueryWithCallback(MappedStatement.java:189)
	at com.ibatis.sqlmap.engine.mapping.statement.MappedStatement.executeQueryForList(MappedStatement.java:139)
	at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForList(SqlMapExecutorDelegate.java:567)
	at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.queryForList(SqlMapExecutorDelegate.java:541)
	at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.queryForList(SqlMapSessionImpl.java:118)
	at com.alibaba.dragoon.patrol.spring.SqlMapExecutorWrapper.queryForList(SqlMapExecutorWrapper.java:386)
	at org.springframework.orm.ibatis.SqlMapClientTemplate$3.doInSqlMapClient(SqlMapClientTemplate.java:298)
	at org.springframework.orm.ibatis.SqlMapClientTemplate.execute(SqlMapClientTemplate.java:209)
	at org.springframework.orm.ibatis.SqlMapClientTemplate.executeWithListResult(SqlMapClientTemplate.java:249)
	at org.springframework.orm.ibatis.SqlMapClientTemplate.queryForList(SqlMapClientTemplate.java:296)
	at org.springframework.orm.ibatis.SqlMapClientTemplate.queryForList(SqlMapClientTemplate.java:290)
	at com.xx.xxx.XXXBean.findxxxx(XXXBean.java:26) //业务方法,就是这个方法在初始化的时候被调用。

从dump纪录上看,执行这个业务方法时C3P0得不到可用的数据库链接??系统的日志级别时[INFO],但此时程序中没有任何错误日志产生。

在测试机器上用mysql命令可以链接到数据库,排除了无法链接数据库的故障。猜测,可能是初始化的时候有资源竞争?调整程序,重新发布,发现还不行。。再次把问题焦点定位到数据库上,查看了C3P0的配置,没有发现什么问题呢。。。

因为工程业务比较复杂,既然怀疑是数据库链接环节有问题,用 C3P0单独写一个测试程序看看。于是把项目的war文件展开,到WEB-INF/lib 下找C3P0和MySQL驱动的Jar文件,靠,竟然找不到MySQL驱动文件?问题原因找到了,肯定是没有MySQL驱动引起的,为什么发布程序没有把MySQL驱动发布上去了,查看POM文件,发现是配置环境搞错了。重新发布,启动Jetty没有任何问题。。。

但是,没有MySQL驱动情况下,系统应该抛出NotFoundClass错误啊,但是没有输出这个日志。只是一个无法获得链接的线程在那里等待。。于是找到了对应版本的C3P0代码。

    try
        {
            if (! isDriverClassLoaded())
            {
                if (driverClass != null)
                    Class.forName( driverClass );
                setDriverClassLoaded( true );
            }
        }
        catch (ClassNotFoundException e)
        {
            if (logger.isLoggable(MLevel.WARNING))
                logger.log(MLevel.WARNING, "Could not load driverClass " + driverClass, e);
        }

从代码上看,当没有找到驱动的时候并没有throw 异常,程序的流程还会继续走,这是为啥获得链接的线程一直等待中。另一方面,在catch代码快中,对这个错误的处理过于简单了,这种错误还要判断日志的级别吗?最好直接输出到stderr上。。。。

总之,这是一个啃爹的问题。。。