问题场景
开发微服务项目的时候,发现数据库链接创建过程中,陷入了阻塞状态。表现形式为:程序输出日志之后,便卡死不动,不再显示新的日志。于是使用arthas
进行问题跟踪,并根据发现的问题,针对性解决!
问题环境
软件 | 版本 |
---|---|
JDK | 1.8 |
springboot | 2.1.1.RELEASE |
hutool | 5.5.5 |
问题原因
以下是使用arthas
的有关命令,各位读者可以一览:
[arthas@22366]$ dashboard
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
46 Timer-for-arthas-dashboard-0cd6726c-c0c3-4fa0- system 10 RUNNABLE 91 0:0 false true
26 SimplePauseDetectorThread_0 system 9 TIMED_WAITING 8 0:0 false true
31 Abandoned connection cleanup thread main 5 TIMED_WAITING 0 0:0 false true
16 AsyncResolver-bootstrap-0 main 5 TIMED_WAITING 0 0:0 false true
35 AsyncResolver-bootstrap-executor-0 main 5 WAITING 0 0:0 false true
36 Attach Listener system 9 RUNNABLE 0 0:0 false true
17 DiscoveryClient-0 main 5 TIMED_WAITING 0 0:0 false true
34 DiscoveryClient-1 main 5 WAITING 0 0:0 false true
33 DiscoveryClient-CacheRefreshExecutor-0 main 5 WAITING 0 0:0 false true
15 Eureka-JerseyClient-Conn-Cleaner2 main 5 TIMED_WAITING 0 0:0 false true
3 Finalizer system 8 WAITING 0 0:0 false true
2 Reference Handler system 10 WAITING 0 0:0 false true
5 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
25 Thread-5 system 9 WAITING 0 0:0 false true
29 Thread-7 main 5 BLOCKED 0 0:0 false false
30 Timer-0 main 5 TIMED_WAITING 0 0:0 false true
[arthas@22366]$ thread --state BLOCKED
Threads Total: 29, NEW: 0, RUNNABLE: 7, BLOCKED: 1, WAITING: 11, TIMED_WAITING: 10, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
29 Thread-7 main 5 BLOCKED 0 0:0 false false
Affect(row-cnt:0) cost in 102 ms.
[arthas@22366]$ thread 29
"Thread-7" Id=29 BLOCKED on java.lang.Class@5a6f639c owned by "main" Id=1
at java.sql.DriverManager.registerDriver(DriverManager.java:334)
- blocked on java.lang.Class@5a6f639c
at com.microsoft.sqlserver.jdbc.SQLServerDriver.<clinit>(SQLServerDriver.java:903)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at java.lang.Class.newInstance(Class.java:442)
at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
at java.sql.DriverManager$2.run(DriverManager.java:603)
at java.sql.DriverManager$2.run(DriverManager.java:583)
at java.security.AccessController.doPrivileged(Native Method)
at java.sql.DriverManager.loadInitialDrivers(DriverManager.java:583)
at java.sql.DriverManager.<clinit>(DriverManager.java:101)
at oracle.jdbc.driver.OracleDriver.<clinit>(OracleDriver.java:188)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at java.lang.Class.newInstance(Class.java:442)
at com.zaxxer.hikari.HikariConfig.setDriverClassName(HikariConfig.java:501)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.zaxxer.hikari.util.PropertyElf.setProperty(PropertyElf.java:146)
at com.zaxxer.hikari.util.PropertyElf.lambda$setTargetFromProperties$0(PropertyElf.java:57)
at com.zaxxer.hikari.util.PropertyElf$$Lambda$587/493239805.accept(Unknown Source)
at java.util.Hashtable.forEach(Hashtable.java:879)
- locked cn.hutool.setting.dialect.Props@647b312d
at com.zaxxer.hikari.util.PropertyElf.setTargetFromProperties(PropertyElf.java:52)
at com.zaxxer.hikari.HikariConfig.<init>(HikariConfig.java:134)
at cn.hutool.db.ds.hikari.HikariDSFactory.createDataSource(HikariDSFactory.java:57)
at cn.hutool.db.ds.AbstractDSFactory.createDataSource(AbstractDSFactory.java:127)
at cn.hutool.db.ds.AbstractDSFactory.getDataSource(AbstractDSFactory.java:92)
- locked cn.hutool.db.ds.hikari.HikariDSFactory@2be25459
[arthas@22366]$ thread --state RUNNABLE
Threads Total: 29, NEW: 0, RUNNABLE: 7, BLOCKED: 1, WAITING: 11, TIMED_WAITING: 10, TERMINATED: 0
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTED DAEMON
49 as-command-execute-daemon system 10 RUNNABLE 100 0:0 false true
36 Attach Listener system 9 RUNNABLE 0 0:0 false true
5 Signal Dispatcher system 9 RUNNABLE 0 0:0 false true
1 main main 5 RUNNABLE 0 0:15 false false
39 nioEventLoopGroup-2-1 system 10 RUNNABLE 0 0:0 false false
44 nioEventLoopGroup-2-2 system 10 RUNNABLE 0 0:0 false false
40 nioEventLoopGroup-3-1 system 10 RUNNABLE 0 0:0 false false
Affect(row-cnt:0) cost in 103 ms.
[arthas@22366]$ thread 1
"main" Id=1 RUNNABLE
at java.sql.DriverManager.registerDriver(DriverManager.java:358)
- locked java.lang.Class@5a6f639c
at java.sql.DriverManager.registerDriver(DriverManager.java:334)
- locked java.lang.Class@5a6f639c
at com.sybase.jdbc4.jdbc.SybDriver.registerWithDriverManager(SybDriver.java:708)
- locked java.lang.Class@5a6f639c
at com.sybase.jdbc4.jdbc.SybDriver.<init>(SybDriver.java:139)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at java.lang.Class.newInstance(Class.java:442)
at com.zaxxer.hikari.HikariConfig.setDriverClassName(HikariConfig.java:501)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.zaxxer.hikari.util.PropertyElf.setProperty(PropertyElf.java:146)
at com.zaxxer.hikari.util.PropertyElf.lambda$setTargetFromProperties$0(PropertyElf.java:57)
at com.zaxxer.hikari.util.PropertyElf$$Lambda$587/493239805.accept(Unknown Source)
at java.util.Hashtable.forEach(Hashtable.java:879)
- locked cn.hutool.setting.dialect.Props@657e32f4
at com.zaxxer.hikari.util.PropertyElf.setTargetFromProperties(PropertyElf.java:52)
at com.zaxxer.hikari.HikariConfig.<init>(HikariConfig.java:134)
at cn.hutool.db.ds.hikari.HikariDSFactory.createDataSource(HikariDSFactory.java:57)
at cn.hutool.db.ds.AbstractDSFactory.createDataSource(AbstractDSFactory.java:127)
at cn.hutool.db.ds.AbstractDSFactory.getDataSource(AbstractDSFactory.java:92)
- locked cn.hutool.db.ds.hikari.HikariDSFactory@69e98e1f
at cn.hutool.db.ds.DSFactory.get(DSFactory.java:111)
at cn.hutool.db.Db.use(Db.java:44)
从上面的命令结果可以看出,是有线程陷入死锁
了,导致了程序没办法继续往下执行。
那么,现在问题来了,是什么原因导致死锁
的发生。我们这里要先讲一个理论,关于类初始化
的加锁
场景:
同时使用相同的类或接口。还有一种可能性是,类或接口的初始化可以作为该类或接口初始化的一部分递归地请求;例如,类a中的变量初始值设定项可以调用不相关类B的方法,而不相关类B又可以调用类a的方法。Java虚拟机的实现负责使用以下过程进行同步和递归初始化。
该过程假设类对象已经过验证和准备,并且类对象包含表示以下四种情况之一的状态:
1. 该类对象已验证并准备好,但尚未初始化。
2. 这个类对象正被某个特定的线程T初始化。
3. 该类对象已完全初始化并可以使用。
4. 此类对象处于错误状态,可能是因为尝试初始化但失败。对于每个类或接口C,都有一个唯一的初始化锁LC。从C到LC的映射由Java虚拟机实现决定。初始化C的过程如下:
1. 同步C的初始化锁LC。这包括等待当前线程可以获取LC。
2. 如果C的类对象指示其他线程正在对C进行初始化,则释放LC并阻止当前线程,直到通知正在进行的初始化已完成,此时重复此步骤。
3. 如果C的类对象指示当前线程正在对C进行初始化,那么这必须是一个递归的初始化请求。释放LC并正常完成。
4. 如果C的类对象指示C已经初始化,则不需要进一步的操作。释放LC并正常完成。
5. 如果C的类对象处于错误状态,则无法进行初始化。释放LC并抛出NoClassDefFoundError。
6. 否则,记录当前线程正在初始化C的类对象,然后释放LC。 然后,初始化值为编译时常量表达式的接口的最终类变量和字段
我们这里可以理一下问题发生的原因:
-
线程29 要进行数据库链接初始化,而该数据库是
Oracle
数据库。在进行初始化的时候,获取了DriverManager
实例,这个时候因为DriverManager
未初始化,故进行了DriverManager
静态代码块的初始化,我们可以看上面的线程调用链:at java.sql.DriverManager.loadInitialDrivers(DriverManager.java:583) at java.sql.DriverManager.<clinit>(DriverManager.java:101) at oracle.jdbc.driver.OracleDriver.<clinit>(OracleDriver.java:188)
java.sql.DriverManager.loadInitialDrivers
函数会找出classpath下所有的jdbc驱动实现类。 -
线程1 在开始进行
Sybase
数据库链接的创建,在调用的时候,需要对DriverManager.class
进行了加锁。而此时因为DriverManager
处于初始化过程,还未初始化完毕,故程序暂停于此,等待其他线程通知该类初始化完毕。代码如下:protected void registerWithDriverManager() { try { Class var1 = DriverManager.class; synchronized(DriverManager.class) { DriverManager.registerDriver(this); Enumeration var2 = DriverManager.getDrivers(); while(var2.hasMoreElements()) { Driver var3 = (Driver)var2.nextElement(); if (var3 instanceof com.sybase.jdbcx.SybDriver && var3 != this) { DriverManager.deregisterDriver(var3); } } } } catch (SQLException var6) { } }
-
而第一步的线程29需要将全部的驱动类加载进去,这个时候还没有将全部驱动类加载完毕,正在加载
com.microsoft.sqlserver.jdbc.SQLServerDriver
。而这个类加载过程中,需要调用方法DriverManager.registerDriver(new SQLServerDriver());
,查看源码,可以知道该方法是需要被加锁的。而因为第二步DriverManager
被加锁了,并因为DriverManager
未初始化完毕导致锁未能释放。故陷入了两边都拿了对应的锁,这就形成了死锁
的情况!!!
解决方案
不要用并发的形式进行JDBC
驱动类的加载。也可以用取巧的方式,延迟一个线程中关于数据库的加载。这样就可以很大程度地避免该问题的发生。
结果
死锁问题得到解决,程序正常运行!!!
总结
从点到面,可以学到很多东西。知其然,知其所以然,才能不断地进步!!!
扩展
随缘求赞
如果我的文章对大家产生了帮忙,可以在文章底部点个赞或者收藏;
如果有好的讨论,可以留言;
如果想继续查看我以后的文章,可以点击关注
可以扫描以下二维码,关注我的公众号:枫夜之求索阁,查看我最新的分享!