[웹로직] IBM AIX WebLogic Starting Slowly hang or STUCK at getLocalHostName

T사에서 웹로직 재기동시 기동하는 속도가 현저히 문제가 되는 경우가 있었다.

OS 리소스(CPU/MEM)를 확인했을 때 사용량이 미비했고, 담당자를 통해 확인한 결과 네트워크의 문제도 아니었고

온전히 웹로직 기동시에 느린 현상으로 확인됐다.

 

기동시 성능 문제의 원인을 파악하기 위해서는 Thread Dump를 떠서 확인하는 방법이 있다.

Thread Dump의 경우 "kill -3 [pid]]"로 생성 가능하다.

 

T사에서 AdminServer 기동 시 대략 20분 넘게 소요가 되었고,

Managed Server의 경우 2시간 이상 소요가 되었다. 뭔가 문제가 이상하다고 판단되어 Thread Dump를 생성했고 해당 내용은 아래와 같다.

 

1. Thread Dump 분석

1XMTHDINFO     All Thread Details NULL           ------------------ NULL 2XMFULLTHDDUMP Full thread dump J9 VM (J2RE 5.0 IBM J9 2.3 AIX ppc-32 build 20071004_14218_bHdSMR, native threads): 3XMTHREADINFO      "main" (TID:0x31F12E00, sys_thread_t:0x30011738, state:R, native ID:0x00069133) prio=5 4XESTACKTRACE          at java/net/Inet6AddressImpl.getLocalHostName(Native Method) 4XESTACKTRACE          at java/net/InetAddress.getLocalHost(InetAddress.java:1461) 4XESTACKTRACE          at weblogic/logging/LogEntryInitializer.getCurrentMachineName(LogEntryInitializer.java:84) 4XESTACKTRACE          at weblogic/logging/LogEntryInitializer.initializeLogEntry(LogEntryInitializer.java:65) 4XESTACKTRACE          at weblogic/logging/WLLogRecord.<init>(WLLogRecord.java:39) 4XESTACKTRACE          at weblogic/logging/MessageLogger.log(MessageLogger.java:64) 4XESTACKTRACE          at weblogic/logging/MessageLogger.log(MessageLogger.java:116) 4XESTACKTRACE          at weblogic/logging/WLMessageLogger.log(WLMessageLogger.java:51) 4XESTACKTRACE          at weblogic/t3/srvr/T3SrvrLogger.logDomainLibPath(T3SrvrLogger.java:3626) 4XESTACKTRACE          at weblogic/Server.appendToClassPath(Server.java:128(Compiled Code)) 4XESTACKTRACE          at weblogic/Server.intializeClassloader(Server.java:140) 4XESTACKTRACE          at weblogic/Server.main(Server.java:66) 3XMTHREADINFO      "JIT Compilation Thread" (TID:0x31F13200, sys_thread_t:0x30011C68, state:CW, native ID:0x00077137) prio=11 3XMTHREADINFO      "Signal Dispatcher" (TID:0x31F13600, sys_thread_t:0x30012198, state:R, native ID:0x000A6047) prio=5 4XESTACKTRACE          at com/ibm/misc/SignalDispatcher.waitForSignal(Native Method) 4XESTACKTRACE          at com/ibm/misc/SignalDispatcher.run(SignalDispatcher.java:84) 3XMTHREADINFO      "Concurrent Mark Helper" (TID:0x33213000, sys_thread_t:0x33167A60, state:CW, native ID:0x000C0141) prio=5 3XMTHREADINFO      "Gc Slave Thread" (TID:0x33213400, sys_thread_t:0x33167CF8, state:CW, native ID:0x000CC061) prio=5 3XMTHREADINFO      "Gc Slave Thread" (TID:0x33213800, sys_thread_t:0x33167F90, state:CW, native ID:0x0011B141) prio=5 3XMTHREADINFO      "Gc Slave Thread" (TID:0x3339E800, sys_thread_t:0x33168228, state:CW, native ID:0x000F90B9) prio=5 XMTHREADINFO      "Gc Slave Thread" (TID:0x333D5700, sys_thread_t:0x333B2F30, state:CW, native ID:0x000611ED) prio=5 3XMTHREADINFO      "Gc Slave Thread" (TID:0x333D5B00, sys_thread_t:0x333B31C8, state:CW, native ID:0x000CB0B5) prio=5 3XMTHREADINFO      "SIGQUIT Thread" (TID:0x333D5F00, sys_thread_t:0x300119D0, state:R, native ID:0x000D3139) prio=11 NULL           ------------------------------------------------------------------------

