CurrentThreadBusy 발생시 ZipFile.open() 에 Thread 가 Block 되어있는 이유
운영중인 서버에서 CurrentThreadBusy 메트릭이 튀기 시작하였다. 특징은 순간적으로 Spike 를 쳤다가 다시 정상 범위로 돌아가고 간헐적으로 여러 서버에서 튄다는 것이다.
tomcat thread 들이 어느 stack trace 에서 busy 상태로 남아있는지 확인하기 위하여 0.5초 마다 currentThreadbusy 값을 확인하면서 임계치를 초과한경우 thread dump 를 생성하도록 스크립트를 작성하여 배포하였다.
#!/bin/bash
CRITICAL_VALUE=20
while [true]
do
sleep 0.5
CURRENT_THREAD_BUSY=`curl -s http://127.0.0.1:9403 | grep'catalina_threadpool_currentthreadbusy' | aws '{print $2}' `
if [ $CURRENT_THRAD_BUSY -ge $CRITICAL_VALUE]
then
jstack 1 > threaddump-{timestamp}.log
sleep 120
done
임계치가 초과되어 생성된 Thread Dump 를 보면 대부분의 tomcat 쓰레드는 동일한 lock 을 기다리고 있는 것을 볼 수 있다.
"http-nio-10001-exec-68" #2611 daemon prio=5 os_prio=0 tid=0x00007f3cbc005000 nid=0x68325 waiting for monitor entry [0x00007f3bc8c96000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1868)
- waiting to lock <0x0000000664400e30> (a java.util.concurrent.ConcurrentHashMap$Node)"http-nio-10001-exec-65" #2608 daemon prio=5 os_prio=0 tid=0x00007f3cbc004800 nid=0x68322 waiting for monitor entry [0x00007f3bc9c11000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1868)
- waiting to lock <0x0000000664400e30> (a java.util.concurrent.ConcurrentHashMap$Node)"http-nio-10001-exec-64" #156 daemon prio=5 os_prio=0 tid=0x00007f3f98d9b800 nid=0x3a1 waiting for monitor entry [0x00007f3ccbffd000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1868)
- waiting to lock <0x0000000664400e30> (a java.util.concurrent.ConcurrentHashMap$Node)락을 기다리는 tomcat thread 들
해당 Lock 을 잡고 있는 쓰레드는 아래와 같이 ZipFile.open() 에서 RUNNABLE 상태로 남아있었다.
"http-nio-10001-exec-69" #2612 daemon prio=5 os_prio=0 tid=0x00007f3cc400a800 nid=0x68326 runnable [0x00007f3b62ffc000]
java.lang.Thread.State: RUNNABLE
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.<init>(ZipFile.java:225)
at java.util.zip.ZipFile.<init>(ZipFile.java:155)
at java.util.jar.JarFile.<init>(JarFile.java:166)
at java.util.jar.JarFile.<init>(JarFile.java:130)
at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:202)
at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:187)
at org.apache.catalina.webresources.AbstractArchiveResourceSet.openJarFile(AbstractArchiveResourceSet.java:308)
- locked <0x000000064b623a30> (a java.lang.Object)
at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:96)
at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:257)
at org.apache.catalina.webresources.StandardRoot.getResourcesInternal(StandardRoot.java:326)
at org.apache.catalina.webresources.CachedResource.validateResources(CachedResource.java:158)
- locked <0x00000007a04f9088> (a org.apache.catalina.webresources.CachedResource)
at org.apache.catalina.webresources.Cache.getResources(Cache.java:165)
at org.apache.catalina.webresources.StandardRoot.getResources(StandardRoot.java:314)
at org.apache.catalina.webresources.StandardRoot.getClassLoaderResources(StandardRoot.java:230)
at org.apache.catalina.loader.WebappClassLoaderBase.findResources(WebappClassLoaderBase.java:1012)
at org.apache.catalina.loader.WebappClassLoaderBase.getResources(WebappClassLoaderBase.java:1113)
at java.util.ServiceLoader$LazyIterator.hasNextService(ServiceLoader.java:348)
at java.util.ServiceLoader$LazyIterator.hasNext(ServiceLoader.java:393)
at java.util.ServiceLoader$1.hasNext(ServiceLoader.java:474)
at io.jsonwebtoken.impl.lang.Services.loadFirst(Services.java:110)
at io.jsonwebtoken.impl.lang.Services.loadFirst(Services.java:100)
at io.jsonwebtoken.impl.DefaultJwtParserBuilder.build(DefaultJwtParserBuilder.java:191)최초에 생성된 쓰레드 덤프
1초 뒤에 떠진 Thread Dump 에도 해당 쓰레드가 같은 lock 을 잡고 여전히 RUNNABLE 상태로 남아있었기 때문에 CurrentThreadBusy 의 원인은 해당 Thread 에 의한 것임을 알 수 있다.
"http-nio-10001-exec-69" #2612 daemon prio=5 os_prio=0 tid=0x00007f3cc400a800 nid=0x68326 runnable [0x00007f3b62ffc000]
java.lang.Thread.State: RUNNABLE
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.<init>(ZipFile.java:225)
at java.util.zip.ZipFile.<init>(ZipFile.java:155)
at java.util.jar.JarFile.<init>(JarFile.java:166)
at java.util.jar.JarFile.<init>(JarFile.java:130)
at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:202)
at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:187)
at org.apache.catalina.webresources.AbstractArchiveResourceSet.openJarFile(AbstractArchiveResourceSet.java:308)
- locked <0x000000064b7c7ea8> (a java.lang.Object)
at org.apache.catalina.webresources.AbstractSingleArchiveResourceSet.getArchiveEntry(AbstractSingleArchiveResourceSet.java:96)
at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:257)
at org.apache.catalina.webresources.StandardRoot.getResourcesInternal(StandardRoot.java:326)
at org.apache.catalina.webresources.CachedResource.validateResources(CachedResource.java:158)
- locked <0x00000007a04f9088> (a org.apache.catalina.webresources.CachedResource)
at org.apache.catalina.webresources.Cache.getResources(Cache.java:165)
at org.apache.catalina.webresources.StandardRoot.getResources(StandardRoot.java:314)
at org.apache.catalina.webresources.StandardRoot.getClassLoaderResources(StandardRoot.java:230)
at org.apache.catalina.loader.WebappClassLoaderBase.findResources(WebappClassLoaderBase.java:1012)
at org.apache.catalina.loader.WebappClassLoaderBase.getResources(WebappClassLoaderBase.java:1113)
at java.util.ServiceLoader$LazyIterator.hasNextService(ServiceLoader.java:348)
at java.util.ServiceLoader$LazyIterator.hasNext(ServiceLoader.java:393)
at java.util.ServiceLoader$1.hasNext(ServiceLoader.java:474)
at io.jsonwebtoken.impl.lang.Services.loadFirst(Services.java:110)
at io.jsonwebtoken.impl.lang.Services.loadFirst(Services.java:100)1초뒤에 생성된 쓰레드 덤프
문제의 69번 톰켓 쓰레드의 코드 Services.loadFirst() 함수 호출부분을 보면 Class 를 파라미터로 넘기면서 객체가 생성되는 것을 알 수 있다. 한가지 의문스러운 부분은 클래스 정보로 객체를 생성할때는 이미 Metaspace 에 로드된 클래스 정보로 객체를 생성할텐데 어떤 이유로 Disk 에 있는 jar 파일에 접근하는지가 궁금해졌다.
this.deserializer = (Deserializer)Services.loadFirst(Deserializer.class);jjwt-impl jar 의 deserializer 객체 생성 코드
jjwt-impl jar 내부의 코드에서 jdk 의 ServiceLoader 클래스를 사용하고 있기 때문에 ServiceLoader 가 무엇인지 이해가 필요하다.
ServiceLoader 란
잘 알려진 interface 를 각 Serivce Provider 가 구현을 하여 jar 안에 포함시키고, jar 의 특정 경로 (META-INF/services) 하위에 Service Provider 가 구현한 interface 와 구현체의 정보를 저장해 놓고 interface 를 객체로 생성하여 사용할 수 있도록 제공하는 것이다.
간단하게 설명하면, 아래와 같다.
- Service Provider 가 interface 를 구현한 클래스를 생성한다
- Service Provider 가 jar 를 생성할때 /META-INF/services 하위에 구현한 interface 를 파일명으로하고 파일 컨텐츠로 구현 클래스의 경로를 작성한다
- Service 사용자는 해당 jar 와 함께 application 를 실행하고 ServiceLoader.load() 를 호출하여 객체를 생성한다
Thread Dump 에서 호출된 클래스로 예를 들면 아래와 같다.
package io.jsonwebtoken.io;
public interface Deserializer<T> {
T deserialize(byte[] var1) throws DeserializationException;
}Service 로 제공할 interface
io.jsonwebtoken.jackson.io.JacksonDeserializer
jjwt-jackson jar 에서 Deserializer interface 의 구현체가 있다는 것을 알리기 위한 파일과 해당 파일에 구현체의 Class 정보가 담겨있는 것을 볼 수 있다
그렇다면 tomcat 에서 이 코드를 실행시켰을때 어쩌다가 ZipFile 이 호출되어 I/O 까지 발생하는지 확인해보자
우선 로컬에서 아래와 같은 샘플 코드로 동일한 함수를 호출해본다
import io.jsonwebtoken.io.Deserializer;
import java.util.ServiceLoader;
public class ReflectionMain {
public static void main(String[] args) {
ServiceLoader<Deserializer> serviceLoader = ServiceLoader.load(Deserializer.class);
Deserializer createdByServiceLoader = serviceLoader.iterator().hasNext() ? serviceLoader.iterator().next() : null;
System.out.println(createdByServiceLoader);
}
}예제 코드
ServiceLoader.load() 내부 구현을 보면 ClassLoader 를 파라미터로 전달하지 않으면 현재 쓰레드의 ClassLoader 가 사용되는것을 볼 수 있다. 이 예제 코드에서는 ClassLoader 를 따로 구현하지 않았기 때문에 AppClassLoader 가 사용되었을 것이다.
public static <S> ServiceLoader<S> load(Class<S> service) {
ClassLoader cl = Thread.currentThread().getContextClassLoader();
return ServiceLoader.load(service, cl);
}
serviceLoader.iterator().hasNext() 함수가 호출되면 ServiceLoader 의 innerclass 인 LazyIterator 함수의 hasNextService() 함수가 호출된다. 이 부분은 Thread Dump 의 stack trace 와 동일하다.
private boolean hasNextService() {
if (nextName != null) {
return true;
}
if (configs == null) {
try {
String fullName = PREFIX + service.getName();
if (loader == null)
configs = ClassLoader.getSystemResources(fullName);
else
configs = loader.getResources(fullName);
} catch (IOException x) {
fail(service, "Error locating configuration files", x);
}
}
while ((pending == null) || !pending.hasNext()) {
if (!configs.hasMoreElements()) {
return false;
}
pending = parse(service, configs.nextElement());
}
nextName = pending.next();
return true;
}ServiceLoader.LazyIterator.hasNextService()
Thread Dump 와 마찬가지로 예제 코드에서도 Line.5 에 configs == null 조건이 참이고 loader != null 조건이 참이기 때문에 loader.getResources() 가 호출되게 된다. 이때 fullName 에는 service 구현 여부를 알 수 있는 경로가 설정된다.
- PREFIX = "META-INF/services/"
- service.getName() = "io.jsonwebtoken.io.Deserializer"
이 경로는 Service Loader 에서 설명했던 jar 파일에 해당 interface 를 구현했는지 여부를 알 수 있는 경로와 일치하는 것을 알 수 있다.
이렇게해서 만들어진 경로는 URLClassLoader 로 전달되게 되고 URLClassLoader 는 현재 Load 되어있는 jar 들 중에 해당 경로에 파일이 있는지 하나씩 확인을 하게 된다.
<URLClassPath.getResource() 캡쳐>
이때 ZipFile 클래스가 호출되는데, ZipFile 클래스의 zipEntry 에는 해당 ZipFile 의 모든 file 의 경로가 저장되어있다. 따라서 아래와 같이 getJarEntry(path) 를 호출했을때 결과 값이 있다면 해당 zip 내부의 경로에 해당 파일이 존재하는지 알 수 있다.
JarEntry var3 = this.jar.getJarEntry(var1);URLClassPath.getResource() 함수에서 찾고자하는 Service 의 구현체가 있는지 확인하는 부분
이렇게 각 Jar 에 사용하고자 하는 Service 의 구현체가 있는지를 확인하기 위해 ZipFile 클래스가 사용되는걸 확인할 수 있다.
확인된 구현체가 있다면 ServiceLoader.nextService() 에서 Class.forName() 으로 META-INF/services 하위에 있는 파일에 쓰여진 구현체 클래스명이 전달되고 c = Class.forName(cn, false, loader); 를 통해 클래스를 만든 후에 c.newInstance() 를 호출하여 최종적으로 객체를 생성하는것을 확인할 수 있다.
즉, ServcieLoader 가 jar 에 접근하는 이유는 해당 jar 파일의 *.class 를 읽어오기 위함이 아닌 /META-INF/services 하위에 찾고자 하는 Service Interface 구현체가 있는지 알기 위함이다.
그렇다면 Tomcat 에서도 동일하게 동작하는지 확인해보자.
tomcat 은 URLClassLoader 가 사용되지 않고 tomcat 이 구현한 WebappClassLoaderBase 가 사용된 것을 볼 수 있다.
ThreadDump 의 stack trace 를 따라가다보면 Cache 클래스의 getResources() 함수가 호출되는 것을 볼 수 있다.
protected WebResource[] getResources(String path, boolean useClassLoaderResources) {
lookupCount.incrementAndGet();
// Don't call noCache(path) since the class loader only caches
// individual resources. Therefore, always cache collections here
CachedResource cacheEntry = resourceCache.get(path);
if (cacheEntry != null && !cacheEntry.validateResources(useClassLoaderResources)) {
removeCacheEntry(path);
cacheEntry = null;
}Tomcat 의 Cache 클래스
Cache.resourceCache 는 key 를 resourcePath 로 하고 value 를 CachedResource 를 가지며 해당 클래스 내부에 WebResources 에 JarResource 로 실제 jar 에 대한 정보를 가지고 있다.
Deserializer 를 예를 들면, "/META-INF/servies/io.josnwebtoken.io.Deseralizer" 를 key 로 하고 value 로 저장되어있는 CachedResource 의 WebResources 에 Deserailzer 를 구현한 jar 의 경로가 저장되어있다. 즉, jar 내부에 "/META-INF/servies/io.josnwebtoken.io.Deseralizer" 경로에 파일을 가지고 있는 jar 들 리스트이다.
이때 전달된 path 는 Service 구현체 정보가 작성되어있는 파일 경로이다 ( /META-INF/services/io.jsonwebtoken.io.Deseraizlier ) 따라서, 해당 Cache 는 이 interface(Deserializer)의 구현체를 가지고 있는 jar 들의 정보일 것이다. thread dump 상으로는 cacheEntry 값이 존재하여 cacheEntry.validateResources() 가 호출되었다. 함수 이름은 validate 이지만 webResources 가 존재하지 않을 경우에 Resource 를 읽어와서 채우는걸 볼 수 있다.
backgourdProcess() 에 의해서 CachedResource 가 clear 되거나 ttl 이 초과하여 CachedResource 가 만료된 경우에는 CachedResource 자체가 없어서 validateResources() 함수가 호출될 수 없다. 따라서 아래 코드로 들어오는 경우는 CachedResource 가 없어서 새로 생성한 후에 validateResources() 를 호출한 경우이다.
if (webResources == null) {
synchronized (this) {
if (webResources == null) {
webResources = root.getResourcesInternal(
webAppPath, useClassLoaderResources);
nextCheck = ttl + now;
return true;
}
}
}CachedResources.validateResources()
해당 함수내부에서는 webResources 가 비어있을때 root.getResourcesInternal() 을 호출하여 webResources 에 값을 할당하는 것을 볼 수 있다.
root.getResourcesInternal() 에서는 로드되어있는 webResources 들을 모두 순회하면서 전달된 경로의 파일이 존재하는 WebResource 를 찾는다. allResources 에는 해당 tomcat 에서 사용된 jar ( /webapps/WEB-INF/lib )들이 모두 들어있다.
protected WebResource[] getResourcesInternal(String path,
boolean useClassLoaderResources) {
List<WebResource> result = new ArrayList<>();
for (List<WebResourceSet> list : allResources) {
for (WebResourceSet webResourceSet : list) {
if (useClassLoaderResources || !webResourceSet.getClassLoaderOnly()) {
WebResource webResource = webResourceSet.getResource(path);
if (webResource.exists()) {
result.add(webResource);
}
}
}
}
if (result.size() == 0) {
result.add(main.getResource(path));
}
return result.toArray(new WebResource[0]);
}
webResourceSet.getResource() 가 호출되면 AbstractArchiveResourceSet.getResource() 가 호출되고 해당 함수 내에 getArchiveEntry() 가 호출되면 아래와 같이 openJarFile() 을 호출하고 jarFile.getJarEntry() 를 호출하여 해당 jar 의 Service 를 구현한 구현체가 있는지 확인을 하게 되는 것이다.
protected JarEntry getArchiveEntry(String pathInArchive) {
JarFile jarFile = null;
try {
jarFile = openJarFile();
return jarFile.getJarEntry(pathInArchive);
} catch (IOException ioe) {
// Should never happen
throw new IllegalStateException(ioe);
} finally {
if (jarFile != null) {
closeJarFile();
}
}
}AbstratSingleArchiveResourceSet.getArchiveEntry()
여기까지 tomcat 에서 JarFile.open() 이 호출되게 된 이유를 알아보았다. 그렇다면 정상적으로 동작중인 서버에서 갑자기 CurrentThreadBusy 가 높아지고 왜 하나의 쓰레드가 ZipFile.open() 에서 1초 이상 RUNNABLE 상태로 남아있었는지를 알아내야한다.
의혹1) CachedResource 에 이미 Deserializer 인터페이스에 대한 정보가 있어야 하는데 없어서 I/O 가 발생한 것이 문제?
해당 서버는 이미 배포된 후 이미 오랜시간동안 요청을 받고 있었으며, ServiceLoader.load() 하는 코드는 spring interceptor 에서 호출하기 때문에 모든 요청이 거쳐가는 부분이다. 따라서 이전에 무조건 Deseralizer 로 ServiceLoader.load() 가 되었을 것이다. 하지만 Thread Dump 에 따르면 CachedResource 의 webResources 가 null 이여서 다시 불러오게 된 것을 볼 수 있다.
Cache.backgroundProcess() 함수에서는 각 CachedResource 별로 주어진 ttl 보다 더 오랜 시간 살아있었던 CachedResource 에 대해서 clear() 하는 부분을 확인할 수 있다.
protected void backgroundProcess() {
// Create an ordered set of all cached resources with the least recently
// used first. This is a background process so we can afford to take the
// time to order the elements first
TreeSet<CachedResource> orderedResources =
new TreeSet<>(new EvictionOrder());
orderedResources.addAll(resourceCache.values());
Iterator<CachedResource> iter = orderedResources.iterator();
long targetSize =
maxSize * (100 - TARGET_FREE_PERCENT_BACKGROUND) / 100;
long newSize = evict(targetSize, iter);
if (newSize > targetSize) {
log.info(sm.getString("cache.backgroundEvictFail",
Long.valueOf(TARGET_FREE_PERCENT_BACKGROUND),
root.getContext().getName(),
Long.valueOf(newSize / 1024)));
}
} private long evict(long targetSize, Iterator<CachedResource> iter) {
long now = System.currentTimeMillis();
long newSize = size.get();
while (newSize > targetSize && iter.hasNext()) {
CachedResource resource = iter.next();
// Don't expire anything that has been checked within the TTL
if (resource.getNextCheck() > now) {
continue;
}
// Remove the entry from the cache
removeCacheEntry(resource.getWebappPath());
newSize = size.get();
}
return newSize;
}
때문에, 이미 생성된 CachedResource 라고 하더라도 캐시가 해제될 수 있는 상황이다. Cache 의 설정에 따라서 jar 를 읽는 빈도가 늘어날 수는 있을것으로 보이나 기존에도 자주 만료시키고 있었을것으로 보여 가능성이 낮아 보임
의혹2) Jar 파일을 읽는 것은 주기적으로 발생할 수 있으나 ZipFile.open() 이 느려져서 문제 발생?
ZipFile.open() 은 네이티브 메서드이고 jdk8 코드를 보면 반환값은 FD 이고 내부적으로 FD 를 캐시로 갖는 코드를 확인할 수 있다.
zip = ZIP_Get_From_Cache(path, &msg, lastModified);
캐시도 있고 단순히 FD 를 가져오는 것인데 오래걸릴 가능성이 있는지 의문이여서 ZipFile 내부에서 open() 이 호출될때마다 남겨주는 PerfCounter 의 메트릭을 수집하여 확인해보기로 하였다
jzfile = open(name, mode, file.lastModified(), usemmap);
sun.misc.PerfCounter.getZipFileOpenTime().addElapsedTimeFrom(t0);
sun.misc.PerfCounter.getZipFileCount().increment();
매트릭을 확인해보니 499 발생 시점과 ZipFile open time 가 튀는 시점이 정확하게 일치하는 것을 확인할 수 있다.
이때 open count 는 늘지 않았기 때문에 ZipFile.open() 자체가 느려진 것이 원인이라는것을 알 수 있다.
이 서버는 쿠버네티스 환경에서 배포가 되고 있고 같은 Node 에 다른 pod 이 배포될때마다 ZipFile.open() 이 튀는걸 여러번 재현을 통해서 확인할 수 있었다. 하지만, Node 의 매트릭이나 Docker container 의 매트릭상 특이점을 찾지 못하였다.
ZipFile.open() 이 튀었을때 iostat 을 남겨 Disk I/O 의 상태를 모니터링 하기 시작하였지만 대부분의 결과에서 특이점을 찾지 못하였다. ( ioutil% 가 60% 이상으로 튀는 지표가 딱 한번 잡혔다)
의혹3) 같은 Node 에 배포된 다른 서버들에서는 발생안하고 이 서버에서만 발생하는 이유는?
서버가 배포되는 Node 의 문제라면 같은 Node 에 배포된 다른 서버들에서도 같은 현상이 발생해야한다. 하지만 다른 서버들은 문제없이 동작하고 있었고 그 차이점을 확인해보기로 하였다.
문제가 있는 서버와 없는 서버의 차이는 spring boot 를 사용했느냐 아니냐가 가장 크며 이로 인해서 오는 차이점은 embeded tomcat 을 사용햐였느냐 extrernal tomcat 을 사용하였느냐이다.
spring-boot 2.2.4.RELEASE 기준으로 사용되는 embeded tomcat 의 ClassLoader 는 TomcatEmbeddedWebappClassLoader 이다.
public URL findResource(String name) {
return null;
}
public Enumeration<URL> findResources(String name) throws IOException {
return Collections.emptyEnumeration();
}
External Tomcat 을 사용하는 버전의 Disk I/O 가 발생하는 함수를 Embedded Tomcat 버전에서 보면 아무처리도 하지 않고 응답값을 반환하는것을 확인할 수 있다.
이렇게 처리가 가능한 이유는, AppClassLoader 에서 jar 에 대한 정보를 이미 가지고 있기 때문이다. External Tomcat 이 jar 를 찾기 위해 ClassLoader 를 확인하는 순서는 아래와 같다.
- Boostrap
- ExternalClassLoader
- AppClassLoader
- WebappClassLoaderBase(URLClassLoader)
이떄 AppClassLoader 에는 $TOMCAT_HOME/lib 하위에 있는 jar 들만 포함되어있다. 때문에 URLClassLoader 를 통해서 jar 를 탐색해야하는 것이다. 하지만 embedded tomcat 을 사용할때는 AppClassLoader 에 이미 찾고자 하는 모든 jar 가 포함되어있기 때문에 WebAppClassLoaderBase 에서 Disk I/O 없이 jar 탐색이 가능한것이다.
이 차이로 인해 같은 Node 에 배포된 서버라고 하더라도 Embedded Tomcat 을 사용하는 서버들에서는 문제가 없었던 것이다.
조치
더 이상 Disk I/O 성능 저하의 원인을 찾기 힘들것으로 보여 증상을 완화할 수 있는 방법도 찾기 시작하였다.
Catalina 의 WebappClassLoaderBase 는 resources 를 찾을때 Cache 에서 먼저 검색을 한다. 이 Cache 는 TTL 과 size 를 기반으로 evict 된다. 해당 서버는 매번 새로운 리소스를 읽어오는 경우가 없기 때문에 TTL 을 매우 큰 값으로 설정하여 backgroudProcess 와 getResources() 시에 invalid 로 판단되지 않도록 조치하였다.
이렇게 조치한 결과 ZipFile.open() 의 수는 기존대비 1/10 수준으로 감소하였고 ZipFile.open() 이 튀는 현상 또한 사라졌다.
근본 원인은 여전히 Disk I/O 성능의 저하로 생가되지만 이렇게 조치함으로서 발생하는 문제는 해결할 수 있었다.