Database Internals

운영 중인 MySQL 서버의 long_query_time이 0초로 잘못 설정되어 있어서 굉장히 많은 수의 슬로우 쿼리가 로깅되고 있는 상황이라고 가정해보자. 거기에다가 QPS는 100만 이상이다. 쿼리가 점점 적체 및 지연되기 시작할 것이고, 디스크 사용량이 증가하게 될 것이다. 그리고 대부분은 그 이유의 주된 원인으로 로깅 작업에 의한 CPU 사용율과 Disk I/O 증가를 꼽을 것이다. 그런데 사실 로깅 작업은 로그를 기록하는 정도이기 때문에 생각만큼 DB 성능에 큰 영향을 끼치진 않는다.

그러면 슬로우 쿼리 로깅이 DB 성능에 영향을 끼치는 좀 더 명확한 원인이 있을까?

슬로우 쿼리가 기록되는 시점

Q. 슬로우 쿼리는 언제 기록될까?

• A1. SQL 문장 실행 시작 단계
• A2. SQL 문장 실행이 끝나고, 결과를 클라이언트에게 보내기 전
• A3. SQL 문장 실행이 끝나고, 결과를 클라이언트에게 보낸 후

슬로우 쿼리는 SQL 문장 실행이 끝나고, 결과를 클라이언트에게 보낸 후에 기록된다.

Q. 실행 오류가 발생한 SQL 문장은 슬로우 쿼리로 기록될까?

• A1. 기록된다
• A2. 기록되지 않는다.

오류 유형에 따라 다르지만 실행 오류가 발생해도 슬로우 쿼리로 기록된다.

두 질문의 핵심은 오류가 발생해도 슬로우 쿼리가 로그에 기록된다는 점이다. SQL 문장 실행이 끝나고, 결과를 클라이언트로 보낸 후에 기록되는 것이 기본적인 슬로우 쿼리 로깅 과정인데, 이 과정에서 실행 오류가 발생해도 슬로우 쿼리가 로깅되는 것이다.

그러면 어떤 오류가 발생하면 슬로우 쿼리에 로깅되는 것일까? 대표적인 몇 가지 오류 케이스를 살펴보도록 하자.
(오류 케이스는 로깅 여부를 확인하는 과정이기 때문에 자세한 설명은 생략한다.)

1. 중복 키 오류