-> AdminServer 기동시 Thread Dump 생성 결과 Inet6AddressImpl.getLocalHostName 스택에서 멈춰 있는 것을 알 수 있다.

해당 이슈는 IBM에서도 동일하게 보고가 된 것으로 보이는데,

https://www.ibm.com/support/pages/ibm-java-aix-howto-troubleshoot-java-version-hang-or-timeout-issue

이 문제는 IPv6와 IPv4 간의 lookup 이슈로 발생할 수 있다. 문제는 JVM이 IPv6와 IPv4 쿼리를 모두 수행하는 것인데, DNS(Domain Name System) 서버가 IPv6 쿼리를 처리하도록 구성되지 않은 경우 애플리케이션은 IPv6 쿼리가 시간 초가될 때까지 기다려야 한다. 

* 오라클 문서 참조 : AdminServer Starting Slowly On IBM AIX STUCK on java.net.Inet6AddressImpl.getLocalHostName (Doc ID 2608465.1)

 

그렇기 때문에 웹로직 기동시 Java Option에 -Djava.net.preferIPv4Stack=true을 추가하여 Java 애플리케이션이 IPv6 lookup 요청을 비활성화 시키고 IPv4만 사용하도록 하는 것이다.

 

[ 참고내용 ]

Java 는 OS 에서 IPv4 와 IPv6 가 모두 사용 가능할 경우 IPv6 를 우선적으로 사용하게 된다. 그래서 netstat이나 lsof 등으로 사용하는 네트워크 포트 정보등을 볼 경우나 JSP 등에서 request.getRemoteAddr() 호출시 주소가 IPv6로 보이게 된다. 

 

개인적인 사견으로는 아마 네트워크 관리자 쪽에서 네트워크 서비스가 IPv6를 지원하지 않도록 수정한 것이 아닌가 싶다.. 그렇지 않고서야 -Djava.net.preferIPv4Stack=true 옵션은 기존에도 들어가 있지 않던 기동옵션인데 갑자기 느려질리가 없다.

https://docs.oracle.com/cd/E56343_01/html/E53782/ipv6-planning-35.html

 

어찌됐건, 해당 옵션을 추가하여 웹로직 기동 속도가 빨라지긴 했지만 여전히 느리다는 내용을 전달받아 다시 한번 Thread Dump를 확인한 결과 이번에는 다른 부분에서 막혀 있었다.

 

2. 2차 Thread Dump 분석

 

