OOM 에러 해결 (GCLocker?)

1. 개요

백오피스 서비스에서 간헐적으로 OOM 에러가 발생한다. 

 

백오피스 기능 중 방대한 크기의 금융 데이터를 Excel 형식으로 파싱하는 기능이 존재했고, Pagination 을 거치치 않은 데이터를 통한 무분별한 객체 생성으로 Heap Memory 부족 현상이 발생한다고 판단했다.

 

의아했던 점은 있다. Excel 로 변경하기 위해 생성된 객체는 짧은 Life Cycle 을 가지고 있기에 Garbage Collection 에 의해 지속적으로 메모리 수거가 될 것이라는 점이다.

모종의 이유로 GC 가 동작하지 못하는 걸까?

 

원인을 분석하고 문제를 해결한 과정을 정리하려 한다.

 

 

2. 원인

2025-09-17 10:12:04.231 ERROR 2080223 --- [-8650-exec-3971] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: Java heap space] with root cause

[589601.531s][warning][gc,alloc] http-nio-8650-exec-3971: Retried waiting for GCLocker too often allocating 150994946 words

java.lang.OutOfMemoryError: Java heap space
at java.base/java.util.Arrays.copyOf(Arrays.java:3537)
at java.base/java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:228)
at java.base/java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:582)
at java.base/java.lang.StringBuffer.append(StringBuffer.java:313)
at net.sf.log4jdbc.sql.resultsetcollector.ResultSetCollectorPrinter.getResultSetToPrint(ResultSetCollectorPrinter.java:118)
at net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator.resultSetCollected(Slf4jSpyLogDelegator.java:609)
at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.reportAllReturns(ResultSetSpy.java:104)
at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.reportReturn(ResultSetSpy.java:192)
at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.next(ResultSetSpy.java:1984)

- nohup.log

 

로그를 살펴보니, 내가 예상한 Exception Stack 과 다른 양상을 보였다.

OOM 에러는 비즈니스 로직이 아닌 로깅에서 발생했기 때문이다.

조금 더 자세히 씹고 뜯어보자.

 

2-1. GCLocker?

Retried waiting for GCLocker too often allocating 150994946 words

nohup.log 를 통해 JVM 내부 오류 로그를 살펴봤을 때, 위와 같은 로그가 남겨져 있는 것을 확인할 수 있었다. 로그에는 다소 생소한 `GCLocker` 라는 용어가 포함되어 있었다.

GCLocker 란 무엇일까?

 

Java HotSpot VM Command-Line Options (JDK 17)

• “A JNI critical region is created when native code uses the JNI functions GetPrimitiveArrayCritical or GetStringCritical … during that time, the HotSpot VM cannot bring the VM to a state that allows garbage collection to occur.” Oracle Docs
• 문서: Java HotSpot VM 명령행 옵션 / 트러블슈팅 문서 Oracle Docs

Java Native Interface Specification (JDK 17)

• JNI의 함수 설명 섹션 중 GetPrimitiveArrayCritical, GetStringCritical 및 관련 함수 Oracle Docs+1

 

Oracle JDK  17 공식문서에 GCLocker 라는 용어가 명시되진 않지만, 유추할 수 있는 내용이 존재한다.

정리하자면 다음과 같다.

 

GCLocker 는 JVM 내부 메커니즘 중 하나로 JNI(Java Native Interface) 가 작업을 수행하는 동안 critical section 에 진입하여 Garbage Collection 이 동작하지 않도록 한다.

 

즉, 어느 로직에서 JNI 코드가 수행되었고, GCLocker 메커니즘에 의해 GC가 멈췄다. GC가 멈춰있는 동안 150994946 words(약 1.13 GiB) 의 Memory Allocationg 이 빈번하게 요청되었다. 

 

 

2-2. 주된 원인

- 1. Arrays.copyOf
- 2. AbstractStringBuilder.append
- 3. StringBuffer.append

OOM 발생의 주된 원인은 위의 코드들이다.

slf4j 의 ResultSetSpy 에서 방대한 resultset을 String 으로 변환을 시도했다. StringBuffer 내부의 byte[] 배열을 빈번하게 재할당(Arrays.copyof) 하였고, GCLocker 메커니즘이 동작함과 Heap 부족 현상이 충돌하여 OOM이 발생한 것이다.

 

StringBuilder.append 는 내부적으로 ensureCapacityInternal 함수를 호출한다.

// 2. AbstractStringBuilder.append
public AbstractStringBuilder append(String str) {
     ...
    ensureCapacityInternal(count + len); // 2-1. 호출!
     ...
}

// 2-1.
private void ensureCapacityInternal(int minimumCapacity) {
    ...
    if (minimumCapacity - oldCapacity > 0) {
        value = Arrays.copyOf(value,       // 1. Arrays.copyOf 호출!
                newCapacity(minimumCapacity) << coder);
		}
}

ensureCapacityInternal 함수가 Arrays.copyOf 를 호출하고 배열을 복사하는 단계에서 Heap Memory 를 모두 소모하여 OOM(Out Of Memory) 이 발생했다.

 

 

 

3. 해결

3-1. 해결방안

1️⃣ 근본적인 원인 제거

• Result Set 데이터는 로그를 남기지 말자!

2️⃣ 조금 유하게 원인 제거

• 조회 결과 excel 다운의 경우 페이지이 수행되지 않기에 Result Set의 크기가 커진다. excel 다운 시에만 Result Set 데이터 로그를 남기지 말자!

3️⃣ 더 유하게 원인 제거 ✔

• Result Set의 로그는 남기되 임계 row 를 넘어간다면 … truncated 으로 표현하기

 

3-2. 해결 방법

