[Trouble Shooting] 쿼리 로그 저장 기능 개선하기 (2)
🎯 로그 조회 기능을 만들다가… 100,000건 넣었는데 왜 30,000건밖에 없지?
( 본 포스팅은 아래 내용과 이어집니다.)
https://comumu.tistory.com/177
[Trouble Shooting] 쿼리 로그 저장 기능 개선하기 (1)
🎯 로그 전송 기능 개선 지난 포스팅에서는 SDK를 통해 서버에서 발생하는 로그를 콘솔에 남기고, 이를 중앙 로그 수집 서버로 전송하는 기본적인 방법에 대해 알아보았습니다. 하지만 로그가
comumu.tistory.com
로그 조회 기능을 개발하면서 테스트를 위해 약 100,000건의 데이터를 저장한 뒤, 이 데이터를 기반으로 여러 가지 테스트를 진행했습니다. 그런데 테스트를 하던 중 이상한 점을 발견했습니다. 분명 100,000 건의 로그를 저장했는데 실제로 MongoDB 에 저장된 로그는 고작 30,000 건 남짓이였습니다.
이전 포스팅에서 로그 저장 로직을 개선하면서 k6 를 활용해 부하 테스트를 진행했습니다. 당시에는 요청의 성공 여부와 드롭된 요청 개수만을 기준으로 안정성을 판단했고 "오~ HTTP 요청 성공률도 높고, 로그도 잘 쌓이겠네 ㅋㅋ" 라는 멍청한 생각을 했던거죠..
그럼 어디가 문제지 ?? 바로 로그 저장 요청은 서버에서 버퍼(Queue) 에 먼저 저장되고, 이 버퍼에서 일정량이 쌓이면 비동기로 MongoDB 에 insert 되도록 구현했었습니다. 그런데 ,,, MongoDB 에 데이터가 삽입되는 속도가 버퍼에서 로그가 쌓이는 속도를 따라가지 못했던 것입니다. 즉, 버퍼가 가득 찬 상태에서 추가 로그가 들어오는 상황에 대한 별도의 로직을 만들지 않아 HTTP 요청은 모두 성공한 것 처럼 보였지만, 내부적으로는 수많은 로그가 조용히 버려지고 있었습니다.
[ 기존 로그 저장 기능 ]
@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();
}
}
}
현재 로그 저장 코드는 다음과 같습니다. 요청된 로그들을 바로 저장하는 것이 아닌, buffer 에 모아둔 뒤 1초 마다 비워주거나 10000 개의 로그가 쌓이면 MongoDB 에 한번에 insert 하는 방법 입니다.
public void saveBufferedBatch(String key, List<QueryLogRequest> requests) {
for (QueryLogRequest request : requests) {
QueryLog log = QueryLog.from(key, request);
buffer.offer(log);
}
}
여기서 buffer.offer 를 할때 이미 꽉 차있으면 그냥 버려지고 있었던 것 입니다.
🎯 저장 기능 개선
위 코드에서 발생할 수 있는 문제를 정리해보면 다음과 같습니다.
1. 버퍼 소비 속도 : flushBuffer() 가 1초마다 실행되기 때문에 많은 로그가 쌓일수록 MongoDB 저장 속도를 따라가지 못함.
2. 병렬처리 없음 : 하나의 쓰레드로 MongoDB 에 저장하다보니 저장 속도에 대해 병목 발생
3. 드롭된 로그 추적이 안됨 : offer() 실패시 로그가 유실되지만, 아무런 처리가 없음
이러한 문제점에 대해 개선한 코드는 아래와 같습니다.
[ 개선된 로그 저장 기능 ]
package com.snailcatch.server.domain.query_log.service;
import com.snailcatch.server.domain.query_log.dto.QueryLogRequest;
import com.snailcatch.server.domain.query_log.entity.QueryLog;
import jakarta.annotation.PostConstruct;
import lombok.RequiredArgsConstructor;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.data.mongodb.core.MongoTemplate;
import org.springframework.scheduling.annotation.Async;
import org.springframework.stereotype.Service;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.*;
@Service
@RequiredArgsConstructor
public class BufferedQueryLogService {
@Autowired
private MongoTemplate mongoTemplate;
private final BlockingQueue<QueryLog> buffer = new LinkedBlockingQueue<>(100_000);
private static final int BATCH_SIZE = 5000;
private static final int CONSUMER_COUNT = 36; // 병렬 Consumer 수
@PostConstruct
public void init() {
ExecutorService executor = Executors.newFixedThreadPool(CONSUMER_COUNT);
for (int i = 0; i < CONSUMER_COUNT; i++) {
executor.submit(this::consumeLogs);
}
}
private void consumeLogs() {
List<QueryLog> batch = new ArrayList<>(BATCH_SIZE);
while (true) {
try {
QueryLog log = buffer.take(); // 대기 (blocking) cpu 가 안 돌면서 대기함
batch.add(log);
buffer.drainTo(batch, BATCH_SIZE - 1); // take 한 거 외에 최대 BATCH_SIZE-1개 추가
if (!batch.isEmpty()) {
saveLogsAsync(new ArrayList<>(batch)); // 복사본 전달
batch.clear(); // 재사용
}
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
break;
} catch (Exception e) {
e.printStackTrace();
batch.clear(); // 에러 시 버리고 다시 시작
}
}
}
public void saveBufferedBatch(String key, List<QueryLogRequest> requests) {
for (QueryLogRequest request : requests) {
QueryLog log = QueryLog.from(key, request);
boolean added = buffer.offer(log);
if (!added) {
System.err.println("Buffer full, dropping log: " + log);
//todo 버려진 로그에 대한 처리
}
}
}
@Async("queryLogExecutor")
public void saveLogsAsync(List<QueryLog> logs) {
try {
mongoTemplate.insert(logs, QueryLog.class);
} catch (Exception e) {
System.err.println("Error saving logs: " + e.getMessage());
e.printStackTrace();
}
}
}
전체적인 흐름에서 쿼리 로그를 효율적으로 비동기 저장하기 위한 버퍼링 기능임은 동일 합니다.
가장 큰 수정 사항은, 버퍼의 저장 용량늘리고 병렬 스레드 를 추가 했습니다.
ExecutorService executor = Executors.newFixedThreadPool(CONSUMER_COUNT);
for (int i = 0; i < CONSUMER_COUNT; i++) {
executor.submit(this::consumeLogs);
}
버퍼 사이즈는 100,000 개로 기존의 용량보다 10배 증가시키고, MongoDB 데이터 삽입때 사용되는 병렬 스레드 수를 36개로 지정했습니다. ( 본인 컴퓨터 CPU 코어는 12개)
그리고 로그 저장 방식은 buffer.take() 로 로그를 하나 꺼내고 drainTo 로 BATCH_SIZE 만큼의 로그를 더 꺼냅니다. 최대 5000 건 단위로 저장 요청을 비동기로 수행합니다. 참고로 MongnDB 에 insert 할 수 있는 한 번의 요청 크기 제한 (wire protocol 기준)은 약 48MB 라고 합니다. 한개의 쿼리 객체는 약 60 bytes 정도라 이론상 800,000 개까지 한번에 insert 해도 되지만 병렬 스레드 수를 36개로 설정했기 때문에, 하나의 스레드가 MongoDB 에 일괄적으로 삽입하는 데이터를 넉넉하게 5000 개 정도로 잡아줬습니다.
그리고 버퍼가 가득 찼을때는 아직 별도의 처리는 하지 않고 콘솔 로그만 찍어주고 있습니다. (이후의 누락된 로그에 대한 처리 로직은 추가할 예정)
개선전 방식과 개선 된 방식에 대해 표로 정리하면 다음과 같습니다.
| 개선 전 | 개선 후 | 개선 이유 | |
| 버퍼 용량 | 10,000 | 100,000 | 더 많은 로그를 수용하기 위해 |
| 처리 쓰레드 수 | 1개 | 36개 병렬 처리 (적절한 코어수를 찾아야됨) | 로그 소비 속도 향상, 저장 병목 해소 |
| 저장 단위 | 1초마다 최대 1000건 | 로그 발생 시마다 최대 5000건 | 실시간성 향상 및 MongoDB I/O 효율 증가 |
| 유실 로그 처리 | 없음 | System.err.println + TODO | 문제 추적 |
🎯 개선된 기능에 대한 부하 테스트
적절한 버퍼 용량 구하기
버퍼의 크기가 너무 작으면 로그가 한번에 많이 몰렸을때 누락될 수 있습니다. (offer 실패), 반대로 너무 크면 메모리 사용량이 폭증해 JVM 메모리가 부족하거나 GC 가 많이 발생해 위험할 수 있습니다.
CPU 코어에 맞는 스레드 수 구하기
CONSUMER_COUNT (스레드 수) 가 너무 많으면 컨텍스트 스위치(문맥 전환) 비용이 증가하고, MongoDB 로 insert 작업을 하므로 동시에 너무 많은 쓰기 작업이 몰리면 MongoDB 에 부하가 발생할 수 있습니다. 즉 너무 많은 컨슈머로 DB 에 접근하면 오히려 TPS 가 떨어질 수 있습니다.
초기 코드에서는 버퍼 사이즈를 일단 100,000 정도로 설정했지만 부하 테스트 시나리오를 변경해가며, 위 두가지 기준으로 가장 합리적인 버퍼 용량과 컨슈머 수를 구했습니다. 그 결과 안정적으로 DB 에 로그가 저장되고 CPU 사용률과 JVM 메모리 지표들을 확인해 DB 저장에 사용될 스레드는 36 개, 버퍼 용량은 9,000,000 으로 결정했습니다.
테스트 시나리오
import http from 'k6/http';
import { sleep, check } from 'k6';
export const options = {
scenarios: {
find_max_log_throughput: {
executor: 'constant-arrival-rate',
rate: 500, // 초당 요청 수
timeUnit: '1s',
duration: '10s',
preAllocatedVUs: 200,
maxVUs: 1000,
},
},
thresholds: {
http_req_failed: ['rate<0.01'],
http_req_duration: ['p(95)<3000'],
},
};
export default function () {
const url = 'http://localhost:8080/api/query-logs';
const queries = Array.from({ length: 100 }, (_, i) => ({
methodName: `methodName${i}`,
sqlQuery: `SELECT * FROM table${i}`,
executionPlan: `executionPlan${i}`,
duration: Math.floor(Math.random() * 1000), // 0 ~ 999 랜덤 duration
}));
const payload = JSON.stringify(queries);
const params = {
headers: {
'Content-Type': 'application/json',
'X-API-KEY': 'c4db0348054449be9ee75da4e8d98729',
},
};
const res = http.post(url, payload, params);
check(res, {
'status is 200': (r) => r.status === 200,
});
}
1초에 500 번의 요청을 10초동안 보내는 시나리오 입니다. 이때 한건의 요청에는 100개의 쿼리 로그가 담겨져 있습니다. 계산해보면 1초에 약 50000(5만건) 의 로그 저장 요청을 보내는 부하 테스트 입니다.
K6 부하 테스트 결과
RPS 는 500, 평균 응답 시간은 9.15ms, p(90) 은 1.62ms 로 매우 빠른 속도로 응답됨을 확인할 수 있습니다.
JVM
CPU 사용률은 40 정도, 메모리 용량도 생각보다 나쁘지 않은것(?) 같습니다. 버퍼 용량을 9000000 으로 설정해 메모리가 부족하지 않을까 걱정했는데 생각보다 널널했습니다.
찾아보니 현재 JVM 에 할당된 최대 힙 메모리는 약 2GB 고, 하나의 로그 객체는 56 bytes 정도 입니다. 대 ~ 충 계산해보면 버퍼 용량이 9000000 일때 504MB 정도를 할당하니 2GB 의 23% 를 차지 합니다. (하지만 이 역시 배포 환경에서 할당된 힙 메모리가 달라질 수 있어 서비스를 운영할때 다시 한번 테스트 하긴 해야 될듯)
마지막으로 누락된 로그가 있는지 확인해본 결과 정확하게 요청된 수 만큼의 로그가 MongoDB 에 잘 저장됨을 확인했습니다. 뭔가 정확한 수치를 보면서 개선하니까 어디를 수정해야 하고 병목 지점을 찾기 쉬운거 같네염