3XMTHREADINFO      "[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" (TID:0x34C85400, sys_thread_t:0x345A68F0, state:R, native ID:0x000CB0B7) prio=5 4XESTACKTRACE          at java/net/Inet4AddressImpl.getLocalHostName(Native Method) 4XESTACKTRACE          at java/net/InetAddress.getLocalHost(InetAddress.java:1461) 4XESTACKTRACE          at weblogic/jdbc/oracle/net8/TTIFUN_OAUTHENTICATE.<init>(Bytecode PC:67) 4XESTACKTRACE          at weblogic/jdbc/oracle/OracleImplConnection.connectAndAuthenticate(Bytecode PC:1930) 4XESTACKTRACE          at weblogic/jdbc/oracle/OracleImplConnection.open(Bytecode PC:363) 4XESTACKTRACE          at weblogic/jdbc/base/BaseConnection.connect(Bytecode PC:197) 4XESTACKTRACE          at weblogic/jdbc/base/BaseConnection.setupImplConnection(Bytecode PC:157) 4XESTACKTRACE          at weblogic/jdbc/base/BaseConnection.open(Bytecode PC:150) 4XESTACKTRACE          at weblogic/jdbcx/base/BaseXADataSource.getBaseConnectionPreparedForXA(Bytecode PC:51) 4XESTACKTRACE          at weblogic/jdbcx/base/BaseXADataSource.getXAConnection(Bytecode PC:43) 4XESTACKTRACE          at weblogic/jdbc/common/internal/XAConnectionEnvFactory.makeConnection(XAConnectionEnvFactory.java:423) 4XESTACKTRACE          at weblogic/jdbc/common/internal/XAConnectionEnvFactory.createResource(XAConnectionEnvFactory.java:140) 4XESTACKTRACE          at weblogic/common/resourcepool/ResourcePoolImpl.makeResources(ResourcePoolImpl.java:1073) 4XESTACKTRACE          at weblogic/common/resourcepool/ResourcePoolImpl.makeResources(ResourcePoolImpl.java:995) 4XESTACKTRACE          at weblogic/common/resourcepool/ResourcePoolImpl.start(ResourcePoolImpl.java:214) 4XESTACKTRACE          at weblogic/jdbc/common/internal/ConnectionPool.doStart(ConnectionPool.java:1042) 4XESTACKTRACE          at weblogic/jdbc/common/internal/ConnectionPool.start(ConnectionPool.java:146) 4XESTACKTRACE          at weblogic/jdbc/common/internal/ConnectionPoolManager.createAndStartPool(ConnectionPoolManager.java:385) 4XESTACKTRACE          at weblogic/jdbc/common/internal/ConnectionPoolManager.createAndStartPool(ConnectionPoolManager.java:326) 4XESTACKTRACE          at weblogic/jdbc/module/JDBCModule.prepare(JDBCModule.java:251) 4XESTACKTRACE          at weblogic/application/internal/flow/ModuleListenerInvoker.prepare(ModuleListenerInvoker.java:93) 4XESTACKTRACE          at weblogic/application/internal/flow/DeploymentCallbackFlow$1.next(DeploymentCallbackFlow.java:360) 4XESTACKTRACE          at weblogic/application/utils/StateMachineDriver.nextState(StateMachineDriver.java:26) 4XESTACKTRACE          at weblogic/application/internal/flow/DeploymentCallbackFlow.prepare(DeploymentCallbackFlow.java:56) 4XESTACKTRACE          at weblogic/application/internal/flow/DeploymentCallbackFlow.prepare(DeploymentCallbackFlow.java:46) 4XESTACKTRACE          at weblogic/application/internal/BaseDeployment$1.next(BaseDeployment.java:615) 4XESTACKTRACE          at weblogic/application/utils/StateMachineDriver.nextState(StateMachineDriver.java:26) 4XESTACKTRACE          at weblogic/application/internal/BaseDeployment$1.next(BaseDeployment.java:615) 4XESTACKTRACE          at weblogic/application/utils/StateMachineDriver.nextState(StateMachineDriver.java:26) 4XESTACKTRACE          at weblogic/application/internal/BaseDeployment.prepare(BaseDeployment.java:191) 4XESTACKTRACE          at weblogic/application/internal/DeploymentStateChecker.prepare(DeploymentStateChecker.java:147) 4XESTACKTRACE          at weblogic/deploy/internal/targetserver/AppContainerInvoker.prepare(AppContainerInvoker.java:61) 4XESTACKTRACE          at weblogic/deploy/internal/targetserver/SystemResourceDeployment.prepare(SystemResourceDeployment.java:65) 4XESTACKTRACE          at weblogic/management/deploy/internal/DeploymentAdapter$1.doPrepare(DeploymentAdapter.java:39) 4XESTACKTRACE          at weblogic/management/deploy/internal/DeploymentAdapter.prepare(DeploymentAdapter.java:187) 4XESTACKTRACE          at weblogic/management/deploy/internal/AppTransition$1.transitionApp(AppTransition.java:21) 4XESTACKTRACE          at weblogic/management/deploy/internal/ConfiguredDeployments.transitionApps(ConfiguredDeployments.java:233) 4XESTACKTRACE          at weblogic/management/deploy/internal/ConfiguredDeployments.prepare(ConfiguredDeployments.java:165) 4XESTACKTRACE          at weblogic/management/deploy/internal/ConfiguredDeployments.deploy(ConfiguredDeployments.java:122) 4XESTACKTRACE          at weblogic/management/deploy/internal/DeploymentServerService.resume(DeploymentServerService.java:173) 4XESTACKTRACE          at weblogic/management/deploy/internal/DeploymentServerService.start(DeploymentServerService.java:89) 4XESTACKTRACE          at weblogic/t3/srvr/SubsystemRequest.run(SubsystemRequest.java:64) 4XESTACKTRACE          at weblogic/work/ExecuteThread.execute(ExecuteThread.java:200) 4XESTACKTRACE          at weblogic/work/ExecuteThread.run(ExecuteThread.java:172)

