[삽질기록]JPA 실행 순서

이건 누구 보라고 잘 정리해놓은 글보다는 삽질하면서 기록해놓은 글이다. (그래서 문제가 발생했던 메서드의 상세한 코드나 에러 로그 전문은 첨부하지 않았다.)
JPA를 사용하여 기능을 구현하는데 원하는 순서대로 실행이 되지 않아서 Hibernate 로그와 내가 찍은 로그를 보면서 연구를 해봤다..
이거 때문에, 로그인을 몇 번을 했는지, 몇 개의 로그를 찍은건지 모르겠다.....
혹시혹시나 나와 같은 의문으로 글을 찾아보고 있는 사람들을 위해 잠정적으로 내린 결론부터 말해본다. 어차피 아래에도 적을거지만, 아래와 같이 결론을 내렸다.

"JpaRepository의 실행순서와 Hibernate의 로그 출력 시점은 다를 수 있다. delete 메서드는 아이디를 가진 데이터 조회 후, 해당 데이터를 삭제하는 과정을 거치기 때문에, 조회나 저장보다 시간이 오래 걸리는 듯하다. 그래서 조회, 저장 쿼리문보다 빨리 수행되지만, 수행 완료되는 시점이 늦어서 로그가 늦게 찍힐 수 있다."

JPA를 사용하면서 생긴 문제

1. 코드 순서대로 쿼리가 찍히지 않음
2. 삭제했는데, getById로 가져오면 null 이 아니라 정상적인 값이 반환됨

1. 코드 순서대로 쿼리가 찍히지 않았던 부분에 대한 의문

나는 분명 아래의 순서와 같이 코드를 짰다.
1. 기존 데이터 삭제
2. A 테이블에 데이터 저장
3. B 테이블에 데이터 저장
4. C 테이블에서 데이터 조회
5. C 테이블에 데이터 저장 or 수정

근데 쿼리 로그를 보면 아래 순서대로 순서가 뒤죽박죽 실행이 됐다.
2(저장) → 3(저장) → 5(저장 or 수정) → 1(삭제) → 4(조회)

그래서 여기서 한 가지 생각이 들었다.
"그럼 Hibernate 로그가 찍히는 순간과 실제 데이터베이스 연산이 일어나는 시점이 다른걸까?"

2. 삭제한 데이터를 getById로 가져오면 정상적으로 값이 반환되는 부분에 대한 의문

위의 생각을 확인하기 위해, 정확히 데이터가 언제 삭제되는지 알고 싶었다. 그래서 로그를 찍어봤는데, 로그를 찍다보니 또 의문이 들었다.

위에서 언급한 것처럼 원래 1번이 가장 먼저기 때문에 delete 쿼리문부터 로그가 찍혀야하는데, 보면 insert into date_tune...(2번 과정)이 찍힌다.
70: 20 43: 20 이렇게 찍힌 로그는 데이터가 언제 삭제되는지, 제대로 삭제됐는지에 대한 정보를 알아보기 위해 찍은 로그인데, 삭제한 20번 데이터를 자꾸 정상정으로 데이터 정보를 가져온다.

• 로그를 찍기 위해 추가한 코드

log.info("46: {}", dateTuneRepository.getById(20L).getDateTuneNo());

그래서 데이터가 삭제되지 않는건가 싶어서 아래 예시처럼 count 메소드로 레코드 갯수 정보를 로그로 찍어봤다.

• 레코드 갯수를 로그로 찍기 위해 수정한 코드

log.info("41: {}", dateTuneRepository.count());

근데, 또 그러면 delete 쿼리가 순서에 맞게 바로 찍힌다. 왜 로그 하나 차이인데 어쩔때는 delete 로그가 빨리 찍혔다가 어쩔때는 나중에 찍혔다가...도대체 쿼리 로그는 언제 찍히는것인가....

여기서 한 가지 알게 된 점 (getById vs findById)

getById로 로그를 찍다가 한 가지 알게 된 점이 있다. JpaRepository의 구현 클래스인 SimpleJpaRepository를 보면 아래와 같이 메소드가 구현되어 있다.

• getById

	@Override
	public T getById(ID id) {

		Assert.notNull(id, ID_MUST_NOT_BE_NULL);
		return em.getReference(getDomainClass(), id);
	}

• findById

@Override
	public Optional<T> findById(ID id) {

		Assert.notNull(id, ID_MUST_NOT_BE_NULL);

		Class<T> domainType = getDomainClass();

		if (metadata == null) {
			return Optional.ofNullable(em.find(domainType, id));
		}

		LockModeType type = metadata.getLockModeType();

		Map<String, Object> hints = new HashMap<>();
		getQueryHints().withFetchGraphs(em).forEach(hints::put);

		return Optional.ofNullable(type == null ? em.find(domainType, id, hints) : em.find(domainType, id, type, hints));
	}

