06 · Logging & Profiling — 발사되는 SQL을 보는 법

이 문서가 답하는 질문: TypeORM이 어떤 SQL을 언제 발사하는지 어떻게 보는가? 느린 쿼리만 골라낼 수 있는가? EXPLAIN을 어떻게 끼우는가? 한 줄 답: “logging: ['query', 'slow', 'error']와 maxQueryExecutionTime 두 줄이 모든 TypeORM 디버깅의 출발점이다 — 이걸 안 켜고 성능을 추측하는 건 안대를 쓰고 운전하는 것과 같다.”

Why — 왜 로깅이 첫 번째인가

N+1, 카르테시안, 캐시 stale — 모든 TypeORM 성능 문제의 첫 번째 증상은 *“왜 느린지 모르겠다”*이다. 코드를 아무리 들여다봐도 find({ relations: { ... } }) 한 줄이 내부적으로 어떤 SQL을 발사하는지 보이지 않기 때문이다.

해결은 단순하다 — 발사되는 SQL을 출력시킨다. TypeORM은 이를 DataSource 옵션 한 줄로 제공한다.

핵심 주장:

모든 최적화는 측정에서 시작한다.
logging 옵션은 개발용과 프로덕션 slow query 추적용을 같은 인터페이스로 제공한다.
EXPLAIN은 TypeORM 외부에서 끼우는 게 깔끔하다.

How — 로깅 옵션 전수

가장 짧은 한 줄

const dataSource = new DataSource({
  // ...
  logging: true,        // ← 모든 쿼리 콘솔 출력
});

이게 개발에서 가장 자주 켜는 형태. 모든 SQL이 console에 찍힌다.

레벨별 분리

const dataSource = new DataSource({
  logging: ['query', 'error', 'schema', 'warn', 'info', 'log', 'migration'],
});

레벨	의미
`'query'`	모든 SQL 쿼리
`'error'`	에러난 쿼리
`'schema'`	DDL (CREATE/ALTER) — synchronize·migration
`'warn'`	경고 (예: 인덱스 누락)
`'info'`	일반 정보
`'log'`	디버그
`'migration'`	마이그레이션 실행
`true`	모든 것
`false`	끔

느린 쿼리만 — `maxQueryExecutionTime`

프로덕션에서 모든 쿼리를 찍으면 로그가 죽는다. 대신:

const dataSource = new DataSource({
  logging: ['error'],
  maxQueryExecutionTime: 1000,   // ← 1초 넘는 쿼리만 warn
});

[WARN] query is slow: SELECT post.* ... (took 1234ms)

이게 프로덕션의 sane default다 — 에러 + 느린 쿼리만 골라낸다.

Mermaid — 환경별 로깅 전략

What — 커스텀 Logger와 외부 APM

커스텀 Logger 클래스

import { Logger, QueryRunner } from 'typeorm';
 
class ProductionLogger implements Logger {
  logQuery(query: string, parameters?: any[], runner?: QueryRunner) {
    // 모든 쿼리 — 보통 안 출력
  }
 
  logQueryError(error: string | Error, query: string, parameters?: any[]) {
    console.error({ error, query, parameters });
    sentry.captureException(error, { extra: { query, parameters } });
  }
 
  logQuerySlow(time: number, query: string, parameters?: any[]) {
    console.warn({ slow_query_ms: time, query, parameters });
    metrics.histogram('db.slow_query', time, { query: normalize(query) });
  }
 
  logSchemaBuild(message: string) {}
  logMigration(message: string) {}
  log(level: 'log' | 'info' | 'warn', message: any) {}
}
 
const dataSource = new DataSource({
  // ...
  logger: new ProductionLogger(),
  maxQueryExecutionTime: 500,
});

이게 Sentry/Datadog/New Relic에 느린 쿼리를 자동 전송하는 정석.

내장 logger 종류

logger: 'advanced-console',  // 기본 — 컬러 + 정렬
logger: 'simple-console',    // 단순 console.log
logger: 'file',              // ormlogs.log 파일
logger: 'debug',             // debug 패키지 사용 (DEBUG=typeorm:* env)

'file'은 디스크가 차는 위험이 있으니 프로덕션은 custom logger가 안전하다.

EXPLAIN 통합

단발 EXPLAIN

const result = await dataSource.query(
  'EXPLAIN ANALYZE SELECT * FROM post LEFT JOIN comment ON ... WHERE post.id = $1',
  [1],
);
console.log(result);

QueryBuilder에서 SQL 추출 → EXPLAIN

const qb = postRepo
  .createQueryBuilder('post')
  .leftJoinAndSelect('post.comments', 'comment')
  .where('post.published = :p', { p: true });
 
const [sql, params] = qb.getQueryAndParameters();
const plan = await dataSource.query(`EXPLAIN ANALYZE ${sql}`, params);
console.table(plan);

이게 카르테시안 폭발을 눈으로 확인하는 길 — Hash Join이 몇 행을 펼치는지가 actual rows에 나온다.

