[Trouble Shooting] 쿼리 로그 저장 기능 개선하기 (1)

🎯 로그 전송 기능 개선  

---

지난 포스팅에서는 SDK를 통해 서버에서 발생하는 로그를 콘솔에 남기고, 이를 중앙 로그 수집 서버로 전송하는 기본적인 방법에 대해 알아보았습니다. 하지만 로그가 발생할 때마다 API 요청으로 중앙 서버로 전송하는 방식은 비효율적이고, 프로덕션 환경에 악영향을 줄 수 있다는 점을 발견했습니다.

 

 

일단, 성능 비교를 위해 기존 로그 저장 API 에 대한 성능을 분석했습니다.

 

 

초당 500 개의 요청을 10초 동안 보냄 == 5000 건의 요청 결과 (K6)

 

요청 목표	5000 (500req/s × 10s)
성공 요청 수	2089건	서버가 실제 처리한 요청 수
Dropped 요청 수	2911건	처리하지 못한 요청 수 (약 58%)
성공률	100% (2089 중 실패 0)	처리된 요청은 모두 HTTP 200
95% 응답 시간	2500ms	응답 시간 ↑ 매우 느려짐
최대 응답 시간	7800ms	서버가 매우 느리게 응답한 경우 존재

 

 

테스트 시나리오를 점진적으로 증가시켜 분석해본 결과 1초에 100 건 정도의 요청만이 안정적으로 처리되었습니다. 500건 정도의 요청으로 증가시켜본 결과 절반 이상의 요청이 Dropped 되며 안정적으로 로그 저장이 수행되지 못 했습니다. 즉 현재 로그 저장 기능은 1개의 요청이 1개의 로그만을 저장하고 있어 개선이 필요해보였습니다.

 

 

🎯 병목 지점 분석

---

 

JVM관련 지표와 CPU 사용률

 

위, 부하 테스트 결과  JVM 관련 지표와 CPU 사용량에서는 매우 안정적인 상태를 보였습니다. 

 

하지만, 평균 응답 시간이 2.5초, 최대 응답 시간이 7.8초에 달하는 등, 비교적 단순한 로직임에도 불구하고 높은 응답 시간이 나타났습니다.  심지어 외부 API 를 사용하지도 않고 DB 에 쏘는 쿼리도 매우 단순하기 때문에, 병목 지점이 DB 커넥션 처리 과정에 있을 가능성이 높다고 판단했습니다.

 

현재 로그 저장 API는 단일 로그 객체를 요청받아 저장하는 단건 저장 방식으로 구현되어 있습니다. 이는 곧 요청 1건마다 새로운 DB 커넥션을 열고, 트랜잭션을 생성한 뒤 로그를 저장하고 커밋하는 과정을 반복한다는 것을 의미합니다.

 

테스트 결과, 초당 500건 × 10초 = 총 5000건의 로그가 요청되었지만, 절반 이상이 dropped 되었고 성공적으로 저장된 로그는 2089건에 불과했습니다. 이는 요청이 몰리면서 커넥션 풀의 커넥션이 모두 소진되고, 추가 요청들이 풀에서 대기하다가 타임아웃되어 버려지는 현상임을 확인했습니다.

 

 

결론적으로, 단건 INSERT 방식은 TPS(초당 처리량) 측면에서 매우 비효율적이며, 해당 부분에 대한 개선이 필요함을 느꼈습니다.

 

 

🎯 버퍼(buffer) 와 비동기를 이용한 성능 개선

---

기존 로직은, SDK를 사용하는 애플리케이션에서 로그가 발생하면 즉시 로그 수집 서버로 전송한 뒤, 단일 로그 단위로 저장하는 구조였습니다. 이로 인해 요청마다 별도의 DB 커넥션과 트랜잭션이 생성되어, 대량의 로그가 몰릴 경우 DB 커넥션 풀이 모두 소진되며 성능 병목이 발생했습니다.

 

이를 개선하기 위해 로그 전송 및 저장 방식에 다음과 같이 개선했습니다.

 

[ 로그 전송 로직 개선 ] 

 

1. SDK 내에서 발생한 로그 PriorityQueue 임시 저장

2. 큐에 일정 개수 쌓임 or 10초 주기로 비동기 전송 

 

