MySQL Replica는 왜 Binlog를 Relay log에 먼저 쌓을까?

Q: MySQL Replica는 왜 Binlog를 Relay log에 먼저 쌓을까?

Replica는 받은 이벤트를 Relay log에 먼저 적고 적용은 따로 하므로, 적용을 30초 막자 받은 위치만 앞서 나가며 Relay log가 파일 23개, 96767바이트로 쌓였다.

이번 시간에는 MySQL Replica의 Relay log 파일을 직접 열어 보고, 적용이 막혔을 때 Relay log가 어떻게 쌓이는지, 언제 지워지는지 확인하며 배워가는 시간입니다.

먼저 말부터 맞춰 볼게요. MySQL 복제에서 변경을 내보내는 서버를 Source, 그 변경을 받아 따라 하는 서버를 Replica라고 불러요. Source가 남기는 변경 기록은 Binlog라고 합니다.

그런데 Replica는 Source에서 Binlog 이벤트를 받자마자 자기 데이터에 적용하지 않아요. 받은 이벤트를 먼저 자기 디스크의 파일에 적어 두고, 적용은 그 파일을 읽어서 따로 합니다. 이 파일이 Relay log예요.

Replica 안에서는 Source에서 이벤트를 받아 Relay log에 쓰는 I/O 스레드와, Relay log를 읽어 적용하는 SQL 스레드가 따로 돌아요. 그래서 SQL 스레드만 멈추면 받은 위치만 앞서 나갑니다.

Binlog 이벤트가 더 궁금하면 Binlog를 다룬 글을 참고하세요.

실습 준비

이 글의 명령은 모두 실습 코드의 mysql-relay-log/ 디렉터리에서 실행합니다.

compose.yaml: MySQL 8.4 Source와 Replica 두 컨테이너 정의
setup.sql: Source에 복제용 계정과 shop.orders 테이블을 만드는 SQL

Docker Compose로 MySQL 8.4 두 대를 띄워서 Source와 Replica로 연결할게요. compose.yaml은 이렇습니다.

services:
  source:
    image: mysql:8.4
    command: --server-id=1 --gtid-mode=ON --enforce-gtid-consistency=ON
    environment:
      MYSQL_ROOT_PASSWORD: root
    ports:
      - "3411:3306"

  replica:
    image: mysql:8.4
    command: --server-id=2 --gtid-mode=ON --enforce-gtid-consistency=ON --relay-log=relay-bin
    environment:
      MYSQL_ROOT_PASSWORD: root
    ports:
      - "3412:3306"

Replica에는 --relay-log=relay-bin을 주어 Relay log 파일 이름을 고정해 두었어요. relay_log를 지정하지 않으면 파일 이름은 호스트이름-relay-bin.000001 형식이 되는데, Docker에서는 컨테이너 ID가 호스트 이름이라 컨테이너를 다시 만들 때마다 이름이 바뀌거든요.

공식 문서는 호스트 이름이 바뀌면 Replica가 기존 Relay log를 찾지 못해 Failed to open the relay log 같은 오류로 복제가 멈출 수 있다고 안내해요.

setup.sql은 Source에 복제용 계정 repl과 shop 데이터베이스를 만들고, orders(id 자동 증가, item, qty) 테이블을 만들어요.

이제 Source와 Replica에 접속하는 셸 함수(src, rep)를 만들고, Replica를 Source에 연결해 주세요. MYSQL_PWD 환경 변수로 비밀번호를 넘기는 방식은 실습에서만 쓰셔야 해요.

Replica에서 먼저 실행하는 RESET BINARY LOGS AND GTIDS는 무엇을 할까요? 컨테이너가 처음 뜰 때 Replica가 스스로 남긴 GTID(트랜잭션마다 붙는, 서버 UUID와 번호로 된 고유 ID)를 지워 줍니다. 그러면 뒤에서 GTID 목록을 읽기가 쉬워져요.

docker compose up -d

src() { docker compose exec -T -e MYSQL_PWD=root source mysql -uroot "$@"; }