mysql> CREATE TABLE `test` (
  `id` int NOT NULL AUTO_INCREMENT,
  `name` varchar(100) DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci

mysql> INSERT INTO test SELECT 1, 'test', NOW();

mysql> SELECT * FROM test
+----+------+---------------------+
| id | name | updated_at          |
+----+------+---------------------+
|  1 | test | 2025-12-02 23:08:39 |
+----+------+---------------------+

-- 로깅 조건을 0초로 설정
mysql> SET long_query_time = 0;

-- 중복 키 오류 발생
mysql> INSERT INTO test SELECT 1, 'test', NOW();
ERROR 1062 (23000): Duplicate entry '1' for key 'test.PRIMARY'

쿼리 실행 과정 중에 중복 키 오류가 발생했지만 슬로우 쿼리 로그에 INSERT 문장이 기록되어 있는 것을 확인할 수 있다.

# Time: 2025-12-02T14:47:03.185812Z
# User@Host: root[root] @ localhost []  Id:    12
# Query_time: 0.000242  Lock_time: 0.000003 Rows_sent: 0  Rows_examined: 1
SET timestamp=1764686823;
insert into test select 1, 'test', now();

2. 잠금 시간 초과 오류

레코드 잠금 대기시간을 초과해서 실행 오류가 발생했지만 슬로우 쿼리 로그에 세션 2의 INSERT 문장이 기록되어 있는 것을 확인할 수 있다.

# Time: 2025-12-02T14:58:59.892387Z
# User@Host: root[root] @ localhost []  Id:    13
# Query_time: 1.000319  Lock_time: 1.000116 Rows_sent: 0  Rows_examined: 1
SET timestamp=1764687538;
insert into test select 2, 'test', now();

3. 데드락 오류

mysql> SELECT * FROM test;
+----+------+---------------------+
| id | name | updated_at          |
+----+------+---------------------+
|  1 | test | 2025-12-02 23:08:39 |
|  2 | test | 2025-12-03 00:06:40 |
+----+------+---------------------+
mysql> SET GLOBAL innodb_lock_wait_timeout = 10; -- 레코드 잠금 시간 10초로 설정
mysql> SET GLOBAL long_query_time = 0; -- 슬로우 쿼리 로깅 대기 시간을 0초로 설정

데드락 오류가 발생했지만 슬로우 쿼리 로그에 세션 2의 UPDATE 문장이 기록되어 있는 것을 확인할 수 있다.

# Time: 2025-12-04T04:05:27.296433Z
# User@Host: service[service] @ localhost [127.0.0.1]  Id:    23
# Query_time: 0.001525  Lock_time: 0.000124 Rows_sent: 0  Rows_examined: 0
SET timestamp=1764821127;
UPDATE test SET id=6 WHERE id=1;

몇 가지 오류 케이스에서 알 수 있듯이 MySQL 서버는 쿼리 정상 처리 여부와 관계없이 오류가 발생해도 슬로우 쿼리를 로깅한다.

그림 1에서 보는 바와 같이 클라이언트는 MySQL 서버와 TCP 핸드셰이크를 통해 연결을 맺고 인증 과정을 거쳐 ① 쿼리를 요청하고, MySQL 서버는 파싱 과정을 거쳐 ② 쿼리를 수행한다. 이 때 중복키 오류, 잠금 대기시간 초과, 데드락 오류 등이 발생하면 MySQL 서버는 클라이언트에게 ③ 오류 패킷을 전송하며, 전송이 끝나고 나면 그제서야 ④⑤ 슬로우 쿼리 로깅을 실행한다.

다만, 슬로우 쿼리에 로깅되지 않는 오류도 존재한다.

• 트리거, 스토어드 프로시저, 함수, 이벤트 스케줄러가 실행하는 내부 SELECT/DML 등의 쿼리는 슬로우 로그에서 제외된다.
• kill <thread_id> 또는 kill connection <thread_id> 명령으로 스레드가 kill 요청을 받은 경우 쿼리 수행 시간이 long_query_time을 초과했어도 슬로우 로그에 기록되지 않는다.
• SELECT a 또는 SELECT FROM table 명령 수행과 같은 단순 파싱 오류는 슬로우 로그에 기록되지 않는다.

이는 슬로우 쿼리 여부를 판단하는 sql/log.cc/log_slow_applicable() 함수에 명확하게 작성되어 있다.

// false인 경우 슬로우 로그에 기록 안함
bool log_slow_applicable(THD *thd) {
  ...
  // 내부 SELECT/DML 등의 쿼리는 제외
  if (unlikely(thd->in_sub_stmt)) return false;  // Don't set time for sub stmt

  // kill 요청을 받은 경우 제외
  if (unlikely(thd->killed == THD::KILL_CONNECTION)) return false;

  // 파싱 오류 제외
  if (unlikely(thd->is_error()) &&
      (unlikely(thd->get_stmt_da()->mysql_errno() == ER_PARSE_ERROR)))
    return false;
  ...

자매품으로 제너럴 로그는 MySQL 서버가 클라이언트의 쿼리 요청을 받고나서 파싱 전에 기록한다.

다시 처음 질문으로 돌아가서, 슬로우 쿼리 로깅이 DB 성능에 영향을 끼치는 좀 더 근본적인 이유는 무엇일까?

로깅으로 인해 쿼리가 적체되고 지연되는 이유

다시 한 번 언급하자면 슬로우 쿼리와 제너럴 쿼리 로깅 작업은 CPU와 Disk I/O 리소스를 사용하지만 사실 로그를 기록하는 정도이기 때문에 생각만큼 DB 성능에 큰 영향을 끼치진 않는다.

MySQL 서버의 스레딩 모델을 떠올려보자. 클라이언트 하나가 오면 그 클라이언트와 1대1로 대응하는 서버 측 스레드가 하나 생성된다. TCP 핸드셰이크를 맺고, 클라이언트가 첫 번째 요청을 보내고 결과를 받는다. 슬로우 쿼리의 경우 MySQL 서버는 클라이언트에게 결과를 반환한 뒤에야 슬로우 쿼리 로그를 기록하기 시작한다.

이제 성능 이야기를 해보자. 클라이언트의 초당 QPS가 굉장히 높거나, 벤치마크용 클라이언트라면 쿼리 결과를 받자마자 다음 요청을 보내게 된다. 이 때 다음 요청은 이전 요청을 처리했던 스레드가 처리할까? 아니면 다른 스레드가 처리할까? 당연히 이전 요청을 처리했던 스레드가 처리한다.

이유는 아직 트랜잭션 중일 수 있기 때문이다. 트랜잭션 상태, 세션 변수, 연결 소켓, 타이머/잠금 시간 등 해당 세션에 필요한 모든 상태를 THD 컨텍스트 안에 담아두고 있기 때문에 다른 스레드로 바꿀 수가 없다. 그래서 이전에 요청을 처리하던 스레드가 계속 처리하게 되는 것이다.

그림 3과 같이 슬로우 쿼리를 로깅하고 있는 세션 스레드는 메인 루프를 한 바퀴 돌 때까지 클라이언트가 요청한 다음 패킷을 읽지 않는다. 즉 소켓 수신 버퍼가 비워질 때까지 클라이언트 요청은 대기하게 된다.

로깅으로 인해 쿼리가 적체되고 지연되는 이유는 클라이언트가 쿼리 결과를 받자마자 다음 요청을 바로 보낼 때, 해당 세션 스레드가 이전 요청에 대한 슬로우 쿼리를 아직 로깅하고 있기 때문이다. 슬로우 쿼리 로그와 제너럴 로그로 인해 발생할 수 있는 성능 문제는 단순히 CPU와 Disk I/O 문제라기보다는 세션 스레드의 로깅 작업을 기다리는 쿼리 지연에 존재한다는 것이다.