문제 상황
혈당 일지를 post 또는 update 할 때, 음식 엔티티 insert가 너무 많이 발생한다. 이를 최적화할 수 있는지 방안을 연구할 필요가 있다.
Set up
Sql 통계 측정을 확인하기 위해 spring.jpa.properties.hibernate.generate_statistics=true
을 properties 파일에 추가한다.
Sql 로그도 알아보고 싶다면, spring.jpa.show_sql=true도 추가한다.
Batch insert 실험 전
로직 및 로그
각 식사 시간에 음식을 5개씩 저장했다고 하자. 로그는 다음과 같다.
먼저 작성자의 일지가 저장된다. 일지는 1개이므로 문제가 없다.
작성자 찾기 (사실 세션에 이미 존재하므로 없애도 될 것 같다.)=> 일지 id 지급(복합키이므로 @GeneratedValue 사용 불가다.) => 일지와 작성자 연관 관계 맺기 => 실제 일지 엔티티 저장이 로직에 해당한다.
2022-03-21 11:35:57.099 INFO 13060 --- [nio-8084-exec-8] .d.r.a.c.s.d.SecurityDiaryRestController : post diary with authenticated user
2022-03-21 11:35:57.105 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveDiaryOfWriterById
Hibernate: select writer0_.writer_id as writer_i1_4_0_, writer0_.email as email2_4_0_, writer0_.name as name3_4_0_, writer0_.password as password4_4_0_, writer0_.profile_id as profile_8_4_0_, writer0_.provider as provider5_4_0_, writer0_.provider_id as provider6_4_0_, writer0_.role as role7_4_0_, profile1_.profile_id as profile_1_3_1_, profile1_.diabetes_phase as diabetes2_3_1_ from writer writer0_ left outer join profile profile1_ on writer0_.profile_id=profile1_.profile_id where writer0_.writer_id=?
Hibernate: select max(diabetesdi0_.diary_id) as col_0_0_ from diabetes_diary diabetesdi0_
Hibernate: select diaries0_.writer_id as writer_i2_0_0_, diaries0_.diary_id as diary_id1_0_0_, diaries0_.diary_id as diary_id1_0_1_, diaries0_.writer_id as writer_i2_0_1_, diaries0_.fpg as fpg3_0_1_, diaries0_.remark as remark4_0_1_, diaries0_.written_time as written_5_0_1_ from diabetes_diary diaries0_ where diaries0_.writer_id=?
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=?
Hibernate: insert into diabetes_diary (fpg, remark, written_time, diary_id, writer_id) values (?, ?, ?, ?, ?)
식사는 아침, 점심, 저녁 3번으로 정했다. 각 식사 엔티티 역시 일지 엔티티처럼 각각 4개의 sql을 실행한다.
2022-03-21 11:35:57.166 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveDietOfWriterById
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_, diabetesdi0_.writer_id as writer_i2_0_, diabetesdi0_.fpg as fpg3_0_, diabetesdi0_.remark as remark4_0_, diabetesdi0_.written_time as written_5_0_ from diabetes_diary diabetesdi0_ where diabetesdi0_.writer_id=? and diabetesdi0_.diary_id=?
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_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_.amount as amount2_2_0_, foodlist1_.amount_unit as amount_u3_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: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
2022-03-21 11:35:57.184 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveDietOfWriterById
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_, diabetesdi0_.writer_id as writer_i2_0_, diabetesdi0_.fpg as fpg3_0_, diabetesdi0_.remark as remark4_0_, diabetesdi0_.written_time as written_5_0_ from diabetes_diary diabetesdi0_ where diabetesdi0_.writer_id=? and diabetesdi0_.diary_id=?
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_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_.amount as amount2_2_0_, foodlist1_.amount_unit as amount_u3_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: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
2022-03-21 11:35:57.199 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveDietOfWriterById
Hibernate: select diabetesdi0_.diary_id as diary_id1_0_, diabetesdi0_.writer_id as writer_i2_0_, diabetesdi0_.fpg as fpg3_0_, diabetesdi0_.remark as remark4_0_, diabetesdi0_.written_time as written_5_0_ from diabetes_diary diabetesdi0_ where diabetesdi0_.writer_id=? and diabetesdi0_.diary_id=?
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_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_.amount as amount2_2_0_, foodlist1_.amount_unit as amount_u3_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: insert into diet (blood_sugar, eat_time, diary_id, writer_id, diet_id) values (?, ?, ?, ?, ?)
문제는 음식인데, 음식은 현재 최대 8개까지 저장이 가능하다. 따라서 음식은 8 x 3 = 24번의 insert 쿼리가 실행될 수 있다.
예제 로그는 음식을 5개씩 저장한 것이다. 따라서 3 x 5 = 15번의 insert가 실행된다.
2022-03-21 11:35:57.208 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.223 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.233 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.241 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.248 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.256 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.264 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.271 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.278 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.285 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.292 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.298 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.306 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.313 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)
2022-03-21 11:35:57.319 INFO 13060 --- [nio-8084-exec-8] c.d.r.a.service.domain.SaveDiaryService : saveFoodAndAmountOfWriterById
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_ inner join diabetes_diary diabetesdi1_ on diet0_.diary_id=diabetesdi1_.diary_id and diet0_.writer_id=diabetesdi1_.writer_id and (diabetesdi1_.writer_id=? and diabetesdi1_.diary_id=?) where diet0_.diet_id=?
Hibernate: select max(food0_.food_id) as col_0_0_ from food food0_
Hibernate: select food0_.diary_id as diary_id0_2_0_, food0_.writer_id as writer_i0_2_0_, food0_.diet_id as diet_id0_2_0_, food0_.food_id as food_id1_2_0_, food0_.diary_id as diary_id5_2_0_, food0_.writer_id as writer_i6_2_0_, food0_.diet_id as diet_id7_2_0_, food0_.amount as amount2_2_0_, food0_.amount_unit as amount_u3_2_0_, food0_.food_name as food_nam4_2_0_ from food food0_ where food0_.diary_id=? and food0_.writer_id=? and food0_.diet_id=? and food0_.food_id=?
Hibernate: insert into food (amount, amount_unit, food_name, diary_id, writer_id, diet_id, food_id) values (?, ?, ?, ?, ?, ?, ?)성능 측정
총 77개의 쿼리가 발생한다. 왜냐하면 5 + 4 x 3 + 3 x 5 x 4 =77이기 때문이다.
2022-03-21 13:27:00.880 INFO 8528 --- [nio-8084-exec-8] i.StatisticalLoggingSessionEventListener : Session Metrics {
273300 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
3892600 nanoseconds spent preparing 77 JDBC statements;
27258400 nanoseconds spent executing 77 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
21959500 nanoseconds spent executing 19 flushes (flushing a total of 266 entities and 127 collections);
12800400 nanoseconds spent executing 37 partial-flushes (flushing a total of 488 entities and 488 collections)
}Batch insert 실험 이후
Batch size = 10
이번엔 spring.jpa.properties.hibernate.jdbc.batch_size=10 과 spring.jpa.properties.hibernate.order_inserts=true를 적용해 보았다. 즉, sql이 10개 쌓이면 db로 전송한다.
2022-03-21 13:36:28.337 INFO 14764 --- [nio-8084-exec-3] i.StatisticalLoggingSessionEventListener : Session Metrics {
343200 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
5149700 nanoseconds spent preparing 77 JDBC statements;
30366700 nanoseconds spent executing 58 JDBC statements;
30790500 nanoseconds spent executing 19 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
53539600 nanoseconds spent executing 19 flushes (flushing a total of 266 entities and 127 collections);
14660400 nanoseconds spent executing 37 partial-flushes (flushing a total of 488 entities and 488 collections)
}batch size = 10이 되니 19개의 배치가 생겼다. 이유는 다음과 같다.
1. 배치 연산 도중 다른 쿼리가 들어가면 또 다른 배치를 만든다.
2. spring.jpa.properties.hibernate.order_inserts=true에 의해 insert 연산만 배치를 실시한다.
3. 각각의 음식들이 식사, 일지 엔티티들과 연관관계를 다르게 맺으므로 다른 쿼리로 인식된다. <-(추측이다. 정확한 것은 아님.)
즉, 일지 insert 1개, 식사 insert 3개, 음식 insert 5 x 3 = 15개이다.
원하는 것은 음식 insert 15개가 하나의 배치로 취급되는 것이었다. 하지만, 각각의 음식이 식사 등의 엔티티와 따로 연관관계를 맺다보니 '다른 쿼리'로 인식되는 것 같다. 즉, 원하는 바를 달성할 수는 없었다. 오히려 로그를 보면 성능이 더 안좋아졌다.
batch size = 50
batch size를 50으로 해봐도 동일하게 19개의 배치로 이루어져 있으며, 배치 적용 이전보다 성능이 안 좋아졌다.
2022-03-21 14:25:11.636 INFO 10612 --- [nio-8084-exec-6] i.StatisticalLoggingSessionEventListener : Session Metrics {
324100 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
5849999 nanoseconds spent preparing 77 JDBC statements;
20224201 nanoseconds spent executing 58 JDBC statements;
23799398 nanoseconds spent executing 19 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
49165499 nanoseconds spent executing 19 flushes (flushing a total of 304 entities and 165 collections);
23269298 nanoseconds spent executing 37 partial-flushes (flushing a total of 560 entities and 560 collections)
}느낀 점
JPA 서적 중에 트랜잭션을 지원하는 쓰기 지연을 보고 실험해 본 것이다.
즉 Insert 쿼리가 여러 번 실행될 수는 있어도, 해당 쿼리가 실행될 때마다 DB에 접속하지 않고 좀 지연시킨 후 한꺼번에 DB에 접속하게 하고 싶었다.
해당 기능은 사실 수백, 수천 만건의 대량 데이터를 다루는데 사용된다고 한다. 이렇게 된 건 데이터 규모도 엄청나게 차이나고 , 또 다른 요인이 많이 있을 것이다.
공부가 많이 얕아 잘못된 판단을 하고 있는 지도 모른다. 하지만 일단 jpa batch insert는 사용하지 않는 게 나아보인다.
대신 로그를 분석하다보니 느낀 게 있다.
분명히 세션이 있는 데 왜 작성자를 다시 find하고 있을까?
같은 트랜잭션 내에 있으면, 연관 관계를 맺은 엔티티를 다시 find할 필요가 없지 않을까? 등이 떠오른다.
해당 select 쿼리를 줄인다면 엔티티 하나당 4개의 쿼리에서 3개의 쿼리로 줄일 수 있을 것이다. 해당 방향으로 연구해봐야겠다.
참고 자료
JPA 서적 [김영한]
아키텍쳐 설계와 테스트 코드에 관심이 많음.