[디베이트 타이머] GC로 인해 우주가 잠시 꺼진 이야기

안녕하세요 브로콜리입니다.

 

오늘은 디베이트 타이머 프로젝트 운영 과정에서 겪었던 GC 이슈에 대해 공유드리고자 합니다.

 

개요

JPA 더티체킹을 활용한 update문에서 발생가능한 StaleObjectException에러를 설명합니다.

멀티 스레드 애플리케이션 환경에서 GC로 인한 STW 단계의 스레드 정지가 JPA update 에러로 이어질 수 있는 가능성에 대해 설명합니다.

 

문제를 발견한 계기

디베이트 타이머 dev 환경에서 평화를 깨는 에러 알림이 울렸습니다.

 

에러를 보고 적잖이 당황했습니다. ObjectOptimisticLockingFailureException? 낙관적 락...에러? 

애플리케이션에서 락을 활용한 동시성 처리를 하고 있지 않았기 때문에 문제를 특정하기 어려웠습니다. 그러나, MySQL 내부에서 잡히는 묵시적 락일 수도 있으니 한번 살펴볼 필요를 느꼈습니다.

 

에러가 발생한 곳은 엔티티를 조회해 와서 JPA 더티체킹을 활용해 update 문을 날리는 API 였습니다.

    @Transactional
    public CustomizeTable updateUsedAt(long tableId, Member member) {
        CustomizeTableEntity tableEntity = tableRepository.getByIdAndMember(tableId, member);
        tableEntity.updateUsedAt();
        return tableEntity.toDomain();
    }

 

 

Hibernate 소스코드로 에러를 특정해보자

 

Fact1 ) 여러 트랜잭션을 받으며 생기는 동시성 이슈다

ObjectOptimisticLockingFailureException은 스프링 스펙에 정의된 예외로 동시성 이슈와 관련된 에러입니다.

public class OptimisticLockingFailureException extends ConcurrencyFailureException {
    public OptimisticLockingFailureException(@Nullable String msg) {
        super(msg);
    }

    public OptimisticLockingFailureException(@Nullable String msg, @Nullable Throwable cause) {
        super(msg, cause);
    }
}

 

그래서 처음에는 해당 메서드에 따닥과 같은 동시성 테스트를 하며 이슈의 원인을 찾으려 했습니다.

그러나, 원인을 찾지 못했고 에러 메시지로 눈을 돌려 다시금 처음부터 원인을 특정해보았습니다.

 

Fact2 ) Hibernate 내부에서 check 메서드가 호출되었다.

Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect):

 

에러 메시지에서는 업데이트를 시도하는 row가 이미 다른 트랜잭션에 의해 삭제 or 업데이트 되었음을 알려주고 있었습니다.

그리고 hibernate 소스코드를 뜯어본 결과, 해당 에러 메시지는 StaleObjectStateException 안에 정의되어 있었습니다.

import org.hibernate.pretty.MessageHelper;

public class StaleObjectStateException extends StaleStateException {

    public StaleObjectStateException(String entityName, Object identifier) {
        super("Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect)");
        this.entityName = entityName;
        this.identifier = identifier;
    }
    
    //중략..

}

 

그럼 해당 에러를 발생시키는 곳은 어디일까요? Hibernate의 AbstractPersister의 check메서드입니다.

check 메서드는 SQL 쿼리 결과를 실행하고 실행결과를 Expectation과 비교하는 검증에서 만약 예상과 다른 결과가 반환되면 StaleObjectStateException을 던집니다.

	
    //package org.hibernate.persister.entity.AbstractPersistor
    protected boolean check(int rows, Object id, int tableNumber, Expectation expectation, PreparedStatement statement, String statementSQL) throws HibernateException {
        try {
            expectation.verifyOutcome(rows, statement, -1, statementSQL); //쿼리 실행 결과가 예상과 같은지를 검증
            return true;
        } catch (StaleStateException var9) {
           throw new StaleObjectStateException(this.getEntityName(), id); //여기서 에러 발생
        } 
        //중략..
    }

 

이제 hibernate의 update문을 따라가며 언제 check 가 호출되는지를 보면 됩니다.

 

Fact3) Update로 영향을 받는 행의 예상과 결과가 달랐다.