[ 로그 저장 로직 개선 ] 

 

1. 로그 수집 서버가 받은 로그를 BlockingQueue 에 저장

2. 일정 주기 or 일정량 쌓일때 saveAll() 을 이용해 한번의 DB커넥션으로 여러개의 로그를 일괄 저장 

 

 

수정된 로그 수집 && 저장 아키텍처

 

 

 

[ 버퍼와 비동기를 이용한 로그 저장 ] 

@Service
@RequiredArgsConstructor
public class BufferedQueryLogService {

    private final QueryLogRepository queryLogRepository;
    private final BlockingQueue<QueryLog> buffer = new LinkedBlockingQueue<>(10000); // 최대 1만건 버퍼

    @PostConstruct
    public void init() {
        Executors.newSingleThreadExecutor().execute(() -> {
            while (true) {
                try {
                    flushBuffer();           // 버퍼 비움
                    Thread.sleep(1000);      // 1초 대기
                } catch (InterruptedException e) {
                    Thread.currentThread().interrupt(); // 현재 쓰레드 인터럽트 설정
                    break; // 루프 종료
                } catch (Exception e) {
                    // flushBuffer에서 발생하는 예외는 로깅하고 루프 계속
                    e.printStackTrace();
                }
            }
        });
    }

    // 다건 로그 요청 처리
    public void saveBufferedBatch(String key, List<QueryLogRequest> requests) {
        for (QueryLogRequest request : requests) {
            QueryLog log = QueryLog.from(key, request);
            buffer.offer(log); // 큐에 하나씩 적재
        }
    }

    // 큐에서 꺼내서 DB에 저장 요청 (비동기 메서드 호출)
    private void flushBuffer() {
        List<QueryLog> batch = new ArrayList<>();
        buffer.drainTo(batch, 1000); // 최대 1000건까지 비움
        if (!batch.isEmpty()) {
            saveLogsAsync(batch);
        }
    }