rep() { docker compose exec -T -e MYSQL_PWD=root replica mysql -uroot "$@"; }

src < setup.sql
rep -e "RESET BINARY LOGS AND GTIDS; CHANGE REPLICATION SOURCE TO SOURCE_HOST='source', SOURCE_USER='repl', SOURCE_PASSWORD='repl', SOURCE_AUTO_POSITION=1, GET_SOURCE_PUBLIC_KEY=1; START REPLICA;"

실습 1: Relay log 안에는 Binlog 이벤트가 그대로 들어 있습니다

Relay log는 Binlog와 같은 형식으로 저장돼요. 정말 그런지 비교해 볼게요.

비교하기 쉽도록 Replica에서 새 Relay log 파일을 연 다음, Source에 한 행을 넣어 주세요.

rep -e "FLUSH LOCAL RELAY LOGS;"
src -e "SHOW BINARY LOG STATUS\G" | grep -E "File|Position"
src -e "INSERT INTO shop.orders (item, qty) VALUES ('keyboard', 1);"
rep -e "SHOW REPLICA STATUS\G" | grep "Relay_Log_File"

             File: binlog.000002
         Position: 1165
               Relay_Log_File: relay-bin.000004

FLUSH RELAY LOGS는 지금 쓰고 있는 Relay log를 닫고 새 파일을 엽니다.

여기에 LOCAL을 붙이면 이 문장이 Replica의 Binlog에 기록되지 않아요. 붙이지 않으면 Replica에 자기 GTID가 생기는데, 이런 GTID는 나중에 이 Replica를 Source로 올리거나 다른 Replica를 붙일 때 걸림돌이 됩니다.

이제 SHOW RELAYLOG EVENTS로 Relay log를 읽어 볼게요.

rep -t -e "SHOW RELAYLOG EVENTS IN 'relay-bin.000004';"

+------------------+-----+----------------+-----------+-------------+--------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                               |
+------------------+-----+----------------+-----------+-------------+--------------------------------------------------------------------+
| relay-bin.000004 |   4 | Format_desc    |         2 |         127 | Server ver: 8.4.11, Binlog ver: 4                                  |
| relay-bin.000004 | 127 | Previous_gtids |         2 |         198 | b734edb1-bc8d-11f1-8168-0242ac190002:1-9                           |
| relay-bin.000004 | 198 | Format_desc    |         1 |           0 | Server ver: 8.4.11, Binlog ver: 4                                  |
| relay-bin.000004 | 321 | Gtid           |         1 |        1244 | SET @@SESSION.GTID_NEXT= 'b734edb1-bc8d-11f1-8168-0242ac190002:10' |
| relay-bin.000004 | 400 | Query          |         1 |        1315 | BEGIN                                                              |
| relay-bin.000004 | 471 | Table_map      |         1 |        1376 | table_id: 88 (shop.orders)                                         |
| relay-bin.000004 | 532 | Write_rows     |         1 |        1429 | table_id: 88 flags: STMT_END_F                                     |
| relay-bin.000004 | 585 | Xid            |         1 |        1460 | COMMIT /* xid=33 */                                                |
+------------------+-----+----------------+-----------+-------------+--------------------------------------------------------------------+

같은 트랜잭션을 Source의 Binlog에서도 읽어 봅니다.

src -t -e "SHOW BINLOG EVENTS IN 'binlog.000002' FROM 1165;"

+---------------+------+------------+-----------+-------------+--------------------------------------------------------------------+
| Log_name      | Pos  | Event_type | Server_id | End_log_pos | Info                                                               |
+---------------+------+------------+-----------+-------------+--------------------------------------------------------------------+
| binlog.000002 | 1165 | Gtid       |         1 |        1244 | SET @@SESSION.GTID_NEXT= 'b734edb1-bc8d-11f1-8168-0242ac190002:10' |
| binlog.000002 | 1244 | Query      |         1 |        1315 | BEGIN                                                              |
| binlog.000002 | 1315 | Table_map  |         1 |        1376 | table_id: 88 (shop.orders)                                         |
| binlog.000002 | 1376 | Write_rows |         1 |        1429 | table_id: 88 flags: STMT_END_F                                     |
| binlog.000002 | 1429 | Xid        |         1 |        1460 | COMMIT /* xid=33 */                                                |
+---------------+------+------------+-----------+-------------+--------------------------------------------------------------------+

