DateTime 자동 저장 시 OS에 따른 Time Precision 문제

프로젝트를 진행하던 중 다른 팀원들의 컴퓨터에서는 RoadmapRepositoryTest의 테스트코드가 잘 돌아가지만 이상하게 내 컴퓨터에서만 테스트의 일부가 실패하는 일이 발생함. 추가적으로 실행시킬 때마다 실패하는 테스트가 다른 기이한 현상까지 발생.

내 컴퓨터만 Windows였고 다른 팀원들의 컴퓨터는 Mac이었기에 일단 운영체제에 따른 오류가 있는 것으로 일단 추측하고 일단 Jenkins를 통해 빌드하기로 결정했다. 하지만 이게 웬걸? Jenkins에서도 내 컴퓨터와 똑같은 부분에서 테스트가 실패해서 빌드가 안 됐다. 결국 문제 상황을 재현 가능한 환경이 내 컴퓨터뿐이었기에 하나하나 실험을 하며 원인을 찾아보았다.

 

실패하는 테스트의 특징

• 무한스크롤을 처리하는 로직이다.
• 무한스크롤 처리 시 data가 저장된 시간인 createdAt을 비교한다. 이전에 전달한 페이지의 가장 마지막 원소의 createdAt을 다음 조회할 페이지의 인자로 넘기는 방식

→ 결국 뭔가 createdAt을 비교할 때 문제가 있다는 의심을 할 수 밖에…

 

(위와 같은 테스트를 실행했을 때 성공할 수도, 실패할 수도 있습니다)

 

 

테스트를 간단히 설명하면 다음과 같다

1. 로드맵 세 개를 만든다. 만든 시점에 createdAt이 자동으로 저장되므로 가장 먼저 만들어지는 로드맵이 가장 빠른 createdAt을 가지게 된다.
2. 첫 로드맵 페이지 요청에서 2개의 요소를 가지는 페이지를 요청하면 세 번째 로드맵과 두 번째 로드맵을 전달받기를 예상한다.
3. 두 번째 로드맵 페이지 요청에서 이전에 전달받은 페이지의 가장 마지막 로드맵을 기준으로 그 이전의 로드맵 2개가 담긴 페이지를 요청한다. 하지만 총 로드맵의 갯수가 3개이므로 첫 번째로 만들어진 로드맵 한 개만 전달받는 것을 예상한다.
4. 하지만 두 번째 로드맵 페이지 요청의 응답에 두 개의 로드맵이 담긴 것을 볼 수 있다.

 

findRoadmapPagesByCategory는 다음과 같다. 주목해야 할 부분은 createdAt을 비교해서 해당하는 로드맵을 가져오는 부분이다. 만약 LocalDateTime 타입의 createdAt이 전달된다면 그 값보다 이전의 값을 가진 로드맵만을 가져온다.

 

 

문제 해결하기

로드맵의 createdAt에 어떤 값이 들어가있는지 알아보기 위해 하나씩 찍어보자. 현재 @CreatedDate를 이용하여 로드맵이 영속화될 때 자동으로 createdAt 값이 설정되도록 되어 있는 상태다. JPA를 사용하고 있으므로 영속성컨텍스트에 들어있는 값과 DB에 실제로 저장되어 있는 값을 출력해보았다.

 

CachedRoadmap에는 영속성 컨텍스트에 담긴 값이 저장되었던 값이 저장되어 있고, DBRoadmap에는 영속성 컨텍스트를 비운 뒤 조회했기 때문에 실제 DB에 있는 값이 저장되어 있다. (해당 부분을 정확하게 이해하기 위해서는 JPA와 영속성 컨텍스트에 대한 이해가 필요함을 주의)

 

그런데 코드 상으로는 서로 같은 로드맵임에도 실제 내부에는 다른 값이 담겨있는 것을 볼 수 있다. 영속성 컨텍스트에는 나노초 단위까지, 데이터베이스에는 마이크로초단위까지 저장이 되어 있다. MYSQL에서 datetime은 마이크로초단위까지밖에 저장이 되지 않기에 반올림이 발생한 상황이다.

 

 

테스트가 실패한 이유

테스트를 다시 한 번 보면서 따라가보자.

우선 로드맵은 시간 순서대로 저장이 되기에 여행 로드맵, 게임 로드맵2, 게임 로드맵1 순으로 최신순이다.

이 때 firstRoadmapRequest에는 가장 최신 로드맵인 <여행 로드맵, 게임 로드맵2>이 담겨 있다고 예상할 수 있다. secondRoadmapRequest는 첫 번째 요청에서 전달된 로드맵 중 가장 이전의 로드맵, 즉 게임 로드맵2의 createdAt 값을 기반으로 탐색된 로드맵들이 담겨 있을 것이다. 게임 로드맵2보다 이전에 만들어진 로드맵은 게임 로드맵1, 하나밖에 없으므로 테스트는 정상적으로 통과할 것이다.

