훈동

디버깅의 함정: 슈뢰딩거의 쿼리?

donghoony

레벨 2의 세 번째 미션. JPA가 도입되면서 이런저런 학습을 하던 중, 크루로부터 기이한 현상을 제보받았다. 연관관계 지연 로딩에서 일어나는 현상이었는데, 정확한 상황은 아래 코드를 확인해 보자. 책과 출판사를 표현하는 두 가지 엔티티 Book과 Publisher가 존재한다.

@Entity
public class Book {

    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private final Long id;
    private final String name;
    @ManyToOne(fetch = FetchType.LAZY)
    private final Publisher publisher;
    
    // constructor, getter
}
@Entity
public class Publisher {

    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private final Long id;
    private final String name;
    @OneToMany(mappedBy = "publisher")
    private final List<Book> books;

    // constructor, getter
}

@JdbcTest를 통해 트랜잭션을 설정하고, 내부에서 아래와 같은 테스트 코드를 작성해 보았다. 

@Test
void getLazyLoadedBookFromPublisher() {
    Publisher publisher = new Publisher("WoowaBooks");
    Book book = new Book("월간 우테코 5월", publisher);
    
    entityManager.persist(publisher);
    entityManager.persist(book);
    entityManager.flush();
//  entityManager.clear();

    Book foundBook = entityManager.find(Book.class, book.getId());
    Publisher foundBookPublisher = foundBook.getPublisher();
    System.out.println("Publisher name : " + foundBookPublisher.getName());
}

현재 entityManager를 통해 flush 연산만 진행했고, 영속성 컨텍스트를 비우지 않았다. 같은 트랜잭션 아래에 있으므로 persist한 엔티티는 관리되고 있는 중이다. 따라서 findById에서 추가적인 쿼리가 발생하지 않고, 즉시 PersistenceContext에서 가져와진다. 온전히 같은 객체인 것이다(identical).

이제 entityManager.clear() 주석을 지워 Context에서 관리하지 않도록 한 뒤, 다시 findById를 한 결과는 어떻게 될까? PersistenceContext, Entity의 생명 주기를 생각하면서 답을 유추해 보자. @ManyToOne 을 통한 지연 로딩을 설정해주었다는 것도 잊지 말자.

PersistenceContext에 엔티티가 존재하지 않으므로, 직접 DB로 쿼리를 날려 해당하는 엔티티를 만들어낸다. 이때, publisher가 지연 로딩되어 있으므로, 프록시 객체가 들어가있는 걸 볼 수 있다. 내부 값이 보이지 않기도 하고. 콘솔로 출력되는 로그 또한 publisher에 대한 select 쿼리가 날아가는 걸 확인했다.

이번에는 반대 상황을 살펴보자. Publisher를 찾은 뒤, 그 안의 값이 어떻게 저장되는 지 살펴보는 것이다. 이번에도 마찬가지로 어떤 식으로 작동할 지 머릿속으로 그려 보자. clear를 하지 않았을 때에는 앞선 결과와 동일하므로, 이번 예시에서는 생략한다. 이번 삽질은 이 코드로부터 시작되었다 🤯

@Test
void findPublisherFromBook() {
    Publisher publisher = new Publisher("WoowaBooks");
    Book april = new Book("월간 우테코 4월", publisher);
    Book may = new Book("월간 우테코 5월", publisher);

    entityManager.persist(publisher);
    entityManager.persist(april);
    entityManager.persist(may);

    entityManager.flush();
    entityManager.clear();

    Publisher foundPublisher = entityManager.find(Publisher.class, publisher.getId());

    List<Book> books = foundPublisher.getBooks();
    System.out.println("Book size : " + books.size());
}

어떤 결과가 출력될 것 같은가? @OneToMany의 fetch가 지연 설정돼 있으므로, 내부 값이 프록시로 보이지 않아야 한다. 메서드를 통해 내부 값을 찔러볼 때, 프록시가 그제서야 추가 쿼리를 날릴 것임을 예상해볼 수 있다. 현재 PersistenceContext에는 어떤 엔티티도 관리되고 있지 않기 때문이다. 하지만..

엥? 내부 값이 보인다. 그럼 쿼리도 날아갔을 듯하다. 콘솔 출력을 확인해 보니, 아래와 같은 쿼리뿐이고 더이상 출력된 건 없었다. Book 테이블로 쿼리가 날아가지 않아 보였다. 어떻게 된 일인지 하루를 꼬박 지내면서 누구의 잘못인지를 확인해보려고 했다. 디버그 포인트를 찍어가면서 어느 부분에서 값이 할당되는지, 쿼리가 정말 날아가지 않는 게 맞는지, 고생고생했던 하루였다.

로그 출력 레벨을 debug로 바꾸었는데도 볼만한 로그가 찍히지 않았다. 우리의 가설은 몇 가지가 있었는데, 내세울 때마다 반례가 튀어나왔다. 몇 가지로는 아래와 같다.

  1. Transactional에서 무언가 하는 것 같다..?
  2. Hibernate에서 무언가 해주는 것 같다..?
  3. EntityManager와 Persistence Context 사이에 무언가 있다..?

하지만 이 세 가지는 모두 공부하다 보니 아니라는 것을 알게 되었다. 우선, JPA, Hibernate, Spring Data JPA가 모두 다르다는 것을 알게 되었다. JPA(Jakarta Persistence API)는 영속성 엔티티에 대한 명세이고, 이를 구현한 게 Hibernate이다. 나아가 스프링에서 활용할 수 있도록 EntityManager를 Repository와 같이 추상화하거나, 쿼리를 메서드를 통해 만들어주거나 등 다양한 기능이 추가돼 Spring Data JPA가 되었다.

