문제 상황
마이크로서비스 프로젝트를 개발하던 중, 데이터베이스 연결 생성 과정에서 블로킹 상태에 빠지는 문제가 발생했습니다. 프로그램이 로그를 출력한 후 멈춰서 더 이상 새로운 로그가 표시되지 않았습니다. 이에 Arthas를 사용하여 문제를 추적하고, 발견된 원인을 해결했습니다.
환경
| 소프트웨어 | 버전 |
|---|---|
| JDK | 1.8 |
| Spring Boot | 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로의 매핑은 JVM 구현에 의해 결정됩니다. 초기화 과정은 다음과 같습니다:
- C의 초기화 잠금 LC를 동기화합니다. 현재 스레드가 LC를 획득할 때까지 대기합니다.
- 다른 스레드가 C를 초기화 중이면 LC를 해제하고, 완료될 때까지 현재 스레드를 차단한 후 이 단계를 반복합니다.
- 현재 스레드가 C를 초기화 중이면 재귀적 요청으로 간주하여 LC를 해제하고 정상 종료합니다.
- C가 이미 초기화되었으면 추가 작업 없이 LC를 해제하고 정상 종료합니다.
- C가 오류 상태이면 초기화할 수 없으며, LC를 해제하고
NoClassDefFoundError를 던집니다.- 그렇지 않으면 현재 스레드가 C를 초기화 중임을 기록하고 LC를 해제한 후, 컴파일 타임 상수 표현식의 인터페이스에 대한 최종 클래스 변수와 필드를 초기화합니다.
문제가 발생한 순서를 정리하면 다음과 같습니다:
-
Thread-29가
Oracle데이터베이스 연결을 초기화하려고 합니다. 이 과정에서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 드라이버 구현 클래스를 찾습니다. -
Thread-1이
Sybase데이터베이스 연결을 생성하려고 하면서DriverManager.class에 잠금을 겁니다. 그러나DriverManager가 아직 초기화 중이므로, Thread-1은 초기화가 완료될 때까지 대기합니다. 다음은 관련 코드입니다: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) { } } -
Thread-29는 모든 드라이버 클래스를 로드해야 합니다. 아직 완료되지 않은 상태에서
com.microsoft.sqlserver.jdbc.SQLServerDriver를 로드 중이며, 이 과정에서DriverManager.registerDriver(new SQLServerDriver())메서드를 호출해야 합니다. 이 메서드는 잠금이 필요합니다. 그런데 Thread-1이DriverManager를 이미 잠갔고, 초기화가 완료되지 않아 잠금이 해제되지 않은 상태입니다. 두 스레드가 서로 필요한 잠금을 보유하게 되어데드락이 발생한 것입니다.
해결 방법
JDBC 드라이버 클래스를 동시에 로드하지 않도록 합니다. 또는 특정 스레드에서 데이터베이스 관련 로드를 지연시키는 우회 방법을 사용할 수 있습니다. 이렇게 하면 문제 발생 가능성을 크게 줄일 수 있습니다.
결과
데드락 문제가 해결되었고, 프로그램이 정상적으로 실행되었습니다.
요약
이 경험을 통해 점에서 면으로 확장하여 많은 것을 배울 수 있었습니다. 원인을 알면 결과를 이해할 수 있고, 그래야 지속적으로 발전할 수 있습니다.
확장
클래스 초기화에 대한 공식 문서는 다음 링크를 참고하세요.