文档章节

解Bug之路-Druid的Bug

无毁的湖光-Al
 无毁的湖光-Al
发布于 2017/05/15 10:48
字数 1818
阅读 4039
收藏 119

解Bug之路-Druid的Bug

笔者很热衷于解决Bug,同时比较擅长(网络/协议)部分,所以经常被唤去解决一些网络IO方面的Bug。现在就挑一个案例出来,写出分析思路,以飨读者,希望读者在以后的工作中能够少踩点坑。

前言

此Bug是Druid低版本的Bug,此Bug至少在1.0.12版本就已经修复。

Druid的Bug现场

在紧张的新项目开发的日子里,突然收到线上某系统的大量报警,对应系统的人员发现此系统在某一台机器上dump了大量的error日志。日志基本都是:

Druid:  GetConnectionTimeoutException

此系统所有用到数据库的地方都抛出此异常。于是祭出重启大法,重启过后,一切Okay。然后对应的系统人员开始排查这个问题,一直没有结果。
过了两天,又收到此类型的error日志报警,而且这一次是有两台系统同时爆出此种错误。紧急重启后,将此问题紧急报到我们这边处理。鉴于本人有丰富的IO处理经验,当然落到了本人头上。

Bug复盘

此系统是通过Druid连接后面的数据库分库分表Proxy,再由此Proxy连接后面的数据库。示意图如下所示:
输入图片说明

缩小Bug范围

获取连接超时(GetConnectionTimeoutException)此错误的出现,只有两种可能:

1.业务系统本身Druid获取连接失败。    
2.作为中间件的Sharding Proxy获取连接失败。         

在这个Bug里面很明显是Druid创建连接失败,原因如下:

1.此系统有10多台机器,仅仅有两台出现此种故障。    
2.这两台重启后一切正常。  

如果说这两台是由于同机房问题出现统一的网络连接异常,那么并不能解释重启后正常这一现象。

Druid问题定位

于是开始分析为何获取连接超时,第一步当然是开始寻找源码中日志抛出异常点。上源码:

DruidConnectionHolder holder;
.......
try {
	if (maxWait > 0) {
	   holder = pollLast(nanos);
	}
	else {
	   holder = takeLast();
	}
	......
}finally {
    lock.unlock();
}
if(holder == null){
   ......
	if (this.createError != null) {
        throw new GetConnectionTimeoutException(errorMessage, createError);
    } else {
        throw new GetConnectionTimeoutException(errorMessage);
    }   
}

可见,这边获取到的DruidConnectionHolder为null,则抛出异常。

Druid获取连接的过程

在分析这个问题之前,先得看下Druid是如何创建连接的,下面是本人阅读Druid源码后画的示意图:
输入图片说明
可见druid创建连接都是通过一个专门的线程来进行的,此图省略了大量的源码细节。

为何Holde为null?

继续上源码

private DruidConnectionHolder pollLast(long nanos) throws InterruptedException, SQLException {
    for (;;) {
        if (poolingCount == 0) {
            emptySignal(); // send signal to CreateThread create connection

            if (estimate <= 0) {
                waitNanosLocal.set(nanos - estimate);
                return null;
            }
            ...
            try {
                long startEstimate = estimate;
                estimate = notEmpty.awaitNanos(estimate); 
                ......
            } finally {
              ......
            }
            ......
            if (poolingCount == 0) {
                if (estimate > 0) {
                    continue;
                }
                waitNanosLocal.set(nanos - estimate);
                return null;
            }
        }
        decrementPoolingCount();
        DruidConnectionHolder last = connections[poolingCount];
        connections[poolingCount] = null;
        return last;
    }
}

可见,如果触发条件,estimate<=0,则返回null。
上述源码的过程示意图如下:
输入图片说明

继续追踪

由此可见,在获取连接的时候一直超时,不停的爆GetConnectionTimeoutException异常,明显是由于创建连接线程出了问题。那到底除了什么问题呢?由于Druid的代码比较多,很难定位问题点,于是还从日志入手。

