Java DriverManager 와 Driver 구현체 간의 deadlock 발견 및 해결 과정 정리
Streamline 프로젝트 개발 작업 중 JDBC 관련 테스트를 하다가 이상하게 Storm worker 에서 초기화가 완료되지 않는 문제가 발견되었다. 보통은 stack dump 를 뜨면 deadlock 상태인 게 눈에 보이는데 (thread 들이 어떤 lock 을 쥐고 있고 어떤 lock 을 기다리고 있는지 id 기준으로 확인하면 얽히고 섥힌 게 보임) 이번에는 의심되는 thread 들이 모두 RUNNABLE 상태였다.
한참을 이리저리 보고 구글링도 했는데, 결과는 클래스 static 초기화 block 이 문제였다.
worker 의 jstack 결과 중 deadlock 과 관련된 두 개의 executor thread 만 뽑아 보면 아래와 같다.
"Thread-17-641-JDBC-RDB-executor[4 4]" #52 prio=5 os_prio=0 tid=0x00007f8aedb6f800 nid=0x742 in Object.wait() [0x00007f8a99036000]
java.lang.Thread.State: RUNNABLE
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 com.mysql.jdbc.Driver.<clinit>(Driver.java:49)
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:326)
..."Thread-7-631-JDBC-PHOENIX-executor[3 3]" #42 prio=5 os_prio=0 tid=0x00007f8aed6ea000 nid=0x738 in Object.wait() [0x00007f8a99a42000]
java.lang.Thread.State: RUNNABLE
at org.apache.phoenix.jdbc.PhoenixDriver.<clinit>(PhoenixDriver.java:128)
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:326)
...
두 executor thread 들의 상태가 모두 RUNNABLE 인데, in Object.wait() 가 표기되어 있다. SO 가라사대 이런 경우는 static block 에서 deadlock 발생했을 가능성이 높다고 한다. (링크는 잃어버려서 패스…) 이를 바탕으로 추적해보자.
일단 첫번째 thread 에서 HikariCP 가 MySQL 의 Driver 클래스를 로딩하면서 클래스 초기화가 수행되고, 클래스 초기화 과정에서 DriverManager 클래스 초기화가 호출된 것을 stack trace 에서 확인할 수 있다.
at java.sql.DriverManager.<clinit>(DriverManager.java:101)
at com.mysql.jdbc.Driver.<clinit>(Driver.java:49) //
// Register ourselves with the DriverManager
//
static {
try {
java.sql.DriverManager.registerDriver(new Driver());
} catch (SQLException E) {
throw new RuntimeException("Can't register driver!");
}
}DriverManager 에 객체를 등록하려고 시도하고 있다.
DriverManager 의 클래스 초기화 코드를 보면…
/**
* Load the initial JDBC drivers by checking the System property
* jdbc.properties and then use the {@code ServiceLoader} mechanism
*/
static {
loadInitialDrivers();
println("JDBC DriverManager initialized");
}
... private static void loadInitialDrivers() {
String drivers;
try {
drivers = AccessController.doPrivileged(new PrivilegedAction<String>() {
public String run() {
return System.getProperty("jdbc.drivers");
}
});
} catch (Exception ex) {
drivers = null;
}
// If the driver is packaged as a Service Provider, load it.
// Get all the drivers through the classloader
// exposed as a java.sql.Driver.class service.
// ServiceLoader.load() replaces the sun.misc.Providers()
AccessController.doPrivileged(new PrivilegedAction<Void>() {
public Void run() {
ServiceLoader<Driver> loadedDrivers = ServiceLoader.load(Driver.class);
Iterator<Driver> driversIterator = loadedDrivers.iterator();
/* Load these drivers, so that they can be instantiated.
* It may be the case that the driver class may not be there
* i.e. there may be a packaged driver with the service class
* as implementation of java.sql.Driver but the actual class
* may be missing. In that case a java.util.ServiceConfigurationError
* will be thrown at runtime by the VM trying to locate
* and load the service.
*
* Adding a try catch block to catch those runtime errors
* if driver not available in classpath but it's
* packaged as service and that service is there in classpath.
*/
try{
while(driversIterator.hasNext()) {
driversIterator.next();
}
} catch(Throwable t) {
// Do nothing
}
return null;
}
});
println("DriverManager.initialize: jdbc.drivers = " + drivers);
if (drivers == null || drivers.equals("")) {
return;
}
String[] driversList = drivers.split(":");
println("number of Drivers:" + driversList.length);
for (String aDriver : driversList) {
try {
println("DriverManager.Initialize: loading " + aDriver);
Class.forName(aDriver, true,
ClassLoader.getSystemClassLoader());
} catch (Exception ex) {
println("DriverManager.Initialize: load failed: " + ex);
}
}
}
여기서 포인트는 ServiceLoader 이다. ServiceLoader 가 class path 내 jar 들을 뒤져서 java.sql.Driver interface 의 구현체가 META-INF.services 디렉토리 내 등록되어 있는 지 확인하고(인터페이스명의 파일을 만들고 파일 내용에 구현체 클래스 명을 작성한다), 등록되어 있는 클래스들을 모두 초기화한다.
쭉 생략하고 실제로 Class 를 다루는 부분을 보자. 아래는 ServiceLoader$LazyIterator.nextService() 구현이다.
private S nextService() {
if (!hasNextService())
throw new NoSuchElementException();
String cn = nextName;
nextName = null;
Class<?> c = null;
try {
c = Class.forName(cn, false, loader);
} catch (ClassNotFoundException x) {
fail(service,
"Provider " + cn + " not found");
}
if (!service.isAssignableFrom(c)) {
fail(service,
"Provider " + cn + " not a subtype");
}
try {
S p = service.cast(c.newInstance());
providers.put(cn, p);
return p;
} catch (Throwable x) {
fail(service,
"Provider " + cn + " could not be instantiated",
x);
}
throw new Error(); // This cannot happen
}Class.forName() 호출 시 class 초기화를 하지 않도록 되어 있다. 그래서 stack trace 상 해당 부분에서 멈추지 않았고, c.newInstance() 로 객체를 만들 때 멈추었다.
이제 다음 thread 를 살펴보자. reflection 관련 라인들 제외하면 맨 윗 라인이 포인트이다.
at org.apache.phoenix.jdbc.PhoenixDriver.<clinit>(PhoenixDriver.java:128)두 번째 thread 는 PhoenixDriver 의 클래스 초기화에서 멈췄다.
여기서 PhoenixDriver 의 코드를 잠깐 보자면…
public static final PhoenixDriver INSTANCE;static {
try {
INSTANCE = new PhoenixDriver();
try {
// Add shutdown hook to release any resources that were never closed
// In theory not necessary, but it won't hurt anything
Runtime.getRuntime().addShutdownHook(new Thread() {
@Override
public void run() {
closeInstance(INSTANCE);
}
});
// Only register the driver when we successfully register the shutdown hook
// Don't want to register it if we're already in the process of going down.
DriverManager.registerDriver( INSTANCE );
} catch (IllegalStateException e) {
logger.warn("Failed to register PhoenixDriver shutdown hook as the JVM is already shutting down");
// Close the instance now because we don't have the shutdown hook
closeInstance(INSTANCE);
throw e;
}
} catch (SQLException e) {
throw new IllegalStateException("Unable to register " + PhoenixDriver.class.getName() + ": "+ e.getMessage());
}
}
singleton 으로 Driver 객체 하나 생성하고 shutdown hook 하나 등록하고 결국 생성한 Driver 객체를 등록하기 위해 DriverManager.registerDriver() 를 호출한다.
그리고 MySQL 과 Phoenix 모두 jar 파일 내 ServiceLoader 에 Driver 와 PhoenixDriver 를 등록하기 위한 준비를 해 두었다. 편의성 측면에서 훌륭하지만, 운이 나쁘게도 이 상황에서는 문제를 일으키게 된다.
code 와 stack trace 를 끼워맞추어 상황을 종합해 보면,
- 첫 번째 thread 의 Driver (MySQL) class 초기화 진입이 좀 더 빨랐고 DriverManager.registerDriver() 를 먼저 실행했음을 유추할 수 있다.
- DriverManager 의 class 초기화에서 ServiceLoader 를 이용하여 Driver 들을 모두 초기화하기 시작했다.
- 두 번째 thread 가 Phoenix Driver class 초기화 진입이 이루어졌고 DriverManager.registerDriver() 를 실행했다. 하지만 class 초기화가 아직 끝나지 않았기 때문에 (classloader 계층 내에서 class 가 처음 로드 될 때만 초기화가 실행됨) 대기하게 된다.
- 첫 번째 thread 는 결과적으로 Phoenix Driver 를 초기화하려고 시도하게 된다. (ServiceLoader 에 등록되어 있으므로) 하지만 Phoenix Driver 도 class 초기화가 아직 끝나지 않았기 때문에 대기하게 된다.
- 결국 두 thread 는 서로의 class 초기화가 끝나길 기다리게 되어 deadlock 상태에 빠진다.
해결 방안은 사실 간단하다. ‘multi thread 에서 동시 초기화하지 않는다’ 같은 뻔한 걸 제외하면 크게 두 가지가 있다.
- Driver class 를 직접 Class.forName() 등으로 초기화하지 않고 ServiceLoader 에게 맡긴다.
사실 HikariCP 가 초기화를 안하면 DriverManager 가 알아서 초기화해 줄 것이다. HikariCP 가 ServiceLoader 를 지원하지 않는 driver 를 위해 옛날 방법으로 초기화한 것이 최신 방법과 부딛히게 된 것인데, 지원하는 driver 인지 먼저 확인하고 지원한다면 초기화하지 않게 driverClassName 을 비워두면 된다. (나중에 보았는데 비우고 먼저 시도해보라고 가이드도 되어 있다…)
https://github.com/brettwooldridge/HikariCP#essentials
참고로 Phoenix 가 DataSource 구현체를 지원하지 않기도 하고 MySQL 의 DataSource 구현체가 network timeout 지원 관련 이슈가 있는 것으로 나와 있어서 Driver 구현체를 썼는데, DataSource 구현체를 지원하는 드라이버는 DataSource 구현체를 사용하도록 HikariCP 를 초기화하면 된다. HikariCP 도 이쪽을 더 권장한다.
https://github.com/brettwooldridge/HikariCP#popular-datasource-class-names
2. Driver class 초기화 전에 DriverManager class 초기화를 실행한다.
나의 경우 bolt class 의 static block 에 DriverManager.getDrivers() 를 한 번 호출해 주었다. 일반적으로 bolt 객체는 serialization 된 상태로 전달되고 worker 에서 deserialization 되기 때문에 일반적으로 worker 프로세스에서 발생해야 할 초기화들은 prepare() 메소드에 작성하지만, class 초기화는 관계없이 두 곳 모두 발생하므로 static block 에 작성해 주어도 동작한다. 이 workaround 는 근본 원인을 피해가는 것이라서 ‘모든 thread 에서 Driver class 초기화 전에 DriverManager class 초기화를 먼저 수행한다’ 는 조건만 만족시키면 문제를 완전히 피해갈 수 있다.
