배경
MVP 개발 단계에서는 일단 돌아가게를 목표로 빠르게 개발을 진행했다. JPA의 유명한 N+1 문제가 있다는 걸 알면서도 의도적으로 미뤘다. 일단 빠르게 개발해서 기능이 돌아가는게 우선이라고 생각했다.
그런데 막상 N+1을 잡으려고 하니 문제가 생겼다. 어떤 API에서 발생하는지 알 수가 없었다. 코드를 하나하나 뜯어보자니 범위가 너무 넓었고, show_sql로 로그를 켜봐도 가독성이 그렇게 좋다고 생각하지 않았다.
요청 단위로 쿼리가 몇 번 나가는지 알 수 있다면?
그래서 직접 구현해보기로 했다.
해결방법
총 3가지를 중심으로 개발했다.
ThreadLocal - 스프링은 HTTP 요청당 스레드가 생성되고, 각 스레드의 임시 저장소 역할을 하는 저장소다.
StatementInspector — Hibernate가 SQL을 실행하기 직전에 호출하는 훅이다. 여기서 실행되는 쿼리를 가로채 카운트할 수 있다.
(StatementInspector는 Hibernate에 종속적이라 네이티브 쿼리는 감지하지 못한다. Feel-Archive 프로젝트에 nativeQuery = true를 사용하는 곳이 없었기 때문에 이 방식으로도 충분히 감지 가능하다고 판단)
HandlerInterceptor — HTTP 요청의 시작과 끝에 끼어드는 Spring MVC 인터셉터다. 요청이 시작될 때 카운터를 초기화하고, 요청이 끝날 때 집계 결과를 확인할 수 있다.
쿼리 수치값을 저장하는 객체
public class QueryMetrics {
private final Map<String, Integer> sqlQueryCounts = new ConcurrentHashMap<>();
private final long startTime = System.currentTimeMillis();
public void appendQuery(String sql) {
sqlQueryCounts.merge(sql, 1, Integer::sum);
}
public Map<String, Integer> getSqlQueryCounts() {
return sqlQueryCounts;
}
public long getStartTime() {
return startTime;
}
}
쿼리 수치값 객체를 관리하는 매니저
public class QueryMetricsManager {
private final ThreadLocal<QueryMetrics> threadLocal = new ThreadLocal<>();
public void start() {
threadLocal.set(new QueryMetrics());
}
public QueryMetrics getCurrentMetrics() {
return threadLocal.get();
}
public void clear() {
threadLocal.remove();
}
}스레드 로컬을 사용한 이유 :
JPA 쿼리 실행 전 실행되는 훅 StatementInspector
@Component
@Profile("!prod")
public class JpaInspector implements StatementInspector {
private final QueryMetricsManager queryMetricsManager;
public JpaInspector(QueryMetricsManager queryMetricsManager) {
this.queryMetricsManager = queryMetricsManager;
}
@Override
public String inspect(String sql) {
QueryMetrics metrics = queryMetricsManager.getCurrentMetrics();
if (metrics != null && sql.toLowerCase().startsWith("select")) {
metrics.appendQuery(sql);
}
return sql;
}
}쿼리를 실행할 때마다 select 쿼리를 카운트하여 append
@Slf4j
@Component
@Profile("!prod")
public class NPlusOneInterceptor implements HandlerInterceptor {
private static final int N_PLUS_ONE_THRESHOLD = 2; // 동일 쿼리 2회 이상이면 의심
private final QueryMetricsManager queryMetricsManager;
public NPlusOneInterceptor(QueryMetricsManager queryMetricsManager) {
this.queryMetricsManager = queryMetricsManager;
}
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
throws Exception {
queryMetricsManager.start();
return true;
}
@Override
public void afterCompletion(HttpServletRequest request,
HttpServletResponse response,
Object handler, @Nullable Exception ex) throws Exception
{
try {
QueryMetrics metrics = queryMetricsManager.getCurrentMetrics();
if (metrics == null) return;
long duration = System.currentTimeMillis() - metrics.getStartTime();
Map<String, Integer> counts = metrics.getSqlQueryCounts();
boolean suspicious = counts.values().stream()
.anyMatch(count -> count >= N_PLUS_ONE_THRESHOLD);
if (suspicious) {
int total = counts.values().stream().mapToInt(Integer::intValue).sum();
log.warn("[N+1 의심] 총 {}ms | 쿼리 {}회 | URI: {}", duration, total, request.getRequestURI());
counts.forEach((sql, count) -> {
if (count >= N_PLUS_ONE_THRESHOLD) {
log.warn(" → [{}회] {}", count, sql.trim());
}
});
}
} finally {
queryMetricsManager.clear();
}
}
}HTTP 요청이 오면 쿼리 집계 start하고 요청이 끝났을 때, 동일한 쿼리 구조(파라미터만 다른)가 N번 반복되는 것을 N+1로 감지한다. Hibernate는 파라미터를 ?로 처리하기 때문에 users where id=1, users where id=2는 동일 쿼리로 집계된다.
실제 테스트
Feel-Archive는 메인 화면에 진입 했을 때를 테스트를 진행했다.
2026-03-02T17:56:59.192+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
2026-03-02T17:56:59.192+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-3] p6spy :
2026-03-02T17:56:59.192+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-4] p6spy :
2026-03-02T17:56:59.192+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-2] p6spy :
2026-03-02T17:56:59.192+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-6] p6spy :
2026-03-02T17:56:59.210+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-2] p6spy :
[Query] statement | 2ms
select n1_0.id,n1_0.content,n1_0.created_at,n1_0.is_read,n1_0.read_at,n1_0.related_id,n1_0.title,n1_0.notification_type,n1_0.user_id from notification n1_0 where n1_0.is_read=false and n1_0.user_id=6 limit 0,20
2026-03-02T17:56:59.214+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-2] p6spy :
2026-03-02T17:56:59.225+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
[Query] statement | 9ms
select a1_0.id,a1_0.content,a1_0.created_at,a1_0.deleted_at,a1_0.emotion,a1_0.like_count,a1_0.latitude,a1_0.location_label,a1_0.longitude,a1_0.location,a1_0.scrap_count,a1_0.updated_at,a1_0.user_id,a1_0.visibility from archive a1_0 where (a1_0.deleted_at IS NULL) and st_distance_sphere(a1_0.location,st_geomfromtext('POINT(37.853046 127.742840)',4326))<=50.0 order by st_distance_sphere(a1_0.location,st_geomfromtext('POINT(37.853046 127.742840)',4326)) limit 10
2026-03-02T17:56:59.234+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
[Query] statement | 0ms
select al1_0.archive_id from archive_like al1_0 where al1_0.user_id=6 and al1_0.archive_id in (2041,2056,2057)
2026-03-02T17:56:59.239+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
[Query] statement | 1ms
select as1_0.archive_id from archive_scrap as1_0 where as1_0.user_id=6 and as1_0.archive_id in (2041,2056,2057)
2026-03-02T17:56:59.241+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
[Query] statement | 0ms
select u1_0.id,u1_0.birth_date,u1_0.created_at,u1_0.email,u1_0.email_notification_enabled,u1_0.gender,u1_0.name,u1_0.nickname,u1_0.password,u1_0.phone,u1_0.role,u1_0.status,u1_0.updated_at from users u1_0 where u1_0.id=3 and (u1_0.status = 'ACTIVE')
2026-03-02T17:56:59.242+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
[Query] statement | 0ms
select u1_0.id,u1_0.birth_date,u1_0.created_at,u1_0.email,u1_0.email_notification_enabled,u1_0.gender,u1_0.name,u1_0.nickname,u1_0.password,u1_0.phone,u1_0.role,u1_0.status,u1_0.updated_at from users u1_0 where u1_0.id=6 and (u1_0.status = 'ACTIVE')
2026-03-02T17:56:59.243+09:00 INFO 84187 --- [rest-api] [nio-8080-exec-7] p6spy :
2026-03-02T17:56:59.245+09:00 WARN 84187 --- [rest-api] [nio-8080-exec-7] c.f.api.utils.NPlusOneInterceptor : [N+1 의심] 총 47ms | 쿼리 5회 | URI: /api/v1/archives/nearby
2026-03-02T17:56:59.245+09:00 WARN 84187 --- [rest-api] [nio-8080-exec-7] c.f.api.utils.NPlusOneInterceptor : → [2회] select u1_0.id,u1_0.birth_date,u1_0.created_at,u1_0.email,u1_0.email_notification_enabled,u1_0.gender,u1_0.name,u1_0.nickname,u1_0.password,u1_0.phone,u1_0.role,u1_0.status,u1_0.updated_at from users u1_0 where u1_0.id=? and (u1_0.status = 'ACTIVE')
2026-03-02T17:57:00.017+09:00 INFO 84187 --- [rest-api] [ scheduling-1] p6spy :
[Query] statement | 6ms
select tc1_0.id,tc1_0.status,tc1_0.content,tc1_0.created_at,tc1_0.deleted_at,tc1_0.emotion,tc1_0.is_notification_sent,tc1_0.latitude,tc1_0.location_label,tc1_0.longitude,tc1_0.open_at,tc1_0.updated_at,tc1_0.user_id from time_capsule tc1_0 where (tc1_0.deleted_at IS NULL) and tc1_0.status='LOCKED' and tc1_0.open_at<='2026-03-02T17:57:00.001+0900' limit 501
2026-03-02T17:57:00.021+09:00 INFO 84187 --- [rest-api] [ scheduling-1] p6spy실제 찍힌 로그를 조금 보기좋게 정리하면,
[JWT 인증]
[Query] statement | 4ms
select * from users where id=6 and status='ACTIVE'
──────────────────────────────────────────
[Request] GET /api/v1/archives/nearby
──────────────────────────────────────────
[Query] statement | 9ms
select * from archive
where st_distance_sphere(location, st_geomfromtext('POINT(37.853046 127.742840)', 4326)) <= 50.0
order by st_distance_sphere(...) limit 10
[Query] statement | 0ms
select archive_id from archive_like
where user_id=6 and archive_id in (2041, 2056, 2057)
[Query] statement | 1ms
select archive_id from archive_scrap
where user_id=6 and archive_id in (2041, 2056, 2057)
[Query] statement | 0ms ← 작성자 조회 1번째
select * from users where id=3 and status='ACTIVE'
[Query] statement | 0ms ← 작성자 조회 2번째 (N+1 발생!)
select * from users where id=6 and status='ACTIVE'
──────────────────────────────────────────
[WARN] N+1 의심 | 총 47ms | 쿼리 5회 | URI: /api/v1/archives/nearby
→ [2회] select * from users where id=? and status='ACTIVE'
──────────────────────────────────────────테스트 했던 화면을 캡쳐하지는 못해서 쉽게 상상하실 수 있게 Feel-Archive의 메인화면이다.
여기서 JWT 인증할 때 User 조회해서 영속성 컨텍스트에 저장되는거 아니에요? 라고 생각할 수 있는데 그렇지 않다.
JWT 인증은 Spring Security 필터 레이어에서 처리되는데, 필터는 Spring의 트랜잭션 밖에 있다. 영속성 컨텍스트는 트랜잭션 단위로 생성되기 때문에, 필터에서 조회한 User는 이후 서비스 메서드의 영속성 컨텍스트와 공유되지 않는다.
나간 쿼리를 보면 총 5개의 쿼리가 나갔는데 아카이브 글은 3개가 조회가 되었고 User는 2번 조회가 되었다.
User가 2번 조회된 이유는 한 유저가 아카이브글을 2개 적었기 때문에 2개만 조회된 것이다.
이 쿼리 로그를 보고 아 아카이브 조회할때마다 아카이브 글 작성자를 조회하는 쿼리가 또 나가는구나를 알게되었고, 아카이브 조회 시 User를 fetchJoin하도록 하여 N+1 문제를 해결했고, 해결한 다음에 찍힌 로그는 다음과 같다.
[JWT 인증]
[Query] statement | 5ms
select * from users where id=6 and status='ACTIVE'
──────────────────────────────────────────
[Request] GET /api/v1/archives/nearby
──────────────────────────────────────────
[Query] statement | 27ms ← archive + user 한번에 조회
select * from archive a
join users u on u.id = a.user_id and status='ACTIVE'
where st_distance_sphere(location, st_geomfromtext('POINT(37.853308 127.743064)', 4326)) <= 50.0
order by st_distance_sphere(...) limit 10
[Query] statement | 1ms
select archive_id from archive_like
where user_id=6 and archive_id in (2041, 2057, 2056)
[Query] statement | 1ms
select archive_id from archive_scrap
where user_id=6 and archive_id in (2041, 2057, 2056)
──────────────────────────────────────────
N+1 WARN 로그 없음
──────────────────────────────────────────
아카이브 조회 시 Join을 통해 User도 함께 가져오기때문에 N+1 발생 문제를 해결했다.
느낀점
개인 프로젝트라 규모가 작아서 N+1이 크게 체감되지 않았지만, 실제 서비스였다면 얘기가 달랐을 것이다. 수십 개의 API에서 N+1이 숨어있다면 코드를 하나하나 뜯어보는 건 현실적으로 불가능하다. 이런 감지 시스템이 있다면 어떤 API 요청에서 문제가 발생하는지 로그만 봐도 바로 파악할 수 있으니 유용할것같다..
'Feel-Archive' 카테고리의 다른 글
| [Feel-Archive] 스케줄러 블로킹을 해결하기 위한 비동기 처리 - 타임캡슐 알림 개발 (1) (0) | 2026.03.18 |
|---|---|
| [Feel-Archive] 성능 테스트(1) - 1GB 메모리에서 모니터링 구축하기 (0) | 2026.03.12 |
| [Feel-Archive] 타임캡슐 알림이 9시간 늦게 온다 (0) | 2026.03.08 |
