문제가 발생한 테스트 코드
@Transactional
@Test
public void findHigherThanBloodSugarBetweenTime() {
Writer me = saveDiaryService.saveWriter("me", "ME@NAVER.COM", Role.User);
DiabetesDiary diary1 = saveDiaryService.saveDiary(me, 20, "test1", LocalDateTime.of(2021, 12, 1, 0, 0, 0));
DiabetesDiary diary2 = saveDiaryService.saveDiary(me, 20, "test1", LocalDateTime.of(2021, 12, 10, 0, 0, 0));
DiabetesDiary diary3 = saveDiaryService.saveDiary(me, 20, "test1", LocalDateTime.of(2021, 12, 25, 0, 0, 0));
Diet diet1 = saveDiaryService.saveDiet(me, diary1, EatTime.BreakFast, 100);
Diet diet2 = saveDiaryService.saveDiet(me, diary1, EatTime.Lunch, 100);
Diet diet3 = saveDiaryService.saveDiet(me, diary1, EatTime.Dinner, 100);
Diet diet4 = saveDiaryService.saveDiet(me, diary2, EatTime.BreakFast, 120);
Diet diet5 = saveDiaryService.saveDiet(me, diary2, EatTime.Lunch, 200);
Diet diet6 = saveDiaryService.saveDiet(me, diary2, EatTime.Dinner, 170);
Diet diet7 = saveDiaryService.saveDiet(me, diary3, EatTime.BreakFast, 150);
Diet diet8 = saveDiaryService.saveDiet(me, diary3, EatTime.Lunch, 120);
Diet diet9 = saveDiaryService.saveDiet(me, diary3, EatTime.Dinner, 140);
//when
List<Diet> dietList = dietRepository.findHigherThanBloodSugarBetweenTime(me.getId(), 150, LocalDateTime.of(2021, 12, 5, 0, 0, 0), LocalDateTime.of(2021, 12, 27, 0, 0, 0));
//then
logger.info(dietList.toString());
assertThat(dietList.size()).isEqualTo(3);
assertThat(dietList.contains(diet5)).isTrue();
assertThat(dietList.contains(diet6)).isTrue();
assertThat(dietList.contains(diet7)).isTrue();
}다 관계 엔티티 세이브 시, update가 추가적으로 발생하는 문제가 발생하였다.
SQL 로그
Hibernate: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)
Hibernate: update writer set create_at=?, updated_at=?, email=?, name=?, role=? where writer_id=?
Hibernate: update diabetes_diary set create_at=?, updated_at=?, fpg=?, remark=?, written_time=? where diary_id=? and writer_id=?
Hibernate: update diabetes_diary set create_at=?, updated_at=?, fpg=?, remark=?, written_time=? where diary_id=? and writer_id=?
Hibernate: update diabetes_diary set create_at=?, updated_at=?, fpg=?, remark=?, written_time=? where diary_id=? and writer_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=?, blood_sugar=?, eat_time=? where diary_id=? and writer_id=? and diet_id=?위 로그는 diet9 엔티티를 저장할 때 나오는 로그이다. (diet1,... diet8 모두에도 len(diet)-1 개수 만큼 update 쿼리가 발생한다.)
insert 문 하나만 있으면 되는데, 쓸데 없이 writer, diabetes_diary , 심지어 다른 diet 엔티티 모두에도 update 쿼리가 발생한다. 이렇게 되면 성능이 매우 저하된다.
실패한 해결책(단방향 매핑 시 update 쿼리 추가되는 이슈 내용 참고)
https://wwlee94.github.io/category/blog/spring-jpa-one-to-many-save-issue/
위 링크에도 save 시 update가 발생하는 문제가 나와있다. 하지만 다대일 양방향 매핑으로 되어있는데도 불구하고 문제가 발생했기 때문에 해당 링크 내용은 이번 문제에 적용될 수 없다.
문제의 예상 원인
아래는 SaveDiaryService 의 엔티티 저장 코드다.
@Transactional
public Writer saveWriter(String name, String email, Role role) {
logger.info("saveWriter");
Writer writer = new Writer(getNextIdOfWriter(), name, email, role);
writerRepository.save(writer);
return writer;
}
@Transactional
public DiabetesDiary saveDiary(Writer writer, int fastingPlasmaGlucose, String remark, LocalDateTime writtenTime) {
logger.info("saveDiary");
DiabetesDiary diary = new DiabetesDiary(getNextIdOfDiary(), writer, fastingPlasmaGlucose, remark, writtenTime);
writer.addDiary(diary);
writerRepository.save(writer);
return diary;
}
@Transactional
public Diet saveDiet(Writer writer, DiabetesDiary diary, EatTime eatTime, int bloodSugar) {
logger.info("saveDiet");
Diet diet = new Diet(getNextIdOfDiet(), diary, eatTime, bloodSugar);
diary.addDiet(diet);
writerRepository.save(writer);
return diet;
}
@Transactional
public Food saveFood(Writer writer, Diet diet, String foodName) {
logger.info("saveFood");
Food food = new Food(getNextIdOfFood(), diet, foodName);
diet.addFood(food);
writerRepository.save(writer);
return food;
}Writer, DiabetesDiary , Diet 모두 컬렉션에 대해 CascadeType.all 을 적용하였다.
예를 들어 saveFood() 시, writerRepository.save(writer); 를 하면 CascadeType.all에 의해 update writer → update diabetes_diary → update diet 가 순차적으로 전파되는 것 같다.
로그 레벨 높여서 확인하기
로그 레벨 높이기
logging.level.org.hibernate=TRACE
logging.level.org.hibernate.hql=INFOsaveWriterWithDiaryWithDietMany 코드의 로그
“dirty”로 검색해보면 문제 원인을 알 수 있다.
2021-12-17 21:40:38.958 INFO 1484 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (SELECT COUNT(di.dietId) FROM Diet di)
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (SELECT COUNT(di.dietId) FROM Diet di)
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing session
2021-12-17 21:40:38.958 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing flush-time cascades
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.958 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.966 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Dirty checking collections
2021-12-17 21:40:38.966 DEBUG 1484 --- [ main] o.hibernate.engine.spi.CollectionEntry : Collection dirty: [jpaEx.domain.diary.writer.Writer.diaries#1]
2021-12-17 21:40:38.966 DEBUG 1484 --- [ main] o.hibernate.engine.spi.CollectionEntry : Collection dirty: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing entities and processing referenced collections
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.writer.Writer.updatedAt is dirty
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.writer.Writer#1]] : [updatedAt]
2021-12-17 21:40:38.966 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.967 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.writer.Writer.updatedAt is dirty
2021-12-17 21:40:38.967 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.writer.Writer#1]] : [updatedAt]
2021-12-17 21:40:38.967 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.writer.Writer.diaries#1], was: [jpaEx.domain.diary.writer.Writer.diaries#1] (initialized)
2021-12-17 21:40:38.967 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diabetesDiary.DiabetesDiary.updatedAt is dirty
2021-12-17 21:40:38.967 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diabetesDiary.DiabetesDiary#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]] : [updatedAt]
2021-12-17 21:40:38.967 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diabetesDiary.DiabetesDiary.updatedAt is dirty
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diabetesDiary.DiabetesDiary#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]] : [updatedAt]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}], was: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}] (initialized)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.createAt is dirty
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c01]] : [createAt, updatedAt]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.createAt is dirty
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c01]] : [createAt, updatedAt]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}] (initialized)
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}], was: [<unreferenced>] (initialized)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing unreferenced collections
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Scheduling collection removes/(re)creates/updates
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 1 insertions, 3 updates, 0 deletions to 4 objects
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 1 (re)creations, 2 updates, 0 removals to 4 collections
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : Listing entities:
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=BreakFast, bloodSugar=100, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.968}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.writer.Writer{role=User, name=ME, diaries=[jpaEx.domain.diary.diabetesDiary.DiabetesDiary], createAt=null, email=TEST@NAVER.COM, writerId=1, updatedAt=2021-12-17T21:40:38.967}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diabetesDiary.DiabetesDiary{fastingPlasmaGlucose=20, dietList=[jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet], remark=test, writtenTime=2021-12-17T21:40:38.907, createAt=null, updatedAt=2021-12-17T21:40:38.968}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Lunch, bloodSugar=200, foodList=[], createAt=2021-12-17T21:40:38.958, updatedAt=2021-12-17T21:40:38.958}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.engine.spi.ActionQueue : Changes must be flushed to space: diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultAutoFlushEventListener : Need to execute flush
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Executing flush
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Inserting entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)
Hibernate: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@18163968 wrapping prep20: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.958]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [TIMESTAMP] - [2021-12-17T21:40:38.958]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [INTEGER] - [200]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.m.m.c.i.NamedEnumValueConverter : Binding [Lunch] to parameter: [4]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [5] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [6] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [7] as [BIGINT] - [2]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@18163968 wrapping prep20: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?) {1: TIMESTAMP '2021-12-17 21:40:38.958', 2: TIMESTAMP '2021-12-17 21:40:38.958', 3: 200, 4: 'Lunch', 5: 1, 6: 1, 7: 2}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@18163968 wrapping prep20: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?) {1: TIMESTAMP '2021-12-17 21:40:38.958', 2: TIMESTAMP '2021-12-17 21:40:38.958', 3: 200, 4: 'Lunch', 5: 1, 6: 1, 7: 2}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : update writer set updated_at=? where writer_id=?
Hibernate: update writer set updated_at=? where writer_id=?
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@800722348 wrapping prep21: update writer set updated_at=? where writer_id=?]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.967]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@800722348 wrapping prep21: update writer set updated_at=? where writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.967', 2: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@800722348 wrapping prep21: update writer set updated_at=? where writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.967', 2: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : update diabetes_diary set updated_at=? where diary_id=? and writer_id=?
Hibernate: update diabetes_diary set updated_at=? where diary_id=? and writer_id=?
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@724190002 wrapping prep22: update diabetes_diary set updated_at=? where diary_id=? and writer_id=?]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.968]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@724190002 wrapping prep22: update diabetes_diary set updated_at=? where diary_id=? and writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.968', 2: 1, 3: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@724190002 wrapping prep22: update diabetes_diary set updated_at=? where diary_id=? and writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.968', 2: 1, 3: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@750667100 wrapping prep23: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [null]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [TIMESTAMP] - [2021-12-17T21:40:38.968]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [4] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [5] as [BIGINT] - [1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@750667100 wrapping prep23: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: NULL, 2: TIMESTAMP '2021-12-17 21:40:38.968', 3: 1, 4: 1, 5: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@750667100 wrapping prep23: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: NULL, 2: TIMESTAMP '2021-12-17 21:40:38.968', 3: 1, 4: 1, 5: 1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Post flush
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.engine.query.spi.HQLQueryPlan : Find: SELECT COUNT(di.dietId) FROM Diet di
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.QueryParameters : Named parameters: {}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@80422114 wrapping prep24: select count(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Registering last query statement [HikariProxyPreparedStatement@80422114 wrapping prep24: select count(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Bound [1] parameters total
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering result set [HikariProxyResultSet@2078510778 wrapping rs21: org.h2.result.LocalResultImpl@2296127 columns: 1 rows: 1 pos: -1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Processing result set
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result set row: 0
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result row:
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([col_0_0_] : [BIGINT]) - [2]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Done processing result set (1 rows)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@80422114 wrapping prep24: select count(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing result set [HikariProxyResultSet@2078510778 wrapping rs21: org.h2.result.LocalResultImpl@2296127 columns: 1 rows: 1 pos: 1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@80422114 wrapping prep24: select count(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.StatefulPersistenceContext : Initializing non-lazy collections
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (SELECT MAX(di.dietId) FROM Diet di)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (SELECT MAX(di.dietId) FROM Diet di)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing session
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing flush-time cascades
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Dirty checking collections
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing entities and processing referenced collections
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.writer.Writer.diaries#1], was: [jpaEx.domain.diary.writer.Writer.diaries#1] (initialized)
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}], was: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}] (initialized)
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}] (initialized)
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}] (initialized)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing unreferenced collections
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Scheduling collection removes/(re)creates/updates
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 0 insertions, 0 updates, 0 deletions to 4 objects
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 0 (re)creations, 0 updates, 0 removals to 4 collections
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : Listing entities:
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=BreakFast, bloodSugar=100, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.968}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.writer.Writer{role=User, name=ME, diaries=[jpaEx.domain.diary.diabetesDiary.DiabetesDiary], createAt=null, email=TEST@NAVER.COM, writerId=1, updatedAt=2021-12-17T21:40:38.967}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diabetesDiary.DiabetesDiary{fastingPlasmaGlucose=20, dietList=[jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet], remark=test, writtenTime=2021-12-17T21:40:38.907, createAt=null, updatedAt=2021-12-17T21:40:38.968}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Lunch, bloodSugar=200, foodList=[], createAt=2021-12-17T21:40:38.958, updatedAt=2021-12-17T21:40:38.958}
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultAutoFlushEventListener : Don't need to execute flush
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.engine.query.spi.HQLQueryPlan : Find: SELECT MAX(di.dietId) FROM Diet di
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.QueryParameters : Named parameters: {}
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.SQL : select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1558397083 wrapping prep25: select max(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Registering last query statement [HikariProxyPreparedStatement@1558397083 wrapping prep25: select max(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Bound [1] parameters total
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering result set [HikariProxyResultSet@30573521 wrapping rs22: org.h2.result.LocalResultImpl@66234b0f columns: 1 rows: 1 pos: -1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Processing result set
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result set row: 0
2021-12-17 21:40:38.968 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result row:
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([col_0_0_] : [BIGINT]) - [2]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Done processing result set (1 rows)
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1558397083 wrapping prep25: select max(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing result set [HikariProxyResultSet@30573521 wrapping rs22: org.h2.result.LocalResultImpl@66234b0f columns: 1 rows: 1 pos: 1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1558397083 wrapping prep25: select max(diet0_.diet_id) as col_0_0_ from diet diet0_]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.StatefulPersistenceContext : Initializing non-lazy collections
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging detached instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Resolved object in session cache: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_MERGE for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to merge: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging detached instance
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Resolved object in session cache: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_MERGE for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to merge: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.968 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging detached instance
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Resolved object in session cache: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to merge: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging detached instance
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Resolved object in session cache: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to merge: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.hibernate.engine.spi.IdentifierValue : ID unsaved-value strategy UNDEFINED
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Detached instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging detached instance
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Object not resolved in any cache: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Fetching entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.976 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Loading entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.976 DEBUG 1484 --- [ main] org.hibernate.SQL : select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1777030223 wrapping prep26: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Registering last query statement [HikariProxyPreparedStatement@1777030223 wrapping prep26: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] - [1]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [3]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Bound [4] parameters total
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering result set [HikariProxyResultSet@2092080808 wrapping rs23: org.h2.result.LocalResultImpl@b5c902 columns: 26 rows: 0 pos: -1]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Processing result set
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Done processing result set (0 rows)
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Total objects hydrated: 0
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.loading.internal.LoadContexts : Constructing collection load context for result set [HikariProxyResultSet@2092080808 wrapping rs23: org.h2.result.LocalResultImpl@b5c902 columns: 26 rows: 0 pos: 0]
2021-12-17 21:40:38.976 DEBUG 1484 --- [ main] o.h.e.l.internal.CollectionLoadContext : No collections were found in result set for role: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1777030223 wrapping prep26: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=? {1: 1, 2: 1, 3: 3}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing result set [HikariProxyResultSet@2092080808 wrapping rs23: org.h2.result.LocalResultImpl@b5c902 columns: 26 rows: 0 pos: 0]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1777030223 wrapping prep26: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id6_1_1_, diet0_.writer_id as writer_i7_1_1_, diet0_.create_at as create_a2_1_1_, diet0_.updated_at as updated_3_1_1_, diet0_.blood_sugar as blood_su4_1_1_, diet0_.eat_time as eat_time5_1_1_, foodlist1_.diary_id as diary_id5_2_3_, foodlist1_.writer_id as writer_i6_2_3_, foodlist1_.diet_id as diet_id7_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id5_2_0_, foodlist1_.writer_id as writer_i6_2_0_, foodlist1_.diet_id as diet_id7_2_0_, foodlist1_.create_at as create_a2_2_0_, foodlist1_.updated_at as updated_3_2_0_, foodlist1_.food_name as food_nam4_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=? {1: 1, 2: 1, 3: 3}]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.i.StatefulPersistenceContext : Initializing non-lazy collections
2021-12-17 21:40:38.976 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Done entity load
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] o.h.e.i.DefaultMergeEventListener : Merging transient instance
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.976 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.978 DEBUG 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Generated identifier: component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}, using strategy: org.hibernate.id.CompositeNestedGeneratedValueGenerator
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Saving [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] o.hibernate.event.internal.WrapVisitor : Wrapped collection in role: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.spi.ActionQueue : Adding an EntityInsertAction for [jpaEx.domain.diary.diet.Diet] object
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.spi.ActionQueue : Adding insert with no non-nullable, transient entities: [EntityInsertAction[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c03]]
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.spi.ActionQueue : Adding resolved non-early insert action.
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_MERGE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_MERGE for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_MERGE for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.978 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_MERGE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.988 DEBUG 1484 --- [ main] o.h.q.c.internal.CriteriaQueryImpl : Rendered criteria query -> select generatedAlias0 from Writer as generatedAlias0
2021-12-17 21:40:38.988 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Unable to locate HQL query plan in cache; generating (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:38.996 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing session
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing flush-time cascades
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Dirty checking collections
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.spi.CollectionEntry : Collection dirty: [jpaEx.domain.diary.writer.Writer.diaries#1]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.spi.CollectionEntry : Collection dirty: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing entities and processing referenced collections
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.writer.Writer.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.writer.Writer#1]] : [updatedAt]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.writer.Writer.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.writer.Writer#1]] : [updatedAt]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.writer.Writer.diaries#1], was: [jpaEx.domain.diary.writer.Writer.diaries#1] (initialized)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diabetesDiary.DiabetesDiary.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diabetesDiary.DiabetesDiary#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]] : [updatedAt]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diabetesDiary.DiabetesDiary.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diabetesDiary.DiabetesDiary#jpaEx.domain.diary.diabetesDiary.DiabetesDiaryId@3e1]] : [updatedAt]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}], was: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}] (initialized)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c01]] : [updatedAt]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c01]] : [updatedAt]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}] (initialized)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.createAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c02]] : [createAt, updatedAt]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.createAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : jpaEx.domain.diary.diet.Diet.updatedAt is dirty
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultFlushEntityEventListener : Found dirty properties [[jpaEx.domain.diary.diet.Diet#jpaEx.domain.diary.diet.DietId@7c02]] : [createAt, updatedAt]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}] (initialized)
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}], was: [<unreferenced>] (initialized)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing unreferenced collections
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Scheduling collection removes/(re)creates/updates
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 1 insertions, 4 updates, 0 deletions to 5 objects
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 1 (re)creations, 2 updates, 0 removals to 5 collections
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : Listing entities:
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=BreakFast, bloodSugar=100, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.writer.Writer{role=User, name=ME, diaries=[jpaEx.domain.diary.diabetesDiary.DiabetesDiary], createAt=null, email=TEST@NAVER.COM, writerId=1, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diabetesDiary.DiabetesDiary{fastingPlasmaGlucose=20, dietList=[jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet], remark=test, writtenTime=2021-12-17T21:40:38.907, createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Lunch, bloodSugar=200, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Dinner, bloodSugar=150, foodList=[], createAt=2021-12-17T21:40:38.976, updatedAt=2021-12-17T21:40:38.976}
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] org.hibernate.engine.spi.ActionQueue : Changes must be flushed to space: writer
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.DefaultAutoFlushEventListener : Need to execute flush
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Executing flush
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Inserting entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] org.hibernate.SQL : insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)
Hibernate: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@188909616 wrapping prep27: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?)]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.976]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [TIMESTAMP] - [2021-12-17T21:40:38.976]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [INTEGER] - [150]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.m.m.c.i.NamedEnumValueConverter : Binding [Dinner] to parameter: [4]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [5] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [6] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [7] as [BIGINT] - [3]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@188909616 wrapping prep27: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?) {1: TIMESTAMP '2021-12-17 21:40:38.976', 2: TIMESTAMP '2021-12-17 21:40:38.976', 3: 150, 4: 'Dinner', 5: 1, 6: 1, 7: 3}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@188909616 wrapping prep27: insert into diet (create_at, updated_at, blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?, ?, ?) {1: TIMESTAMP '2021-12-17 21:40:38.976', 2: TIMESTAMP '2021-12-17 21:40:38.976', 3: 150, 4: 'Dinner', 5: 1, 6: 1, 7: 3}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] org.hibernate.SQL : update writer set updated_at=? where writer_id=?
Hibernate: update writer set updated_at=? where writer_id=?
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1534265514 wrapping prep28: update writer set updated_at=? where writer_id=?]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.998]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1534265514 wrapping prep28: update writer set updated_at=? where writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1534265514 wrapping prep28: update writer set updated_at=? where writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] org.hibernate.SQL : update diabetes_diary set updated_at=? where diary_id=? and writer_id=?
Hibernate: update diabetes_diary set updated_at=? where diary_id=? and writer_id=?
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1118442276 wrapping prep29: update diabetes_diary set updated_at=? where diary_id=? and writer_id=?]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.998]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1118442276 wrapping prep29: update diabetes_diary set updated_at=? where diary_id=? and writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1, 3: 1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1118442276 wrapping prep29: update diabetes_diary set updated_at=? where diary_id=? and writer_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1, 3: 1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.998 DEBUG 1484 --- [ main] org.hibernate.SQL : update diet set updated_at=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set updated_at=? where diary_id=? and writer_id=? and diet_id=?
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1634001207 wrapping prep30: update diet set updated_at=? where diary_id=? and writer_id=? and diet_id=?]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [2021-12-17T21:40:38.998]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [1]
2021-12-17 21:40:38.998 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [4] as [BIGINT] - [1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1634001207 wrapping prep30: update diet set updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1, 3: 1, 4: 1}]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1634001207 wrapping prep30: update diet set updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: TIMESTAMP '2021-12-17 21:40:38.998', 2: 1, 3: 1, 4: 1}]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Updating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:39.006 DEBUG 1484 --- [ main] org.hibernate.SQL : update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?
Hibernate: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@2130241059 wrapping prep31: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=?]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.p.entity.AbstractEntityPersister : Dehydrating entity: [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [TIMESTAMP] - [null]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [TIMESTAMP] - [2021-12-17T21:40:38.998]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [BIGINT] - [1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [4] as [BIGINT] - [1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicBinder : binding parameter [5] as [BIGINT] - [2]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@2130241059 wrapping prep31: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: NULL, 2: TIMESTAMP '2021-12-17 21:40:38.998', 3: 1, 4: 1, 5: 2}]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@2130241059 wrapping prep31: update diet set create_at=?, updated_at=? where diary_id=? and writer_id=? and diet_id=? {1: NULL, 2: TIMESTAMP '2021-12-17 21:40:38.998', 3: 1, 4: 1, 5: 2}]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Post flush
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.engine.query.spi.HQLQueryPlan : Find: select generatedAlias0 from Writer as generatedAlias0
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.hibernate.engine.spi.QueryParameters : Named parameters: {}
2021-12-17 21:40:39.006 DEBUG 1484 --- [ main] org.hibernate.SQL : select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_
Hibernate: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1032689422 wrapping prep32: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Registering last query statement [HikariProxyPreparedStatement@1032689422 wrapping prep32: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Bound [1] parameters total
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering result set [HikariProxyResultSet@799834280 wrapping rs24: org.h2.result.LocalResultImpl@6987a133 columns: 6 rows: 1 pos: -1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Processing result set
2021-12-17 21:40:39.006 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result set row: 0
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([writer_i1_3_] : [BIGINT]) - [1]
2021-12-17 21:40:39.006 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result row: EntityKey[jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Done processing result set (1 rows)
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Total objects hydrated: 0
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1032689422 wrapping prep32: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing result set [HikariProxyResultSet@799834280 wrapping rs24: org.h2.result.LocalResultImpl@6987a133 columns: 6 rows: 1 pos: 1]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1032689422 wrapping prep32: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:39.006 TRACE 1484 --- [ main] o.h.e.i.StatefulPersistenceContext : Initializing non-lazy collections
2021-12-17 21:40:39.048 INFO 1484 --- [ main] j.domain.diary.writer.CreateDiaryTest : Writer[id=1,name=ME,email=TEST@NAVER.COM,role=User]
2021-12-17 21:40:39.056 INFO 1484 --- [ main] j.domain.diary.writer.CreateDiaryTest : DiabetesDiary[id=1,writerId=Writer[id=1,name=ME,email=TEST@NAVER.COM,role=User],fpg=20,remark=test,written time=2021-12-17T21:40:38.907]
2021-12-17 21:40:39.056 INFO 1484 --- [ main] j.domain.diary.writer.CreateDiaryTest : Diet[id=1,diary=DiabetesDiary[id=1,writerId=Writer[id=1,name=ME,email=TEST@NAVER.COM,role=User],fpg=20,remark=test,written time=2021-12-17T21:40:38.907],eatTime=BreakFast,blood sugar=100]
2021-12-17 21:40:39.056 INFO 1484 --- [ main] j.domain.diary.writer.CreateDiaryTest : Diet[id=2,diary=DiabetesDiary[id=1,writerId=Writer[id=1,name=ME,email=TEST@NAVER.COM,role=User],fpg=20,remark=test,written time=2021-12-17T21:40:38.907],eatTime=Lunch,blood sugar=200]
2021-12-17 21:40:39.056 INFO 1484 --- [ main] j.domain.diary.writer.CreateDiaryTest : Diet[id=3,diary=DiabetesDiary[id=1,writerId=Writer[id=1,name=ME,email=TEST@NAVER.COM,role=User],fpg=20,remark=test,written time=2021-12-17T21:40:38.907],eatTime=Dinner,blood sugar=150]
2021-12-17 21:40:39.056 DEBUG 1484 --- [ main] o.h.q.c.internal.CriteriaQueryImpl : Rendered criteria query -> select generatedAlias0 from Writer as generatedAlias0
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.engine.query.spi.QueryPlanCache : Located HQL query plan in cache (select generatedAlias0 from Writer as generatedAlias0)
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing session
2021-12-17 21:40:39.056 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing flush-time cascades
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.056 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to persist on flush: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractSaveEventListener : Persistent instance of: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultPersistEventListener : Ignoring persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_PERSIST_ON_FLUSH for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_PERSIST_ON_FLUSH for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Dirty checking collections
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushing entities and processing referenced collections
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.writer.Writer.diaries#1], was: [jpaEx.domain.diary.writer.Writer.diaries#1] (initialized)
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}], was: [jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList#component[diaryId,writer]{diaryId=1, writer=1}] (initialized)
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}] (initialized)
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}] (initialized)
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.engine.internal.Collections : Collection found: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}], was: [jpaEx.domain.diary.diet.Diet.foodList#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}] (initialized)
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Processing unreferenced collections
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Scheduling collection removes/(re)creates/updates
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 0 insertions, 0 updates, 0 deletions to 5 objects
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.h.e.i.AbstractFlushingEventListener : Flushed: 0 (re)creations, 0 updates, 0 removals to 5 collections
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : Listing entities:
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=BreakFast, bloodSugar=100, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.writer.Writer{role=User, name=ME, diaries=[jpaEx.domain.diary.diabetesDiary.DiabetesDiary], createAt=null, email=TEST@NAVER.COM, writerId=1, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diabetesDiary.DiabetesDiary{fastingPlasmaGlucose=20, dietList=[jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet, jpaEx.domain.diary.diet.Diet], remark=test, writtenTime=2021-12-17T21:40:38.907, createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Lunch, bloodSugar=200, foodList=[], createAt=null, updatedAt=2021-12-17T21:40:38.998}
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.hibernate.internal.util.EntityPrinter : jpaEx.domain.diary.diet.Diet{eatTime=Dinner, bloodSugar=150, foodList=[], createAt=2021-12-17T21:40:38.976, updatedAt=2021-12-17T21:40:38.976}
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultAutoFlushEventListener : Don't need to execute flush
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.engine.query.spi.HQLQueryPlan : Find: select generatedAlias0 from Writer as generatedAlias0
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.QueryParameters : Named parameters: {}
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] org.hibernate.SQL : select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_
Hibernate: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering statement [HikariProxyPreparedStatement@1578052738 wrapping prep33: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Registering last query statement [HikariProxyPreparedStatement@1578052738 wrapping prep33: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Bound [1] parameters total
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Registering result set [HikariProxyResultSet@159791010 wrapping rs25: org.h2.result.LocalResultImpl@4afd65fd columns: 6 rows: 1 pos: -1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Processing result set
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result set row: 0
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.type.descriptor.sql.BasicExtractor : extracted value ([writer_i1_3_] : [BIGINT]) - [1]
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] org.hibernate.loader.Loader : Result row: EntityKey[jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Done processing result set (1 rows)
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.loader.Loader : Total objects hydrated: 0
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing statement [HikariProxyPreparedStatement@1578052738 wrapping prep33: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing result set [HikariProxyResultSet@159791010 wrapping rs25: org.h2.result.LocalResultImpl@4afd65fd columns: 6 rows: 1 pos: 1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Closing prepared statement [HikariProxyPreparedStatement@1578052738 wrapping prep33: select writer0_.writer_id as writer_i1_3_, writer0_.create_at as create_a2_3_, writer0_.updated_at as updated_3_3_, writer0_.email as email4_3_, writer0_.name as name5_3_, writer0_.role as role6_3_ from writer writer0_]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Starting after statement execution processing [ON_CLOSE]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.StatefulPersistenceContext : Initializing non-lazy collections
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Loading entity: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Attempting to resolve: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.internal.DefaultLoadEventListener : Resolved object in session cache: [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting a persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting [jpaEx.domain.diary.writer.Writer#1]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_DELETE for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to delete: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting a persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting [jpaEx.domain.diary.diabetesDiary.DiabetesDiary#component[diaryId,writer]{diaryId=1, writer=1}]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_DELETE for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to delete: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting a persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=1}]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to delete: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting a persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=2}]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.hibernate.engine.spi.CascadingAction : Cascading to delete: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting a persistent instance
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.i.DefaultDeleteEventListener : Deleting [jpaEx.domain.diary.diet.Diet#component[diary,dietId]{diary=component[diaryId,writer]{diaryId=1, writer=1}, dietId=3}]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_DELETE for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diet.Diet.foodList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diet.Diet
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_DELETE for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.diabetesDiary.DiabetesDiary.dietList
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.diabetesDiary.DiabetesDiary
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done cascade ACTION_DELETE for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done deleting orphans for collection: jpaEx.domain.diary.writer.Writer.diaries
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Processing cascade ACTION_DELETE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.engine.internal.Cascade : Done processing cascade ACTION_DELETE for: jpaEx.domain.diary.writer.Writer
2021-12-17 21:40:39.058 DEBUG 1484 --- [ main] o.h.e.t.internal.TransactionImpl : rolling back
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] j.i.AbstractLogicalConnectionImplementor : Preparing to rollback transaction via JDBC Connection.rollback()
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] j.i.AbstractLogicalConnectionImplementor : Transaction rolled-back via JDBC Connection.rollback()
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] j.i.AbstractLogicalConnectionImplementor : re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] j.i.AbstractLogicalConnectionImplementor : LogicalConnection#afterTransaction
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing JDBC resources
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] cResourceLocalTransactionCoordinatorImpl : ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(false)
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] .t.i.SynchronizationRegistryStandardImpl : SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(5)
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.internal.SessionImpl : SessionImpl#afterTransactionCompletion(successful=false, delayed=false)
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] org.hibernate.internal.SessionImpl : Closing session [b9647368-e7d1-48f7-949a-3682beb94089]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.e.jdbc.internal.JdbcCoordinatorImpl : Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl@45e7bb79]
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing JDBC resources
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.LogicalConnectionManagedImpl : Closing logical connection
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.ResourceRegistryStandardImpl : Releasing JDBC resources
2021-12-17 21:40:39.058 TRACE 1484 --- [ main] o.h.r.j.i.LogicalConnectionManagedImpl : Logical connection closed
2021-12-17 21:40:39.058 INFO 1484 --- [ main] o.s.t.c.transaction.TransactionContext : Rolled back transaction for test: [DefaultTestContext@6572421 testClass = CreateDiaryTest, testInstance = jpaEx.domain.diary.writer.CreateDiaryTest@564fabc8, testMethod = saveWriterWithDiaryWithDietMany@CreateDiaryTest, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@6b81ce95 testClass = CreateDiaryTest, locations = '{}', classes = '{class jpaEx.Application}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@6737fd8f, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@68bbe345, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@6895a785, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@59e5ddf], contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map[[empty]]]위 로그를 보니, createdAt, updatedAt에서 더티 체킹이 발생한다. 그래서 BaseTimeEntity 클래스 상속을 하지 않도록 엔티티들을 변경했다.
해결 후 로그
BaseTimeEntity 상속 제거 후 findHigherThanBloodSugarBetweenTime()의 로그다.
insert와 select만 있을 뿐, 불필요한 update 쿼리가 모두 없어졌다.
2021-12-17 21:53:34.466 INFO 2732 --- [ main] o.s.t.c.transaction.TransactionContext : Began transaction (1) for test context [DefaultTestContext@37afeb11 testClass = ReadDiaryTest, testInstance = jpaEx.domain.diary.writer.ReadDiaryTest@223d2c72, testMethod = findHigherThanBloodSugarBetweenTime@ReadDiaryTest, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@515aebb0 testClass = ReadDiaryTest, locations = '{}', classes = '{class jpaEx.Application}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@7494e528, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@9660f4e, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@396f6598, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@704a52ec], contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map[[empty]]]; transaction manager [org.springframework.orm.jpa.JpaTransactionManager@20256a0b]; rollback [true]
2021-12-17 21:53:34.498 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveWriter
Hibernate: select count(writer0_.writer_id) as col_0_0_ from writer writer0_
Hibernate: select writer0_.writer_id as writer_i1_3_1_, writer0_.email as email2_3_1_, writer0_.name as name3_3_1_, writer0_.role as role4_3_1_, diaries1_.writer_id as writer_i2_0_3_, diaries1_.diary_id as diary_id1_0_3_, diaries1_.diary_id as diary_id1_0_0_, diaries1_.writer_id as writer_i2_0_0_, diaries1_.fpg as fpg3_0_0_, diaries1_.remark as remark4_0_0_, diaries1_.written_time as written_5_0_0_ from writer writer0_ left outer join diabetes_diary diaries1_ on writer0_.writer_id=diaries1_.writer_id where writer0_.writer_id=?
2021-12-17 21:53:34.547 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiary
Hibernate: insert into writer (email, name, role, writer_id) values (?, ?, ?, ?)
Hibernate: select count(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_1_, diabetesdi0_.writer_id as writer_i2_0_1_, diabetesdi0_.fpg as fpg3_0_1_, diabetesdi0_.remark as remark4_0_1_, diabetesdi0_.written_time as written_5_0_1_, dietlist1_.diary_id as diary_id4_1_3_, dietlist1_.writer_id as writer_i5_1_3_, dietlist1_.diary_id as diary_id0_1_3_, dietlist1_.writer_id as writer_i0_1_3_, dietlist1_.diet_id as diet_id1_1_3_, dietlist1_.diary_id as diary_id0_1_0_, dietlist1_.writer_id as writer_i0_1_0_, dietlist1_.diet_id as diet_id1_1_0_, dietlist1_.diary_id as diary_id4_1_0_, dietlist1_.writer_id as writer_i5_1_0_, dietlist1_.blood_sugar as blood_su2_1_0_, dietlist1_.eat_time as eat_time3_1_0_ from diabetes_diary diabetesdi0_ left outer join diet dietlist1_ on diabetesdi0_.diary_id=dietlist1_.diary_id and diabetesdi0_.writer_id=dietlist1_.writer_id where diabetesdi0_.diary_id=? and diabetesdi0_.writer_id=?
2021-12-17 21:53:34.549 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiary
Hibernate: insert into diabetes_diary (fpg, remark, written_time, diary_id, writer_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select max(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_1_, diabetesdi0_.writer_id as writer_i2_0_1_, diabetesdi0_.fpg as fpg3_0_1_, diabetesdi0_.remark as remark4_0_1_, diabetesdi0_.written_time as written_5_0_1_, dietlist1_.diary_id as diary_id4_1_3_, dietlist1_.writer_id as writer_i5_1_3_, dietlist1_.diary_id as diary_id0_1_3_, dietlist1_.writer_id as writer_i0_1_3_, dietlist1_.diet_id as diet_id1_1_3_, dietlist1_.diary_id as diary_id0_1_0_, dietlist1_.writer_id as writer_i0_1_0_, dietlist1_.diet_id as diet_id1_1_0_, dietlist1_.diary_id as diary_id4_1_0_, dietlist1_.writer_id as writer_i5_1_0_, dietlist1_.blood_sugar as blood_su2_1_0_, dietlist1_.eat_time as eat_time3_1_0_ from diabetes_diary diabetesdi0_ left outer join diet dietlist1_ on diabetesdi0_.diary_id=dietlist1_.diary_id and diabetesdi0_.writer_id=dietlist1_.writer_id where diabetesdi0_.diary_id=? and diabetesdi0_.writer_id=?
2021-12-17 21:53:34.559 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiary
Hibernate: insert into diabetes_diary (fpg, remark, written_time, diary_id, writer_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select max(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_1_, diabetesdi0_.writer_id as writer_i2_0_1_, diabetesdi0_.fpg as fpg3_0_1_, diabetesdi0_.remark as remark4_0_1_, diabetesdi0_.written_time as written_5_0_1_, dietlist1_.diary_id as diary_id4_1_3_, dietlist1_.writer_id as writer_i5_1_3_, dietlist1_.diary_id as diary_id0_1_3_, dietlist1_.writer_id as writer_i0_1_3_, dietlist1_.diet_id as diet_id1_1_3_, dietlist1_.diary_id as diary_id0_1_0_, dietlist1_.writer_id as writer_i0_1_0_, dietlist1_.diet_id as diet_id1_1_0_, dietlist1_.diary_id as diary_id4_1_0_, dietlist1_.writer_id as writer_i5_1_0_, dietlist1_.blood_sugar as blood_su2_1_0_, dietlist1_.eat_time as eat_time3_1_0_ from diabetes_diary diabetesdi0_ left outer join diet dietlist1_ on diabetesdi0_.diary_id=dietlist1_.diary_id and diabetesdi0_.writer_id=dietlist1_.writer_id where diabetesdi0_.diary_id=? and diabetesdi0_.writer_id=?
2021-12-17 21:53:34.559 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diabetes_diary (fpg, remark, written_time, diary_id, writer_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.567 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.569 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.569 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.579 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.579 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.579 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.589 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
2021-12-17 21:53:34.589 INFO 2732 --- [ main] jpaEx.service.SaveDiaryService : saveDiet
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select count(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select max(diet0_.diet_id) as col_0_0_ from diet diet0_
Hibernate: select diet0_.diary_id as diary_id0_1_1_, diet0_.writer_id as writer_i0_1_1_, diet0_.diet_id as diet_id1_1_1_, diet0_.diary_id as diary_id4_1_1_, diet0_.writer_id as writer_i5_1_1_, diet0_.blood_sugar as blood_su2_1_1_, diet0_.eat_time as eat_time3_1_1_, foodlist1_.diary_id as diary_id3_2_3_, foodlist1_.writer_id as writer_i4_2_3_, foodlist1_.diet_id as diet_id5_2_3_, foodlist1_.diary_id as diary_id0_2_3_, foodlist1_.writer_id as writer_i0_2_3_, foodlist1_.diet_id as diet_id0_2_3_, foodlist1_.food_id as food_id1_2_3_, foodlist1_.diary_id as diary_id0_2_0_, foodlist1_.writer_id as writer_i0_2_0_, foodlist1_.diet_id as diet_id0_2_0_, foodlist1_.food_id as food_id1_2_0_, foodlist1_.diary_id as diary_id3_2_0_, foodlist1_.writer_id as writer_i4_2_0_, foodlist1_.diet_id as diet_id5_2_0_, foodlist1_.food_name as food_nam2_2_0_ from diet diet0_ left outer join food foodlist1_ on diet0_.diary_id=foodlist1_.diary_id and diet0_.writer_id=foodlist1_.writer_id and diet0_.diet_id=foodlist1_.diet_id where diet0_.diary_id=? and diet0_.writer_id=? and diet0_.diet_id=?
Hibernate: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
Hibernate: select diet0_.diary_id as diary_id0_1_, diet0_.writer_id as writer_i0_1_, diet0_.diet_id as diet_id1_1_, diet0_.diary_id as diary_id4_1_, diet0_.writer_id as writer_i5_1_, diet0_.blood_sugar as blood_su2_1_, diet0_.eat_time as eat_time3_1_ from diet diet0_ cross join diabetes_diary diabetesdi1_ where diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and diabetesdi1_.writer_id=? and diet0_.blood_sugar>=? and (diabetesdi1_.written_time between ? and ?)
2021-12-17 21:53:34.609 INFO 2732 --- [ main] jpaEx.domain.diary.writer.ReadDiaryTest : [Diet[id=5,diary=DiabetesDiary[id=2,writerId=Writer[id=1,name=me,email=ME@NAVER.COM,role=User],fpg=20,remark=test1,written time=2021-12-10T00:00],eatTime=Lunch,blood sugar=200], Diet[id=6,diary=DiabetesDiary[id=2,writerId=Writer[id=1,name=me,email=ME@NAVER.COM,role=User],fpg=20,remark=test1,written time=2021-12-10T00:00],eatTime=Dinner,blood sugar=170], Diet[id=7,diary=DiabetesDiary[id=3,writerId=Writer[id=1,name=me,email=ME@NAVER.COM,role=User],fpg=20,remark=test1,written time=2021-12-25T00:00],eatTime=BreakFast,blood sugar=150]]
Hibernate: select writer0_.writer_id as writer_i1_3_, writer0_.email as email2_3_, writer0_.name as name3_3_, writer0_.role as role4_3_ from writer writer0_
2021-12-17 21:53:34.659 INFO 2732 --- [ main] o.s.t.c.transaction.TransactionContext : Rolled back transaction for test: [DefaultTestContext@37afeb11 testClass = ReadDiaryTest, testInstance = jpaEx.domain.diary.writer.ReadDiaryTest@223d2c72, testMethod = findHigherThanBloodSugarBetweenTime@ReadDiaryTest, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@515aebb0 testClass = ReadDiaryTest, locations = '{}', classes = '{class jpaEx.Application}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@7494e528, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@9660f4e, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@396f6598, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@704a52ec], contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map[[empty]]]찾아낸 진짜 원인
시나리오는 다음과 같다.
1.최상위 Writer가 10:14분에 만들어졌다. (save(writer))
2.그 다음 Diary를 10:15분에 만들고 연관관계 설정해서 최상위를 저장하면, (save(writer)) 최상위 갱신시간이 10:15분으로 변경된다.
3.손주 엔티티인 Diet를 10:16분에 만들고 최상위로 저장하면, (save(writer)) 최상위 갱신시간이 10:16분으로 변경된다.
그러면 cascade로 인해 자식 엔티티인 Diary도 갱신시간 10:16분 변경된다.
4.증손주 10:17에 만들어졌으면 최상위로 저장하면(save(writer)) 최상위 갱신시간이 10:16분으로 변경된다. 그러면 cascade로인해 자식 엔티티인 Diary, 손주 엔티티인 Diet 모두 갱신시간 10:17분으로 변경된다.
느낀 점
구글링하는 것 보다도, 로그 레벨이 높은 로그를 봐서 분석하는 것이 더 빠르고 정확하다.
시드 레벨 스타트업의 2호 직원으로서 백엔드 시스템의 70%를 설계 및 개발하였고, TIPS 5억 투자 유치에 기여한 서버 개발자입니다. (Go/Python/MSA/Spring)