进一步挖掘日志

错误信息量最大的是最初出现错误的时间点,这是笔者多年排查错误的经验总结。由于正好有两台出错,比较其错误的共同点也能对解决问题大有裨益。

大量create connection error

当笔者和同事追查错误的源头的时候,在有大量的create connection error,奇怪的是,到了一个时间点之后,就只剩GetConnectionTimeoutException异常了。
继续分析,在出现create connection error的时候,还是有部分业务请求能够执行的。即获取到了连接。
翻了翻源码,create connection error是在创建连接线程打印的,如果这个异常没有继续打印,而同时连接也获取不到,就在很大程度上表明:

创建连接根本就是被销毁了!  

错误分界点

于是开始寻找什么时候create connection error开始销毁。于是通过笔者和同事在无数的错误日志中用肉眼发现了一个不寻常的日志隐蔽在大量的错误日志间:

Druid:create holder error

在这个错误出现之后,就再也没有了create connection error,翻了翻另一台机器的日志,页是同样的现象!

源码寻找Bug

隐隐就感觉这个日志是问题错误的关键,打出这个日志的源码为:

创建连接线程
@Override
public void run() {
            runInternal();
}

private void runInternal() {

    for (; ; ) {
        ......
        try{
            holder = new DruidConnectionHolder(DruidDataSource.this,connection);
        }catch(SQLException ex){
            LOG.error("create connection holder error",ex);
            // 这句break就是罪魁祸首
            // 至少在1.0.12修复
            break;
        }
        ......
    }
}

这边竟然在for(;;)这个死循环中break了!!!,那么这个线程也在break后跳出了死循环从而结束了,也就是说创建连接线程被销毁了!!!如下图所示:
输入图片说明

为何create holder error?

继续搜寻日志,发现create holder error之前,会有获取事务隔离级别的报错。那么结合源码,错误的发生如下图:
输入图片说明
即在Druid的创建连接线程创建连接成功之后,还需要拿去数据库的holdability,isolation(隔离级别)等MetaData,在获取MetaData失败的时候,则会抛出异常,导致创建连接线程Break。
但是如果在handshake的时候就失败,那么由于Druid处理了这种异常,打印create connection error,并继续创建连接。
于是就有了在create holder error之前大量create connection error,在这之后没有了的现象。

完结了么?

Druid的Bug是弄清楚了,但是为何连接如此不稳定,有大量的创建连接异常,甚至于Druid前脚创建连接成功,后脚发送命令就失败呢?

Sharding Proxy的Bug

于是此问题又萦绕在笔者心头,在又一番不下于上述过程的努力之后,发现一个月之前上线的新版本的Sharding Proxy的内存泄露Bug导致频繁GC(并定位内存泄露点),导致了上述现象,如下图所示:
输入图片说明
由于每次内存泄露过小,同时Sharding Proxy设置的内存过大。所以上线后过了一个月才有频繁的GC现象。之前上线后,大家观察了一周,发现没有任何异常,就不再关注。与此类似,如果DB负载过高的话,笔者推测也会触发Druid的Bug。

最后处理

笔者去翻Druid最新源码,发现此问题已经修复,紧急联系各业务线升级Druid,同时让Sharding Proxy负责人修改了最新代码并上线。
终于这次的连环Bug算是填完了。

总结

追查Bug,日志和源码是最重要的两个部分。最源头的日志信息量最大,同时要对任何不同寻常的现象都加以分析并推测,最后结合源码,才能最终找出Bug。

原文链接

https://my.oschina.net/alchemystar/blog/899987

© 著作权归作者所有

无毁的湖光-Al

无毁的湖光-Al

粉丝 460
博文 31
码字总数 54420
作品 0
浦东
后端工程师
私信 提问
加载中

评论(51)

无毁的湖光-Al
无毁的湖光-Al 博主

引用来自“张明明-技术”的评论

图是用什么工具画的?很不错!

@张明明-技术 mac上的omnigraffle
QNo8312
QNo8312
图是用什么工具画的?很不错!
无毁的湖光-Al
无毁的湖光-Al 博主