하지만 결과는 항상 그렇지는 않았다. secondRoadmapRequest에 두 개의 로드맵에 대한 정보가 담겨질 때가 있었다.

(실패하는 테스트)

 

JPA에서는 사용하려는 entity가 영속성 컨텍스트에 존재하는 걸 감지한다면 DB까지 접근하지 않고 영속성 컨텍스트의 값을 사용한다. 즉 위의 테스트에서 처음에 로드맵을 저장할 때 영속성 컨텍스트에 기록이 된다. 한 테스트 내부에서는 같은 트랜잭션 동안 방금 전에 저장된 로드맵을 Repository에서 조회하기 때문에 DB까지 접근하는 것이 아니라 영속성 컨텍스트의 값을 가지고 온다. 그 후에 전달된 값을 가지고 DB에 저장된 데이터들의 값과 비교를 하게 된다.

간단히 말해 이 메서드에서 인자로 전달된 createdAt의 값은 영속성컨텍스트에서, roadmap.createdAt의 값은 DB에서 가지고 온다는 말이다.

 

그렇다면 이게 어떻게 문제가 되는 것일까? 위에서 출력했던 예시를 보자.

 

나는 CachedRoadmap보다 이전에 만들어진 로드맵만 결과로 얻고 싶다. 그래서 .908522400보다 작은 createdAt 값을 가지는 로드맵들을 DB에서 반환받도록 했다. 당연히 코드는 데이터베이스에 .908522로 주어진 값보다 작은 로드맵이 있길래 반환한다. 하지만 실제로는 이 두 로드맵은 같은 로드맵인 것이다.

MySQL에서 DateTime 형식은 최대 마이크로초 단위까지 저장할 수 있기 때문에, 자동으로 소숫점 7자리 아래 숫자들은 반올림 처리한다. 이 때문에 로드맵이 저장된 시간에 따라 테스트가 성공할 수도, 실패할 수도 있는 상황이 발생한 것이다.

 

 

내 컴퓨터에서만 문제가 발생한 이유는?

@CreatedDate, @LastModifiedDate는 @EntityListners 등의 어노테이션만과 함께 사용하면 스프링이 알아서 영속화 직전에 생성 시간이나 수정 시간을 담아주는 편리한 기능이다. AuditingEntityListener라는 클래스의 코드를 잘 따라가다보면 어떤 코드가 이 역할을 담당하고 있는지 알 수 있다.

 

 

그런데 이 LocalDateTime.now()는 코드를 실행하는 컴퓨터의 시스템 시간의 정밀도를 기반으로 값을 반환한다. 따라서 Windows와 Mac의 차이에 따른 문제가 아니라 OS마다 테스트의 성공 여부가 달라질 수 있다는 얘기다. 해당 이슈는 다음 글에서 볼 수 있다.

https://stackoverflow.com/questions/39586311/java-8-localdatetime-now-only-giving-precision-of-milliseconds

 

 

해결 방법

프로젝트에서 사용한 해결 방법은 다음과 같다.

영속화 이전에 LocalDateTime의 포맷을 정해주기

스프링 빈의 생성 시점, 소멸 시점에 특정한 메서드를 호출하기 위해(현재는 자바에서 지원) @PreConstruct나 @PreRemove 등의 어노테이션을 사용한다. 영속화하는 구간에도 이러한 기능을 지원해주는 어노테이션이 있다. @PrePersist, @PostPersist, @PreUpdate, @PostUpdate 등이다. createdAt이 데이터베이스에 저장되는 것처럼 소숫점 이하 여섯자리까지 저장되도록 강제하고 싶었기 때문에 @PrePersist를 사용해서 다음과 같이 코드를 수정해주어서 문제를 해결해주었다.

• 이전 코드

• 이후 코드

 

이외에도 AuditorAware를 구현하는 방법도 가능할 것으로 보인다.

 

 

정리

@CreatedDate, @LastModifiedDate 등의 어노테이션은 내부적으로 LocalDateTime.now()를 호출해서 시간을 입력한다. 이 때 LocalDateTime.now()의 시간 정밀도는 실행하는 환경에 따라 달라진다.

따라서 사용하는 데이터베이스나 운영체제에 따라 JPA의 영속성 컨텍스트에 담긴 값과 실제 데이터베이스에 담긴 값이 다를 수 있다.

 

P.S

삽입과 조회가 한 컨텍스트에서 진행되는 테스트라는 조건 내에서 발생하는 문제라서 실제 서비스에 적용되었을 때도 발생할 여지가 있을지는 불확실하다. 다만 자동 CI를 구축해놓았을 때 언제는 되고 언제는 안 될 때 이러한 이슈가 있을 수 있다는 생각은 드는 경험이었다.