ResultSet Log 는 남기되, MAX_ROWS 값을 넘기게 되면 더이상의 resultSet Log 문자열을 생성하지 않고 … Truncated 를 출력하는 방식으로 해결하려 한다.

간단하게 logback.xml 파일 프로퍼티의 옵션을 통해 Result Set 의 출력 길이를 지정할 수는 있지만, 해당 방법은 모든 Result Set 을 문자열로 변환하는 작업을 거친 후 절사하는 방법이기에 OOM의 근본적인 발생 원인을 해결할 수는 없다.

Error 의 Stack Trace 를 따라가다 보니 아래와 같은 로그를 발견할 수 있었다.

at java.base/java.lang.StringBuffer.append(StringBuffer.java:313)
at net.sf.log4jdbc.sql.resultsetcollector.ResultSetCollectorPrinter.getResultSetToPrint(ResultSetCollectorPrinter.java:118)
at net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator.resultSetCollected(Slf4jSpyLogDelegator.java:609)
at net.sf.log4jdbc.sql.jdbcapi.ResultSetSpy.reportAllReturns(ResultSetSpy.java:104)

1. Slf4jSpyLogDelegator.resultSetCollected
2. ResultSetCollecterPrinter.getResultSetToPrint

public class Slf4jSpyLogDelegator implements SpyLogDelegator { ... }

SpyLogDelegator 는 Jdbc 객체의 Proxy(Spy) 를 파라매터로 받아 Logger에게 로그 문자열을 전달하는 역할이다. 로그에 자주보이는 resultset, sqltiming 등의 Logger 를 인스턴스 변수로 가진다.

그중 Result Set 을 String 으로 변환하는 로직은 아래 코드에서 수행된다.

// 1. Slf4jSpyLogDelegator.resultSetCollected
public void resultSetCollected(ResultSetCollector resultSetCollector) {
		String table = new ResultSetCollectorPrinter().getResultSetToPrint(resultSetCollector);
}

public class ResultSetCollectorPrinter {

		private final StringBuffer table = new StringBuffer();
		
		// 2.ResultSetCollecterPrinter.getResultSetToPrint
		public String getResultSetToPrint(ResultSetCollector resultSetCollector) {
			 // ... 
		}
}

 

이제 해당 코드를 가로채어 메모리 사용량을 줄여보자.

 

기존에 사용하던 Slf4jSpyLogDelegator에서 result set 로그 생성 로직만 가로채 절사 로직을 추가한다. 그 외의 기능은 기존 Delegator 에게 위임한다.

인터페이스 + 조합 (Composition) 으로 데코레이터(Decorator) + 위임(Delegate) 패턴 적용

public class TruncateTableSpyLogDelegator implements SpyLogDelegator {

   private static final int RESULTSET_TABLE_DEFAULT_MAX_ROWS = 200;

   private final Logger resultSetTableLogger;
   private final Slf4jSpyLogDelegator logDelegator;

   public TruncateTableSpyLogDelegator() {
      resultSetTableLogger = LoggerFactory.getLogger("jdbc.resultsettable");
      logDelegator = new Slf4jSpyLogDelegator();
   }
	
	 // Result set Log 생성 메서드
	 @Override
   public void resultSetCollected(ResultSetCollector resultSetCollector) {
      if (!resultSetTableLogger.isDebugEnabled()) return;
      try {
         String table = new ResultSetCollectorPrinter().getResultSetToPrint(resultSetCollector, RESULTSET_TABLE_DEFAULT_MAX_ROWS);
         resultSetTableLogger.debug(table);

      // 예외 발생 시 기존 Delegator (Slf4jSpyLogDelegator) 기능 사용
      } catch (Exception customDelegatorExceptionDetected) {
         logDelegator.resultSetCollected(resultSetCollector);
      }
   }
   
   // result set 외의 로깅은 기존 Delegator (Slf4jSpyLogDelegator) 에게 위임
   @Override
   public boolean isJdbcLoggingEnabled() {
      return logDelegator.isJdbcLoggingEnabled();
   }
   
   // ...

 

절사 로직은 ResultSetCollectorPrinter 에서 구현한다. (nested inner class)

// TruncateTableSpyLogDelegator.ResultSetCollectorPrinter
private static class ResultSetCollectorPrinter {

		private final StringBuffer table = new StringBuffer();
      
	  public String getResultSetToPrint(ResultSetCollector resultSetCollector, int maxRows) {
					// ....
		}

 

 

마지막으로 log4j2.properties 파일에서 사용할 Delegator 를 Custom Delegator 로 지정해준다.

log4jdbc.spylogdelegator.name=TruncateTableSpyLogDelegator

 

확인해보면 max rows 초과된 데이터는 잘려서 출력된다..!

 

4. 결론

본 이슈는 비즈니스 로직의 메모리 누수가 아닌 로깅 도구의 비효율적 문자열 처리로 인한 OOM이었다.
log4jdbc의 ResultSet 로깅 로직을 커스터마이징하고, 대용량 데이터에 대한 로그 절삭(Truncation)을 적용함으로써
OOM 문제를 근본적으로 해결하였다.

 

또한, 이를 통해 로깅으로 인한 부수적인 리스크를 줄이고
서비스의 안정성(Availability) 과 확장성(Scalability) 을 모두 확보할 수 있었다.

 

Log에서 발생하는 OOM 문제는 해결했다.

하지만 해당 resultSet을 통해 비즈니스로직에서 Excel 생성 시 메모리 부족이 다시 발생할 가능성은 존재한다고 생각한다. 약 1달 가량의 시간이 지난 지금까지 OOM이 발생하진 않았지만, 지속적으로 모니터링하려 한다.