引用来自“zengjin_”的评论

花哥666👍

@zengjin_ :) 必须6
哼哈2
花哥666👍
无毁的湖光-Al
无毁的湖光-Al 博主

引用来自“呼呼南风”的评论

厉害

@呼呼南风 :)
呼呼南风
呼呼南风
厉害
无毁的湖光-Al
无毁的湖光-Al 博主

引用来自“pointerException”的评论

666

@pointerException :)
pointerException
pointerException
666
无毁的湖光-Al
无毁的湖光-Al 博主

引用来自“叶绘飛”的评论

学习
:)
叶绘飛
学习
java.lang.OutOfMemoryError: Failed to allocate a 257909772 byte allocation with 4184720 free byte...

前言 今天在做项目的时候,出现了一个很郁闷的bug,然后调了好半天才找到问题。在此做下记录吧。 今天涉及的内容: 出现bug时的项目背景 bug内容 寻解路径 最终原因及解决办法 一. 出现bug时...

奔跑的佩恩
11/13
0
0
Druid 0.2.10 发布, Java数据库连接池

Druid 0.2.10发布 这个版本主要是bug fixed和增强WallFilter。 源码 https://github.com/AlibabaTech/druid 文档 https://github.com/AlibabaTech/druid/wiki/%E5%B8%B8%E8%A7%81%E9%97%AE%......

wenshao
2012/12/24
2.3K
17
阿里开源数据库连接池Druid发布0.2.12版本

这是一个Bug fixed版本。修复的BUG基本都是和SQL Parser相关。 代码托管 https://github.com/alibaba/druid 文档 https://github.com/alibaba/druid/wiki/%E5%B8%B8%E8%A7%81%E9%97%AE%E9%A......

wenshao
2013/03/13
4.2K
10
Druid 发布 0.2.11 版本,数据库连接池

这个版本主要是进一步提升sql parser性能,增强对sql server的支持,还有几个小的bug fixed。 Release Notes http://code.alibabatech.com/jira/secure/ReleaseNote.jspa?projectId=10030&v...

wenshao
2013/01/23
1K
13
Druid 0.2.17 发布,阿里巴巴数据库连接池

阿里巴巴开源连接池druid发布0.2.17版本。修复数据库故障时连接池的BUG,增强SQL Parser,增强监控,增强SQL防注入。 Bug [DRUID-232] - 连接Oracle设置queryTimeout出错 [DRUID-240] - 修正...

wenshao
2013/05/01
1K
19

没有更多内容

加载失败,请刷新页面

加载更多

02.日志系统:一条SQL更新语句是如何执行的?

我们还是从一个表的一条更新语句说起,我们创建下面一张表: create table T(ID int primary key, c int); 如果要将ID=2这一行c的值加1,SQL可以这么写: update T set c=c+1 where ID=2; 前...

scgaopan
今天
7
0
【五分钟系列】掌握vscode调试技巧

调试前端js 准备一个前端项目 index.html <!DOCTYPE html><html lang="en"><head> <meta charset="UTF-8"> <meta name="viewport" content="width=device-width, initial-scale=1......

aoping
今天
6
0
PhotoShop 高级应用:USM锐化/S锐化/防抖

、 高反差锐化+混合模式:叠加模式 【将更多的边缘细节添加到图像中】

东方墨天
今天
7
0
Python数据可视化之matplotlib

常用模块导入 import numpy as npimport matplotlibimport matplotlib.mlab as mlabimport matplotlib.pyplot as pltimport matplotlib.font_manager as fmfrom mpl_toolkits.mplot3d i......

松鼠大帝
昨天
5
0
我用Bash编写了一个扫雷游戏

我在编程教学方面不是专家,但当我想更好掌握某一样东西时,会试着找出让自己乐在其中的方法。比方说,当我想在 shell 编程方面更进一步时,我决定用 Bash 编写一个扫雷游戏来加以练习。 我在...

老孟的Linux私房菜
昨天
9
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部