두 출력을 나란히 놓고 보면 이런 점이 눈에 들어와요.

Gtid부터 Xid까지: Source의 이벤트가 종류, GTID, 내용까지 그대로 들어 있습니다. Server_id도 Source의 1입니다.
End_log_pos: Relay log에서도 Source Binlog 기준 위치(1244, 1315, 1376, 1429, 1460)를 그대로 가지고 있습니다. 그래서 SQL 스레드가 Relay log를 읽어 적용하면서도 Source 기준으로 어디까지 적용했는지(Exec_Source_Log_Pos) 알려 줄 수 있습니다.
Pos: Relay log 파일 안에서의 위치입니다. 321부터 시작해 Source의 1165와는 다릅니다.
첫 Format_desc, Previous_gtids: Server_id가 2입니다. Replica가 Relay log 파일을 열 때 스스로 붙이는 머리글입니다.
세 번째 줄 Format_desc(Server_id 1): Source Binlog의 머리글을 받아 둔 것입니다. SQL 스레드가 뒤따르는 이벤트를 어떻게 읽을지 알려 줍니다.

형식이 같으니까 mysqlbinlog로도 Relay log 파일을 읽을 수 있어요.

실습 2: 적용이 막히면 Relay log가 쌓입니다

이번에는 받기는 정상인데 적용만 막힌 상황을 만들어 볼게요.

파일이 넘어가는 모습을 보려고 max_relay_log_size를 4096바이트로 아주 작게 줄이고, Replica에서 shop.orders에 쓰기 잠금을 30초 동안 잡아 둡니다. 운영으로 치면 Replica에서 돌던 긴 배치나 DDL이 테이블 잠금을 쥐고 있는 경우와 비슷해요.

그사이 Source에는 INSERT 300건을 한 건씩 커밋합니다.

rep -e "SET GLOBAL max_relay_log_size = 4096;"
rep -e "LOCK TABLES shop.orders WRITE; SELECT SLEEP(30); UNLOCK TABLES;" > /dev/null &
for i in $(seq 1 300); do echo "INSERT INTO shop.orders (item, qty) VALUES ('pen', $i);"; done | src
rep -e "SHOW REPLICA STATUS\G" | grep -E "Read_Source_Log_Pos|Exec_Source_Log_Pos|Relay_Log_Space|Seconds_Behind_Source|Replica_SQL_Running_State"
docker compose exec replica sh -c 'ls /var/lib/mysql | grep relay-bin' | grep -c 'relay-bin.0'

          Read_Source_Log_Pos: 88460
          Exec_Source_Log_Pos: 1460
              Relay_Log_Space: 96767
        Seconds_Behind_Source: 5
    Replica_SQL_Running_State: Waiting for replica workers to process their queues
23

출력을 보면 받기와 적용이 확실히 벌어져 있어요.

Read_Source_Log_Pos: I/O 스레드는 Source Binlog의 88460까지 모두 받았습니다.
Exec_Source_Log_Pos: SQL 스레드는 앞에서 넣은 한 행 뒤인 1460에 머물러 있습니다.
Relay_Log_Space: 남아 있는 Relay log 파일 크기의 합입니다. 96767바이트가 쌓였습니다.
마지막 숫자: Relay log 파일이 23개로 늘었습니다.

여기서는 INSERT 300건이 작아서 금방 끝났어요. 하지만 운영에서 대량 변경이 들어오는 동안 적용이 막혀 있으면 같은 일이 GB 단위로 일어납니다.