pg_stat_statements (PostgreSQL)

-- 한 번 활성화
CREATE EXTENSION pg_stat_statements;
 
-- 가장 느린 쿼리 top 10
SELECT query, calls, mean_exec_time, total_exec_time
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 10;

TypeORM 바깥에서 보는 가장 강력한 도구. 어플리케이션이 어떤 쿼리에 시간을 가장 많이 쓰는지를 DB 입장에서 보여준다.

실전 디버깅 체크리스트

의심: “이 API가 느리다”

로깅 켠다: logging: ['query', 'error'], maxQueryExecutionTime: 100
API 한 번 호출 → 로그를 본다
SQL이 몇 번 발사됐나? → N+1 의심
한 쿼리가 느리면 → EXPLAIN으로 plan 본다
plan에 Seq Scan? → 인덱스 누락
plan에 Hash Join + 큰 actual rows? → 카르테시안

비교 매트릭스 — 증상 → 도구

증상	도구	어디서
한 요청에 SQL 50번 발사	`logging: ['query']`	DataSource
같은 쿼리가 분당 1000번	pg_stat_statements	DB
쿼리 하나가 5초	`maxQueryExecutionTime` + EXPLAIN	DataSource + DB
메모리 사용량 폭증	Node heap snapshot	OS
DB CPU 100%	pg_stat_statements + EXPLAIN	DB
같은 row가 캐시 hit 안 됨	Redis MONITOR	Redis

What-if — 잘못된 해석들

오해 1 — “로깅은 성능에 부담이다”

maxQueryExecutionTime로 느린 것만 찍으면 부담 거의 없다. 모든 쿼리를 찍는 것은 개발에서만.

오해 2 — “EXPLAIN ANALYZE는 위험하다”

EXPLAIN(without ANALYZE)는 실제 실행 안 함 — 항상 안전. ANALYZE는 실제 실행하므로 UPDATE/DELETE에는 위험하다. SELECT는 OK.

오해 3 — “Seq Scan은 항상 나쁘다”

작은 테이블(< 1000행)은 Seq Scan이 더 빠르다 — DB planner의 옳은 결정. 대형 테이블에서 Seq Scan만 문제.

오해 4 — “TypeORM 로그가 SQL을 보여주면 끝이다”

TypeORM 로그는 SQL 텍스트를 보여주지만 바인딩된 파라미터는 별도다. [1, 'hello'] 같은 배열이 쿼리와 분리되어 출력된다 — DB에 복사 붙여넣기할 때 수동으로 합쳐야 한다.

Insight — 한 단락 이야기

“성능 문제는 추측이 아니라 측정에서 시작한다”

1974년 Donald Knuth가 *“premature optimization is the root of all evil”*을 말한 이유 — 측정 없이 어디가 느린지 추측하는 습관이 대부분의 잘못된 최적화의 원인이라는 관찰이었다. 그 인용의 생략된 앞부분은 “We should forget about small efficiencies, say about 97% of the time” — 3%는 측정해서 최적화하라는 뜻이다. TypeORM의 logging: true는 그 측정의 가장 짧은 한 줄이다. 5분이면 어디서 SQL이 발사되고 있는지가 전부 보인다. 그런데 이걸 안 켜고 “이 API가 왜 느리지?”를 코드 읽으며 추측하는 팀이 대다수다. 측정 없는 최적화는 대부분 효과가 없고, 효과 있는 자리는 측정만 켜도 즉시 보인다. “무엇이 발사되고 있는가”를 보는 한 줄이 모든 ORM 디버깅의 출발점이다.

요약 + Mermaid

핵심 키	값
개발 표준	`logging: true` (모든 SQL)
프로덕션 표준	`logging: ['error']` + `maxQueryExecutionTime: 1000`
커스텀 Logger	Sentry/Datadog 통합 자리
EXPLAIN 추출	`qb.getQueryAndParameters()` + `dataSource.query`
DB 입장의 도구	pg_stat_statements (PostgreSQL)
첫 번째 디버깅 단계	로그를 켜는 것

한 줄 결론 — 측정 없는 최적화는 추측이다. TypeORM은 로깅 한 줄로 모든 SQL을 보여주고, maxQueryExecutionTime으로 프로덕션에서도 부담 없이 느린 쿼리를 추적한다. 이 챕터 전체의 도구들은 로깅을 켠 다음에야 의미가 생긴다.

이 챕터 전체 요약 — TypeORM의 N+1은 기본값이고, relations(02) / leftJoinAndSelect(03) / cache(04) / loadRelationCountAndMap(05)이 그것을 끄는 네 도구이며, 이 모든 결정의 출발점은 logging(06)이다. 다음 챕터(08-theory-and-alternatives)는 Prisma와 Drizzle이 같은 문제를 어떻게 다른 추상으로 푸는지를 본다.

05-batching-and-loadRelationCountAndMap 📖 개요