위의 이슈가 발생한 것은 update 문입니다. hibernate는 update 실행 결과, 영향을 받은 행의 수를 기반으로 예측치와 같은지 검증하고 만약 예측치와 다르다면 StaleStateException을 발생시킵니다.

    //package org.hibernate.jdbc.Expectation.intreface;
    public static class RowCount implements Expectation {
        public RowCount() {
        }

        public final void verifyOutcome(@UnknownKeyFor @NonNull @Initialized int rowCount, @UnknownKeyFor @NonNull @Initialized PreparedStatement statement, @UnknownKeyFor @NonNull @Initialized int batchPosition, @UnknownKeyFor @NonNull @Initialized String sql) {
            if (batchPosition < 0) {
                Expectations.checkNonBatched(this.expectedRowCount(), rowCount, sql); 
            } else {
                Expectations.checkBatched(this.expectedRowCount(), rowCount, batchPosition, sql);
            }

        }

        protected @UnknownKeyFor @NonNull @Initialized int expectedRowCount() {
            return 1;
        }
    }
    
    static void checkBatched(@UnknownKeyFor @NonNull @Initialized int expectedRowCount, @UnknownKeyFor @NonNull @Initialized int rowCount, @UnknownKeyFor @NonNull @Initialized int batchPosition, @UnknownKeyFor @NonNull @Initialized String sql) {
        switch (rowCount) {
            case -3:
                throw new BatchFailedException("Batch update failed: " + batchPosition);
            case -2:
                LOG.debugf("Success of batch update unknown: %s", batchPosition);
                break;
            default:
                if (expectedRowCount > rowCount) {
                    throw new StaleStateException("Batch update returned unexpected row count from update [" + batchPosition + "]; actual row count: " + rowCount + "; expected: " + expectedRowCount + "; statement executed: " + sql);
                }

                if (expectedRowCount < rowCount) {
                    throw new BatchedTooManyRowsAffectedException("Batch update returned unexpected row count from update [" + batchPosition + "]; actual row count: " + rowCount + "; expected: " + expectedRowCount, expectedRowCount, rowCount, batchPosition);
                }
        }

    }

    static void checkNonBatched(@UnknownKeyFor @NonNull @Initialized int expectedRowCount, @UnknownKeyFor @NonNull @Initialized int rowCount, @UnknownKeyFor @NonNull @Initialized String sql) {
        if (expectedRowCount > rowCount) {
            throw new StaleStateException("Unexpected row count: " + rowCount + "; expected: " + expectedRowCount + "; statement executed: " + sql);
        } else if (expectedRowCount < rowCount) {
            throw new TooManyRowsAffectedException("Unexpected row count: " + rowCount + "; expected: " + expectedRowCount, 1, rowCount);
        }
    }

 

즉, update문이 날아갈 때 1개의 row가 영향을 받을 것이라고 예상되었으나, 검증결과 실제로는 영향을 받은 행이 없어서 에러가 발생한 것입니다.

 

DataDog을 통해 원인을 특정해보자

위의 에러 내역을 정리하면 예외 메시지처럼 update를 시도할 때 다른 트랜잭션에 의해 행이 삭제된 경우가 유력했습니다.

그런데 이상했습니다. 분명 UI 상 Update 이전에 Delete API 를 호출할 수 있는 케이스가 없기 때문입니다.

 

일단 DataDog을 뜯어보기로 했습니다.

 

 

위의 500에러가 발생한 PATCH update 요청 이전에 실제로 update 대상인 DELETE문이 날아온 것을 볼 수 있습니다.

 

그럼 또 의문이 생깁니다. Dirty Checking을 활용한 update문을 날리기 위해서는 일단 엔티티를 조회해와야 합니다. 만약 데이터가 삭제된 이후에 PATCH 요청이 왔다면 아예 데이터가 조회되지 않아 404 에러가 발생하는게 정상아니었을까요?

 

그때 이 시간대의 PATCH 요청의 응답 시간이 눈에 띄였습니다. 단일 update 요청에 있어서 응답시간이 무려 1.59초가 걸렸습니다.

 

혹시 GC 이슈는 아닐지 문득 떠올랐고,  실제로 UPDATE 요청 발생 시점에 minor GC가 돌아간 것을 볼 수 있었습니다.

 

이제 어느정도 가설이 생겼습니다.

 

트랜잭션 1 : UPDATE 요청 --> 엔티티 조회 --> 메모리 부족! GC STW --> 엔티티 조회 -->  이미 삭제된 테이블 update 시도!

트랜잭션 2 : --------------------DELETE 요청 --> 테이블 삭제

 

즉, 트랜잭션1의 update 요청 에서 엔티티를 조회하고 메모리를 할당받을 때 GC가 돌아 스레드가 일시적으로 스탑되었고, 그 순간에 delete 요청으로 인해 update 대상인 엔티티를 삭제한 것입니다.

 