그러니 Replica 디스크가 Source보다 먼저 찬다면 Relay_Log_Space부터 확인해 주세요.

실습 3: 적용을 마친 Relay log는 언제 지워질까

30초가 지나 잠금이 풀리면 SQL 스레드가 밀린 트랜잭션을 적용해요. 적용 위치가 받은 위치를 따라잡은 뒤에 다시 볼게요.

rep -e "SHOW REPLICA STATUS\G" | grep -E "Read_Source_Log_Pos|Exec_Source_Log_Pos|Relay_Log_Space|Seconds_Behind_Source"
docker compose exec replica sh -c 'ls /var/lib/mysql | grep relay-bin' | grep -c 'relay-bin.0'

          Read_Source_Log_Pos: 88460
          Exec_Source_Log_Pos: 88460
              Relay_Log_Space: 95344
        Seconds_Behind_Source: 0
22

여기서 눈여겨볼 건, 적용은 끝났는데 파일은 22개가 남아 있고 Relay_Log_Space도 거의 그대로라는 점이에요.

relay_log_purge는 켜져 있으면 적용을 마친 파일을 자동으로 지우는 설정이고, 이 Replica에서는 ON이에요. 그래도 적용이 끝나는 즉시 지워지는 건 아니라는 거죠. 그럼 Relay log 파일을 한 번 넘겨 볼게요.

rep -e "FLUSH LOCAL RELAY LOGS;"
docker compose exec replica sh -c 'ls /var/lib/mysql | grep relay-bin'
rep -e "SHOW REPLICA STATUS\G" | grep "Relay_Log_Space"

relay-bin.000025
relay-bin.000026
relay-bin.index
              Relay_Log_Space: 2719

SQL 스레드가 다음 파일로 넘어가면서 적용을 마친 파일을 한꺼번에 지웠고, 파일 두 개만 남았어요. 공식 문서도 SQL 스레드가 파일의 이벤트를 모두 실행해 더 필요 없어진 파일을 자동으로 지운다고 설명합니다.

정리하면 Relay log는 파일 단위로, SQL 스레드가 다음 파일로 넘어갈 때 지워져요. 그래서 쓰기가 적어 파일이 잘 넘어가지 않는 Replica에서는 이미 적용한 Relay log가 한동안 남아 있을 수 있습니다.

정리

범위: MySQL 8.4.11(mysql:8.4 이미지) Source와 Replica 한 대씩, GTID 복제, replica_parallel_workers 기본값 4, 실습 중 max_relay_log_size는 4096바이트로 줄임.

Relay log의 이벤트는 Source Binlog의 이벤트 종류, GTID, End_log_pos를 그대로 가졌고 Pos만 Relay log 파일 기준이었어요. Relay log는 SHOW RELAYLOG EVENTS나 mysqlbinlog로 Binlog처럼 읽으시면 됩니다.
LOCK TABLES로 적용을 30초 막자 받은 위치는 88460, 적용 위치는 1460에 머물렀고 Relay log가 파일 23개, 96767바이트로 늘었어요. Replica 디스크가 Source보다 먼저 차면 Relay_Log_Space부터 보세요.
적용을 마친 뒤에도 파일 22개가 남아 있다가 FLUSH LOCAL RELAY LOGS로 다음 파일로 넘어가자 2개만 남고 Relay_Log_Space가 2719가 됐어요. 쓰기가 적은 Replica에서는 적용을 마친 Relay log가 한동안 남는다고 보고 디스크 여유를 잡아 두세요.
이 글에 싣지 않은 추가 측정에서는 서버가 시작할 때 기존 Relay log를 버리고 Source에서 다시 받게 하는 relay_log_recovery=ON으로 SIGKILL 뒤 재시작하자 기존 Relay log 파일이 사라지고, 받았지만 적용 전이던 5건을 Source에서 다시 받아 두 서버의 행 수가 같았어요. Replica에는 relay_log_recovery를 켜고, Source의 Binlog는 Replica가 멈춰 있을 수 있는 시간보다 길게 남겨 두세요.