OpenSearch Batch 인덱싱 속도 급감 원인 파악

Jang990·2025년 7월 5일

JPA Opensearch ec2 mysql rds springbatch

BookSpot

목록 보기

10/16

SpringBatch 서버에서 OpenSearch로 Bulk 인덱싱 요청을 보내는 과정에서 처리 속도가 갑자기 느려졌다.

그래서 작업을 재시작도 해보기도 하고, 인덱스를 지우고 다시 시작해도
정상적인 속도로 Bulk Insert 작업이 진행되다가 1~2시간정도 지나면 분당 1 청크씩만 처리가 됐다.

단서들

EC2 - 싱글스레드 처리로 10% 미만의 사용률
OpenSearch - 20~40% 사이의 CPU 사용량
OpenSearch - 30~70% 사이의 JVM 메모리 Pressure

AWS에서 제공해주는 모니터링 정보를 확인해보니 전부 정상 범위 안에서 실행중이였다.

인덱싱 지연 시간 또한 정상이였다. 사실 여기서 깨달았어야 했는데 그러지 못했다.

OpenSearch 확인해보기

❌ 검색 가능한 문서?

검색 가능한 문서를 확인해보자.

3번 시도한 기록을 볼 수 있었다.

첫 시도.
작업이 너무 느려져서 멈추고 원인을 알아보다가 모르겠어서 재시작. 너무 느려서 다시 중단
인덱스 세팅을 수정하고 저장해놓은 인덱스를 제거하고 다시 재시도

수직의 붉은선을 기준으로 갑자기 검색 가능한 문서의 수가 조금씩 증가하는 것을 확인할 수 있었다. 마치 크레딧이 모자란 것처럼 2시간 30분정도 정상 속도로 동작하다 갑자기 확 느려졌다.

하지만 OpenSearch는 EBS 볼륨 유형이 범용(SSD) - gp3이기 때문에 크레딧을 사용하지 않는다.
멍청하게도 나는 OpenSearch 쪽 문제인줄 알고, OpenSearch와 관련된 정보를 찾아봤다...

❌ GC의 문제일까?

Young 영역 컬렉션 시간이 끝도없이 증가한다.
시간이 뚝 떨어지는 건 내가 재시작할 때 뚝떨어진 것이다.
근데 이상하게 재시작을 하고 컬렉션 시간이 빠를 때도 문제가 발생한다.

찾아보니 이 값은 누적이라더라.
그래서 재시작을 할 때만 뚝 떨어지는 것이고 값보단 기울기를 봐야하는 영역이였다.

출처: https://stackoverflow.com/a/70435091

❌ IO의 문제일까?

/_nodes/stats/fs로 요청을 보내서 1분간 변화량을 파악해봤다.

딱히 IO의 문제는 아닌 것 같다.

지표	1분 전	1분 후	변화량
작업 수 (operations)	94255	94293	+38
읽기 작업 (read_operations)	23758	23759	+1
쓰기 작업 (write_operations)	70497	70534	+37
읽은 킬로바이트 (read_kilobytes)	979580	979584	+4 KB
쓴 킬로바이트 (write_kilobytes)	771528	771676	+148 KB
읽기 시간 (read_time)	23808 ms	23808 ms	0 ms
쓰기 시간 (write_time)	80028 ms	80056 ms	+28 ms
큐 크기 (queue_size)	103836	103864	+28
I/O 시간 (io_time_in_millis)	63632 ms	63656 ms	+24 ms

아무리 찾아봐도 OpenSearch에서 병목이 생기는 원인을 찾을 수 없었다.

EC2 - Batch 서버 확인하기

OpenSearch에서는 아무리 찾아봐도 원인을 알아볼 수 없었다.
정말 OpenSearch 요청에서 지연이 되는지 확인하기 위해서 Batch 처리를 하는 Reader와 Writer의 처리 시간을 로그로 찍어봤다.

❌ Batch 서버 Writer 로그 찍기

Batch 처리를 진행하는 Writer에 로그를 찍어봤다.

2025-07-04T17:59:41.476+09:00  : => 0 청크 처리 시작
2025-07-04T17:59:46.129+09:00  : => 0 완료 시간 = 4653ms
2025-07-04T18:00:08.215+09:00  : => 1000 청크 처리 시작
2025-07-04T18:00:14.035+09:00  : => 1000 완료 시간 = 5820ms
2025-07-04T18:03:41.461+09:00  : => 2000 청크 처리 시작
2025-07-04T18:03:41.614+09:00  : => 2000 완료 시간 = 153ms
2025-07-04T18:08:45.357+09:00  : => 3000 청크 처리 시작
2025-07-04T18:08:45.524+09:00  : => 3000 완료 시간 = 167ms

OpenSearch에서 처리가 오래 걸린 줄 알았지만 처음 인덱싱 시간을 제외하곤 준수하게 처리됐다.
OpenSearch가 원인이 아니란 것이다.

원인을 파악할 때 Batch 서버에서 먼저 정확하게 원인을 파악했어야 하는데...
의미없이 OpenSearch만 뒤적였다.

✅ Batch 서버 Reader 확인하기

Reader에 로그를 찍어봤다.

-- bookRepository.findAll(PageRequest.of(currentPage, pageSize)).getContent();
BookWithLibraryIdReader   : ===> 책 조회 시작
BookWithLibraryIdReader   : ===> 책 완료 시간 = 66200ms

-- SELECT book_id, JSON_ARRAYAGG(library_id) as library_ids
-- FROM library_stock
-- WHERE book_id in (:bookIds)
-- GROUP BY book_id;
BookWithLibraryIdReader   : ==> 도서관 조회 시작
BookWithLibraryIdReader   : ==> 도서관 완료 시간 = 212ms

BookWithLibraryIdReader   : ===> 책 조회 시작
BookWithLibraryIdReader   : ===> 책 완료 시간 = 155374ms
BookWithLibraryIdReader   : ==> 도서관 조회 시작
BookWithLibraryIdReader   : ==> 도서관 완료 시간 = 249ms

findAll() 부분이 원인이였다.

쿼리 살펴보기

Hibernate: 
    select
        c1_0.id,
        c1_0.author,
        c1_0.created_at,
        c1_0.isbn13,
        c1_0.loan_count,
        c1_0.publication_year,
        c1_0.publisher,
        c1_0.subject_code,
        c1_0.title 
    from
        book c1_0 
    limit
        ?,?
Hibernate: 
    select
        count(c1_0.id) 
    from
        book c1_0

원인

구현하기 쉬워서 findAll을 사용해서 구현했는데 다음과 같은 치명적인 단점들이 있다는 것을 놓쳤다.

비효율적인 Limit, Offset 방식
Page<Book>을 반환해야 하기 때문에 추가적인 count 쿼리 발생

Limit, Offset을 사용하는 방식은 맨 앞의 ID부터 탐색을 하고,
약 300만의 데이터가 있는 Book 테이블에서 count 쿼리가 페이징 쿼리 시도마다 발생하기 때문에 RDS의 gp2 ssd의 버스트 크레딧을 전부 소진하게 된 것이다.

Limit, Offset이 비효율적인 이유는 아래 링크를 참고하자.
https://explainextended.com/2009/10/23/mysql-order-by-limit-performance-late-row-lookups/
.
https://stackoverflow.com/questions/4481388/why-does-mysql-higher-limit-offset-slow-the-query-down