둘 다 id를 이용해 데이터베이스에서 해당 id를 가진 객체를 찾는 행동을 한다는 점에서는 비슷하다.

다만 getById는 entity자체를 반환하고, findById는 Optional 객체를 반환한다.
또한, 해당 id를 가진 데이터를 찾을 때 getById는 entity manger의 getReference를 사용하고, findById는 find 메소드를 사용한다.

getReference는 엔티티를 반환하는데, 찾는 엔티티가 없으면, EntityNotFoundException을 반환한다.
find는 엔티티 또는 null을 반환한다.

하지만 아무리 찾아봐도, 삭제된 20번의 데이터를 getById(20L)로 가져오려고 할 때, EntityNotFoundException이 발생하는 게 아니라, 정상적으로 데이터를 가져오는지는 이유를 잘 모르겠다. 왜냐하면, 다른 테이블에서도 삭제된 데이터를 똑같은 방법으로 가져와보는 테스트를 했는데, 그건 예상대로 예외가 발생했기 때문이다. 왜 이 테이블만 그런건지...아무래도 getById를 호출한 시점이나 장소?에 따라 다른게 아닐까...

JpaRepository의 실행순서와 Hibernate 로그 출력 시점에 대한 추측

그래서 나 나름대로 삽질을 하면서 잠정적으로 결론을 내렸다.

"JpaRepository의 실행순서와 Hibernate의 로그 출력 시점은 다를 수 있다. delete 메서드는 아이디를 가진 데이터 조회 후, 해당 데이터를 삭제하는 과정을 거치기 때문에, 조회나 저장보다 시간이 오래 걸리는 듯하다. 그래서 조회, 저장 쿼리문보다 빨리 수행되지만, 로그가 늦게 찍힐 수 있다."

이 글 아래 첨부한 로그는 위에서 잠시 언급했던 방법으로, JpaRepository의 count() 메서드로 삭제 시점을 확인했다.
삭제하기 전 데이터 개수는 8개이지만, 삭제 후 7개로 줄어든다. count()로 로그를 찍지 않았을 때와 count()로 로그를 찍었을 때, Hibernate 로그 순서가 다르긴 하지만, 일단은 삭제는 내가 원하는 시점에 바로 수행되는 게 맞는 같다.

2022-08-03 14:45:27.338  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 41: 8
Hibernate: 
    select
        datetune0_.date_tune_no as date_tun1_1_,
        datetune0_.av_date as av_date2_1_,
        datetune0_.schedule_no as schedule3_1_,
        datetune0_.user_no as user_no4_1_ 
    from
        date_tune datetune0_ 
    where
        datetune0_.user_no=? 
        and datetune0_.schedule_no=? 
        and datetune0_.av_date=?
2022-08-03 14:45:27.362  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 🔽 36번 데이터(8번 스케줄, 7번 유저, 2022-08-01) 에 해당하는 데이터 삭제를 시작합니다.🔽
Hibernate: 
    delete 
    from
        date_tune 
    where
        date_tune_no=?
Hibernate: 
    select
        count(*) as col_0_0_ 
    from
        date_tune datetune0_
2022-08-03 14:45:27.406  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 75: 7
Hibernate: 
    select
        count(*) as col_0_0_ 
    from
        date_tune datetune0_
2022-08-03 14:45:27.422  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 43: 7
Hibernate: 
    insert 
    into
        date_tune
        (av_date, schedule_no, user_no) 
    values
        (?, ?, ?)
2022-08-03 14:45:27.437  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 가능 날짜 저장 완료
Hibernate: 
    select
        count(*) as col_0_0_ 
    from
        date_tune datetune0_
2022-08-03 14:45:27.445  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 46: 8
Hibernate: 
    insert 
    into
        av_time
        (av_time, date_tune_no) 
    values
        (?, ?)
2022-08-03 14:45:27.456  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 가능 시간 저장 완료
Hibernate: 
    select
        count(*) as col_0_0_ 
    from
        date_tune datetune0_
2022-08-03 14:45:27.471  INFO 66848 --- [io-8080-exec-10] com.sswu.meets.service.DateTuneService   : 51: 8

삽질을 통해 알게된 점

사실 알게 된 게 모두 맞는지는 모르겠지만, 로그를 찍어보면서 알게 된 점들을 정리한다.

• 쿼리들은 비동기적으로 수행된다. a → b → c 이렇게 순서대로 쿼리들이 실행되도록 명령을 내리더라도 a가 수행되는 동안 b, c도 수행을 하다가 먼저 끝나면, 끝난 순서대로 Hibernate 로그가 찍힌다.
• getById는 Entity를 반환하거나 EntityNotFoundException을 발생시키고, findById는 Entity 또는 null을 반환한다.