나아가, EntityManager는 직접 엔티티를 담아두지 않는다. 관리되는 엔티티가 담기는 곳은 PersistenceContext이다. EntityManager는 PersistenceContext에 접근하기 위해 사용되는 말 그대로 Manager의 역할일 뿐이다. PersistenceContext에게도 생명주기가 존재하며, 이는 보통 Transaction에 종속된다 (Transaction-scoped인 경우).

이 정도를 학습하고 나니 현재 상황이 제시한 가정에도 속하지 않는다는 걸 알게 되었다. 2차 캐시는 기본적으로 비활성화되어 있고… 뭔가 잘못된 부분이 있으리라 생각했지만 JPA 문서 선에서 정리될 뿐이었다. (JPA 문서가 꽤나 친절하게 설명돼 있다. 한 번쯤 엔티티나 영속성 컨텍스트와 관련된 부분이 이해되지 않는다면 읽어 보자!)

디버깅을 통한 브레이크 포인트를 잡기도 쉽지 않았다. AOP 기반으로 진행돼 인터셉터가 대여섯 개 걸쳐있는데다가, 프록시에 값이 언제 담기는가? 를 알아보기 위해서 다양한 클래스의 코드를 새로 읽어나가야 했다. 지나가는 길에 Hibernate가 관리하는 PersistentBag도 구경하고, PersistenceUtil 등을 활용해 지연 로딩이 되었는지 확인하는 법… 여러 좋은 팁을 얻었다.

캠퍼스에서 네오를 붙잡고 지금까지의 상황을 이야기하고, 이런저런 디버깅을 해 봤다. 모든 로그를 띄워보기도 하고, trace 레벨까지 내려 다른 로그가 있는지 확인해봤지만 별다른 수확은 없었다. Context가 비워져있는 상태에서 쿼리가 날아가지 않고 값을 가져오는 것은 더이상 이해되는 부분이 아니었기에, H2의 문제일 수 있지 않을까? 라는 가설도 세워졌다.

이전 미션인 체스 때 진행했던 도커를 끌어오고, MySQL 서버를 열어 모든 쿼리에 대한 로그를 MySQL 서버에서 찍도록 한 뒤, 테스트를 진행해 봤다. 이때까지만 해도 내 눈을 믿지 못했어…🥹 처음에는 보이지 않았던 로그가 보였는데, 그 타이밍이 기가 막혔다.

아니 왜 여기서 쿼리가 나가 🔥

그랬다… Debugger에서 값을 편하게 볼 수 있도록 그때그때 확인해주는 기능을 가지고 있는데, 이걸 펼치는 순간 내부 값을 들여다보는 연산이 진행되었던 것이고, 프록시가 지연로딩 된 객체들의 값을 쿼리를 통해 구성하는 순간을 포착했다. JPA의 잘못도, Hibernate의 잘못도 아닌 IntelliJ가 그럴 줄은 상상도 못 했다.. 🤣

결국 처음 생각했던 게 정답이었다. 가설이랍시고 장황하게 늘어놓았던 친구들은 거짓임이 진작 공부를 통해(…) 밝혀졌고, 한참 삽질할 때 진짜 이게 아닐까? 라고 생각했던 일이 현실이 되었다. 로그가 콘솔에 찍히지 않은 것은 Debugger evaluation을 진행할 때 출력이 나갔으나 다른 File descriptor에 출력되었을 것이라고 짐작하고 있다. 같은 쿼리 메서드를 통해 날아가니 로그가 찍히지 않을 리가 없었다.

혹시나 해서 앞의 @ManyToOne도 확인해봤는데, 마찬가지로 내부 값을 확인하는 순간 추가 쿼리가 날아갔다. 보이는 것은 null이었지만, HibernateProxy 객체가 가지고 있는 필드 중에 쿼리의 결과로 만들어진 객체가 포함돼있는 것을 확인했다.

null이지만 프록시는 알고 있다

이번 사태(?)를 통해 문제를 해결하는 다양한 방법에 대한 인사이트를 얻었다. 로그를 찍는 곳에 브레이크를 건다거나 (사실 이것도… IntelliJ에서 무시된다고 왼쪽 아래에 팝업이 잠깐 올라오긴 한다), IntelliJ마저 믿지 말고 다른 로그 방법을 택한다거나… 와 같이. 아무리 생각해도 상식 밖의 결과라서 모자른 지식인 줄 알고 JPA에 대한 명세도 읽어보고 했는데, 그와 완전 별개의 내용이라니 허무하기도 했다 🤣

여러 가설 중 하나로 우스갯소리로 넘겼던 말이었는데.. 이게 왜 진짜야

그래도 JPA, Hibernate, Lazy loading, EntityManager, Persist Context 등 영속성과 관련돼서 공부한 게 도움되겠지? 특히 @___ToOne에서는 ByteCode가 조작된 HibernateProxy 객체가 들어오고, @___ToMany에서는 PersistentBag, PersistentSet과 같이 List, Set 인터페이스를 구현한 객체가 프록시 역할을 하고 있는 방식의 차이도 알게 되었다. 내가 만든 객체에 대한 프록시를 제공하기 위해서는 인터페이스가 필요할 텐데, 모든 클래스에 이걸 만들어줄 수는 없는 노릇이니 정형화되지 않은 클래스에 대해서는 이런 프록시를 제공한다고 보았다.

이것저것 적어보니 얻어가는 게 많아 좋은 경험… 이라고 생각한다 🥴 다신 이런 늪에 빠지지 않을 테야…

Categories