-> Thread Dump Stack을 봤을 때, 확실히 이번에는 Inet4Address로 변경된 것을 확인할 수 있었다.

해당 스택으로 오라클 문서 확인결과,

Slow Performance or Process Hang in HostName Lookup (Doc ID 1383210.1)

 

IP주소는 기본적으로 캐시되지 않고, 조회가 매번 수행되기 때문에 지연 및 성능 저하가 발생할 수 있다. 런타임 코드는 여러 위치에서 InetAddress.getLocalHost() 메소드를 호출한 다음 DNS lookup 요청을 발생시킨다. 그렇기 때문에 해당 이슈는 아래와 같은 옵션으로 workaround를 제안할 수 있다.

 

1. Implement the following parameter that would cache the localhost/hostname information:
   
   For IBM JDK: -Dcom.ibm.cacheLocalHost=true
   NOTE: This property is not available on HP-UX and Solaris platforms. Java APAR PK19242 (shipped with Java SDK 1.4.2 service refresh SR 5) is required for this property to work.For Sun JDK and JRockit JDK, set the Java property "networkaddress.cache.ttl" in the %JRE%/lib/security/java.security file. networkaddress.cache.ttl is specified in java.security to indicate the caching policy for successful name lookup's from the name service. The value is specified as an integer to indicate the number of seconds to cache the successful lookup. A value of -1 indicates "cache forever."
   
   For HP JDK:
   -Dsun.net.inetaddr.ttl=-1
   -Dnetworkingaddresscache=-1                                                                                                  NOTE: We need to add these parameter(based on the recommendations and depending on the platforms that we are using as there are different parameters for different JDKs) in the server start-up parameters and ONLY in the environment where the DNS names are not changed frequently. The default values, i.e., -1 or 'forever,' make servers brittle to DNS updates. This helps in redcing the overhead of doing a lookup each time, but these settings need to be done on a per use-case basis and are NOT generic/recommended settings.

 

결론적으로 AdminServer와 Managed Server에 하기 두 개의 Java Option을 추가하고 기동한 뒤에야 기동 속도가 정상적으로 돌아왔다. 

-Djava.net.preferIPv4Stack=true

-Dcom.ibm.cacheLocalHost=true

 

물론 기존에도 해당 옵션없이도 기동 성능에 대한 이슈가 없었지만, 아무리 생각해도 네트워크 쪽에서 DNS 관련 설정을 건드린게 아닌가 싶다..

 

우선 위와 같은 동일한 문제 발생 시에 2개의 Java Option으로 대응이 가능하겠지만, 네트워크 쪽에서 수정한 사항이 있는지 같이 확인하는 것이 맞는 것 같다..