이후 update 스레드가 재개되고 update 쿼리를 날려 영향이 예상되는 행 수(1개)와 실제 영향 받은 행 수(0개)를 비교하며 StaleException이 발생했다는 가설을 세울 수 있게 되었습니다.

 

테스트를 통해 가설을 검증해보자

 

테스트를 통해 가설을 검증할 차례입니다.

 

먼저 update 문에서 update 문이 날아가기 이전에 GC Stop The World를 흉내낸 Thread.sleep을 추가하였습니다.

public void updateUsedAt() {
        try {
            Thread.sleep(3000L);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        this.usedAt = LocalDateTime.now();
}

 

그리고 update 문과 delete문을 동시 요청해보았습니다.

		
        @Test
        void 테이블의_사용_시간을_업데이트한다() throws InterruptedException {
            Member member = memberGenerator.generate("email@email.com");
            CustomizeTableEntity tableEntity = tableEntityGenerator.generate(member);
            LocalDateTime beforeUsedAt = tableEntity.getUsedAt();

            runAtSameTime(
                    List.of(
                            () -> customizeTableDomainRepository.updateUsedAt(tableEntity.getId(), member),
                            () -> customizeTableDomainRepository.delete(tableEntity.getId(), member)

                    )
            );
        }

 

예상대로 동일한 에러가 재현되는 것을 확인할 수 있었습니다.

 

근데 StaleObjectStateException이 발생했는데 왜 낙관적 락 에러가 발생해요?

Hibernate는 다양한 DB 벤더에서 발생한 비슷한 종류의 예외를 추상화하여 전환합니다.

 

그중 동시성과 관련된 에러는 OptimisticLockException으로 전환합니다. 실ㅈ로 StaleObjectStateException의 경우 ExceptionConvertorImpl에서 OptimisticLockException으로 전환하여 던지고 있었습니다.

    protected PersistenceException wrapStaleStateException(StaleStateException exception) {
		final String message = exception.getMessage();
		if ( exception instanceof StaleObjectStateException staleStateException ) {
			final Object identifier = staleStateException.getIdentifier();
			final String entityName = staleStateException.getEntityName();
			if ( identifier != null ) {
				try {
					final Object entity = session.internalLoad( entityName, identifier, false, true );
					if ( entity instanceof Serializable ) { // avoid some user errors regarding boundary crossing
						return new OptimisticLockException( message, exception, entity ); //여기서 전환됨!
					}
				}
				catch (EntityNotFoundException entityNotFoundException) {
					// swallow it;
				}
			}
		}
		return new OptimisticLockException( message, exception );
	}

 

그렇기 때문에 실제 예외 알림은 StaleObjectStateException이 전환된 OptimisticLockException으로 반환이 되었던 것입니다.

 

느낀 점

 

11월에 겪었던 이슈인만큼 언젠가 정리해야지..하고만 생각하고 있었는데 hibernate를 까보며 왜 에러가 발생했는지를 명확히 특정하고 싶어 시간이 오래 걸렸습니다. 사실 애플리케이션 GC STW Duration이 0.1ms - 0.8ms 이내로 매우 준수한편임에도 불구하고 이런 이슈를 마주하여 꽤 흥미로웠습니다.

 

무엇보다 조회 -> 업데이트 라는 JPA DirtyChecking이 이런 GC 이슈에 취약하다는 점을 느끼고 조회 없이 직접 DB에 update문을 날리는 쿼리로의 전환을 고려하고 있기도 합니다. 그러나, 이러한 Modifying 쿼리는 JPA의 사용의의인 객체 중심 프로그래밍을 해치는 인터페이스라 생각되어 트레이드 오프를 고려하기 쉽지 않은 것도 사실입니다.

 

해당 이슈를 파며 GC 키워드에도 관심을 가지고 더 파보고 싶은 생각도 들었습니다.

- 현재 운영중인 micro 스펙에서 JVM은 어떤 GC를 선택할까? (17버전 default는 G1 GC이나 JVM은 가동하는 환경의 메모리 용량에 따라 GC를 동적으로 선택합니다.)

- GC 힙 크기를 어느정도로 최적화하는 것이 좋을까?

 

GC로 우주가 잠시 꺼졌던 이야기는 여기까지입니다.

댓글을 통한 오류 지적과 피드백은 언제든지 환영입니다.

 

 

Reference)

https://github.com/hibernate/hibernate-orm/blob/main/hibernate-core/src/main/java/org/hibernate/internal/ExceptionConverterImpl.java