    // 실제 DB 저장은 비동기로 처리
    @Async
    public void saveLogsAsync(List<QueryLog> logs) {
        try {
            queryLogRepository.saveAll(logs);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

 

BufferedQueryLogService는 쿼리 로그를 바로 DB에 저장하지 않고, 메모리 내 큐에 모았다가 일정 시간마다 한 번에 비동기 처리로 저장합니다.

 

 

버퍼링: 최대 1만 건까지 로그를 LinkedBlockingQueue에 쌓아두어 DB 부하 감소

주기적 저장: 별도 스레드가 1초마다 큐에서 최대 1000건을 꺼내 DB에 저장하는 작업 수행

비동기 처리: DB 저장은 @Async를 통해 비동기로 실행되어 메인 로직의 지연을 최소화

 

 

 

초당 500 개의 요청을 10초 동안 보냄 == 5000 건의 요청 결과 (K6)

 

요청 목표	5000 (500req/s × 10s)
성공 요청 수	4962건	서버가 실제 처리한 요청 수
성공률	100% (2089 중 실패 0)	처리된 요청은 모두 HTTP 200
95% 응답 시간	18ms	응답 시간 안정적
최대 응답 시간	570ms	응답 시간 안정적

 

 

개선 전 코드와 비교해봤을때, 성능이 눈에 띄게 향상된 것을 확인할 수 있었습니다. 기존에 한번의 요청에 한 건의 로그만을 저장해 (테스트 시나리오 에서) 총 5000 건의 로그를 10초동안 반절조차 저장하지 못했습니다.

 

하지만 개선 후 한번의 요청에 10개의 로그를 담아 테스트 해본결과 50000 건의 로그를 10초동안 드롭된 요청이 거의 없이 상대적으로 안전하게 처리할 수 있었습니다. 

 

---

 

 

하지만, 아직 드롭된 요청이 조금 남아 있었습니다. 그렇다면 어디가 병목 지점일까? 다시 한번 찾아봅시다.

 

@Service
@RequiredArgsConstructor
public class BufferedQueryLogService {

    private final QueryLogRepository queryLogRepository;
    private final BlockingQueue<QueryLog> buffer = new LinkedBlockingQueue<>(10000); // 최대 1만건 버퍼

   ...
   
    // 큐에서 꺼내서 DB에 저장 요청 (비동기 메서드 호출)
    private void flushBuffer() {
        List<QueryLog> batch = new ArrayList<>();
        buffer.drainTo(batch, 1000); // 최대 1000건까지 비움
        if (!batch.isEmpty()) {
            saveLogsAsync(batch);
        }
    }
    
    // 실제 DB 저장은 비동기로 처리
    @Async
    public void saveLogsAsync(List<QueryLog> logs) {
        try {
            queryLogRepository.saveAll(logs);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

 

saveLogAsync 메서드는 1초마다 큐에서 최대 1000개의 로그를 꺼내 비동기로 MongoDB에 저장하는 기능입니다. 이때, MongoRepository의 saveAll() 메서드는 내부적으로 각 엔티티가 이미 존재하는지 판단하고, 존재하면 업데이트(upsert)를 수행하기 때문에 대량의 데이터를 저장할 때 성능 저하가 발생할 수 있습니다. --> 여기가 병목 지점!

 

 

반면 MongoTemplate 의 insert 는 지정된 도메인 클래스와 함께 전달된 컬렉션의 중복 여부를 확인하지 않고 일괄 삽입합니다. 즉, 존재 여부에 상관없이 빠른 처리가 가능해집니다.

 

 

( 로그라는 데이터 특성상 중복되어도 크게 상관없다 생각해 중복 여부 보다 저장 속도가 더 중요하다 생각함 )

 

MongoTemplate 의 insert 내부 동작 과정

 

 

수정된 코드

@Service
@RequiredArgsConstructor
public class BufferedQueryLogService {
    @Autowired
    private MongoTemplate mongoTemplate;
    private final BlockingQueue<QueryLog> buffer = new LinkedBlockingQueue<>(10000); // 최대 1만건 버퍼

    @PostConstruct
    public void init() {
        Executors.newSingleThreadExecutor().execute(() -> {
            while (true) {
                try {
                    flushBuffer();           // 버퍼 비움
                    Thread.sleep(1000);      // 1초 대기
                } catch (InterruptedException e) {
                    Thread.currentThread().interrupt(); // 현재 쓰레드 인터럽트 설정
                    break; // 루프 종료
                } catch (Exception e) {
                    // flushBuffer에서 발생하는 예외는 로깅하고 루프 계속
                    e.printStackTrace();
                }
            }
        });
    }

    // 다건 로그 요청 처리
    public void saveBufferedBatch(String key, List<QueryLogRequest> requests) {
        for (QueryLogRequest request : requests) {
            QueryLog log = QueryLog.from(key, request);
            buffer.offer(log); // 큐에 하나씩 적재
        }
    }

    // 큐에서 꺼내서 DB에 저장 요청 (비동기 메서드 호출)
    private void flushBuffer() {
        List<QueryLog> batch = new ArrayList<>();
        buffer.drainTo(batch, 1000); // 최대 1000건까지 비움
        if (!batch.isEmpty()) {
            saveLogsAsync(batch);
        }
    }

    // 실제 DB 저장은 비동기로 처리
    @Async
    public void saveLogsAsync(List<QueryLog> logs) {
        try {
            mongoTemplate.insert(logs, QueryLog.class);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

 

 

수정된 코드 부하 테스트 결과 (K6)

Grafana

 

드롭된 요청 없이 모든 요청에 대해 성공적으로 처리할 수 있었고, 평균 응답 시간도 18.4ms -> 1.83ms 큰폭으로 향상 된 것을 확인할 수 있습니다. 

 

 

그러면 요청을 어느정도까지 안정적으로 처리할 수 있을까? 부하 테스트 시나리오를 좀 더 극단적으로 끌어 올려보자

 

 

1번의 요청에 100건의 로그를 넣고, 1초에 1000번의 요청을 10초 동안 보냈을때의 결과 입니다. 

 

K6 결과

 

총 9902 건의 요청을 처리했고, 99건의 요청이 드롭되었습니다. 99% 정도의 요청이 성공적으로 처리 되었고 평균 응답 시간도 27.15MS 로 매우 빨랐습니다. 

 

요청 수(9902) X 로그수(100) 를 기반으로 초당 처리되는 로그 수를 계산해보면, 1초에 99,020 건 정도의 로그를 저장할 수 있습니다.