포스트

pt-osc Issue in MariaDB v10.11.7

pt-osc Issue in MariaDB v10.11.7

AWS RDS MariaDB 10.11.7 환경에서 pt-online-schema-change 가 INSERT 의 일부를 누락시키는 사고가 있었고, MariaDB JIRA MDEV-34438 로 upstream confirmed 된 trigger 재실행 버그였습니다. 단계적으로 이슈를 좁혀나간 진단 흐름을 되새겨 보았고, 그 과정에서 들어간 코드 수정 두 곳을 함께 정리합니다.

들어가며

운영 중인 MariaDB 의 DDL 작업은 거의 매번 pt-online-schema-change (이하 pt-osc) 로 처리합니다. 무중단이 보장되어야 하는 24·365 워크로드에서 ALTER TABLE 을 그대로 수행할 수는 없기 때문입니다.

항목
EngineMariaDB 10.11.7 (AWS RDS, Multi-AZ)
인스턴스db.r5.8xlarge (vCPU 8 / RAM 64 GB)
스토리지9 TB
워크로드24·365, DB 의존도 High
DDL 티켓약 27 건/월, 평균 segment size 300 GB 이상
innodb_flush_log_at_trx_commit2 (default 1)
tx_isolationREAD-UNCOMMITTED (default REPEATABLE-READ)

이 환경에서 평소처럼 진행하던 pt-osc 가 chunk copy 시점에 들어온 INSERT 의 일부를 통째로 잃어버리는 사고가 발생했습니다. 작업 직후 row count 비교에서 1~2 분 단위로 count = 0 인 구간이 발견되었고, 누락 비율은 부하 시나리오에 따라 8 ~ 26 % 였습니다.

이 글은 그 원인을 좁혀나간 단계별 흐름과, 원인파악을 가능하게 만든 두 곳의 코드 수정을 정리합니다.

무엇이 잘못됐는가

이번 장애를 재현하기 위해 단순화한 시나리오는 다음과 같습니다.

1
2
3
4
5
6
7
8
9
10
1) Procedure 시작
       │ INSERT 100만 건 (1 초당 1,000 ~ 2,500 행)
       ▼
2) pt-osc 동시 수행
       │ ALTER TABLE (chunk copy + trigger sync)
       ▼
3) 결과 확인
       │ row count 시간대별 집계
       ▼
4) 결과 불일치 발견 → 누락 구간 존재

집계 결과를 시간대별로 펼쳐보면 1 ~ 2 분 단위로 count = 0 이 연속되는 구간이 보였습니다.

REG_DTMCOUNT
2024-03-12 11:03:572,464
2024-03-12 11:03:582,356
2024-03-12 11:03:591,897
… 중략 …
2024-03-12 11:04:501,405
2024-03-12 11:04:510
2024-03-12 11:04:520
2024-03-12 11:04:530
… 중략 …
2024-03-12 11:04:590

Procedure 는 now() 를 컬럼에 박아 INSERT 했기 때문에, 이 시점에 들어와야 했을 행 자체가 없는 것이 명확했습니다.

가설 1 — DB 파라미터

DBA 가 INSERT 누락을 만나면 가장 먼저 의심하는 것은 transaction durability 입니다. Commit 전에 OS Cache 단계까지만 내려간 변경분이 어떤 이유로든 사라지는 시나리오를 검증해야 합니다.

후보는 두 개였습니다.

  • innodb_flush_log_at_trx_commit : 0 / 1 / 2 — Commit 시 disk flush 강도
  • tx_isolation : READ-UNCOMMITTED / READ-COMMITTED / REPEATABLE-READ / SERIALIZABLE

innodb_flush_log_at_trx_commit 의 차이를 단일 layer 로 정리하면 다음과 같습니다.

1
2
3
4
5
DML ──► Log Buffer ──► OS Cache ──► Disk

  0 :  Commit (Write to OS Cache)              Flush to Disk (every 1 sec)
  1 :  Commit (Write & Flush to Disk)                           ← Default
  2 :  Commit (Write to OS Cache)              Flush to Disk (every 1 sec)

tx_isolation 4 단계와 innodb_flush_log_at_trx_commit 3 단계, 합쳐서 7 조합을 각각 5 회씩 돌려 35 회 부하 테스트를 진행했습니다. 부하 조건은 동일하게 INSERT 100 만 건입니다.

고정 / 가변회차 평균 누락 시간누락 비율 (평균)누락 발생 (회차/시행)
flush_log = 2, tx_iso = READ-UNCOMMITTED1 분 38 초약 24 %5 / 5
flush_log = 1, tx_iso = READ-UNCOMMITTED37 초약 9 %5 / 5
flush_log = 0, tx_iso = READ-UNCOMMITTED1 분 50 초약 25 %5 / 5
flush_log = 1, tx_iso = READ-COMMITTED41 초약 8 %5 / 5
flush_log = 1, tx_iso = REPEATABLE-READ36 초약 8 %5 / 5
flush_log = 1, tx_iso = SERIALIZABLE42 초약 9 %5 / 5

조합과 무관하게 모든 회차에서 누락이 발생했습니다. 비율도 8 ~ 26 % 사이에서 큰 변화 없이 비슷합니다.

이 시점에 첫 가설이 기각됩니다. 누락이 durability 와 isolation 두 축에 모두 무관하다면, 원인은 transaction 계층보다 위에 있다. 트랜잭션이 commit 되었느냐 아니냐의 문제가 아니라, 그 commit 자체가 어딘가에서 사라지고 있다는 뜻이었습니다.

가설 2 — pt-osc 옵션·버전

다음 의심 대상은 pt-osc 자체였습니다. AWS Performance Insight 의 DB Workload 그래프에서 pt-osc 동작 시점에 throughput 스파이크가 또렷이 보였기 때문에, “부하를 너무 빠르게 주입해서 INSERT 가 밀려나는 게 아닌가” 라는 가설이 자연스러웠습니다.

조절 가능한 핵심 옵션은 다음과 같습니다.

OptionDefault설명
chunk-size1000chunk 1 개당 SELECT 행 수
chunk-time0.5chunk SELECT 가 이 시간 안에 끝나도록 chunk size 동적 조정
chunk-size-limit4desired chunk size 의 N 배 초과 시 chunk 차단
sleep0chunk 복사 후 sleep (초)
max-loadThreads_running=25임계치 초과 시 일시정지
max-lag1 sreplica lag 초과 시 일시정지

의도적으로 부하를 줄이는 방향으로 chunk-time 을 0.1 ~ 0.3 사이에서 흔들고 sleep 을 0.1 ~ 0.5 사이에서 끼워 넣는 9 가지 조합을 5 회차씩 돌렸습니다.

chunk-timesleep누락 평균 시간누락 비율 (평균)
0.30.1약 2 분 4 초약 26 %
0.20.3약 3 분 10 초약 26 %
0.10.5약 8 분 21 초약 27 %

부하를 낮출수록 chunk 진행이 느려져 누락 시간 길이만 비례하게 늘어났을 뿐, 누락 비율은 거의 같았습니다. pt-osc 와 MariaDB 의 minor 버전을 모두 한 단계 위·아래로 교체해 봤지만 마찬가지였습니다.

두 번째 가설도 기각됩니다. 옵션·버전 무관하게 누락이 재현된다면, pt-osc 의 구성 영역이 아니라 그것이 의존하는 환경, 즉 DB 엔진 자체에 무언가가 있다.

MySQL 에서는?

같은 가설을 검증할 가장 빠른 방법은 동일 시나리오를 MySQL 에서 돌려 보는 것이었습니다. 동일한 procedure, 동일한 pt-osc 옵션, 동일한 파라미터, 동일한 부하로 MySQL 8 환경에서 테스트한 결과는 다음과 같았습니다.

MySQL 8 에서는 INSERT 누락이 한 회차도 발생하지 않았습니다. pt-osc 자체나 procedure 의 INSERT 패턴이 원인이라면 MySQL 에서도 재현됐어야 합니다. 이 시점에 가설이 “MariaDB engine layer” 로 좁혀집니다.

이제 MariaDB 측에서 pt-osc 가 거는 trigger 가 정확히 어떻게 동작하는지를 직접 들여다볼 차례였습니다.

정밀 추적 — source audit 컬럼

여기서 첫 번째 벽에 부딪힙니다. 누락 행을 보고 있어도, 그 행이 원래 procedure INSERT 로 들어왔어야 했던 것 인지, pt-osc trigger 가 NEW 테이블에 복제했어야 했던 것 인지 식별할 수 없었습니다. pt-osc 가 끝난 뒤 우리가 들고 있는 결과는 그저 새 테이블 한 개일 뿐이었기 때문입니다.

해결 아이디어는 단순합니다. 행마다 출처 라벨을 직접 박아두자. target 테이블에 source 라는 audit 컬럼을 하나 추가하고, 각 INSERT 경로가 자기 라벨을 거기에 채우도록 만들면 됩니다.

pt-osc 완료 후 새 테이블의 source 컬럼은 다음 셋 중 하나여야 합니다.

의미원본 테이블에 존재새 테이블에 존재
'' (공백)pt-osc 시작 전 이미 들어 있던 행OO
'PROCEDURE'procedure 가 INSERT 한 행OO (chunk copy 시점에 따라)
'TRIGGER'pt-osc 의 _ins trigger 가 새 테이블에 복제한 행XO

이 라벨링을 통해 누락된 행이 어느 경로에서 사라졌는지를 곧바로 식별할 수 있게 됩니다.

코드 수정

수정은 두 곳입니다. 부하를 만드는 procedure 한 곳과, pt-osc 가 동적으로 만들어 거는 INSERT trigger 한 곳입니다.

Procedure (변경 전)

원본 procedure 는 target 테이블(bjh.test) 에 MSHP_ID, STR_CD, reg_dtm, IP 4 개 컬럼을 박는 단순 INSERT loop 입니다. 출처를 알 수 없는 형태입니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
DELIMITER $$
CREATE OR REPLACE DEFINER=`admin`@`%` PROCEDURE `bjh`.`test`(IN num INT)
BEGIN
    DECLARE i INT DEFAULT 0;
    DECLARE LAST_MSHP_ID INT DEFAULT 0;

    SELECT count(1) INTO LAST_MSHP_ID
      FROM bjh.test mmm
     WHERE mmm.STR_CD = '012002'
       AND mshp_id LIKE '%test85';

    WHILE i < num DO
        INSERT INTO bjh.test
        (
            MSHP_ID,
            STR_CD,
            reg_dtm,
            IP
        )
        VALUES (
            CONCAT(LAST_MSHP_ID, 'test85'),
            '012002',
            now(),
            i
        );
        SET i = i + 1;
        SET LAST_MSHP_ID = LAST_MSHP_ID + 1;

        COMMIT;
    END WHILE;
END$$
DELIMITER ;

Procedure (변경 후)

IP 컬럼을 source 컬럼으로 바꾸고, INSERT 의 마지막 VALUE 로 'PROCEDURE' 라는 literal 을 박습니다. 이렇게 하면 procedure 가 직접 넣은 행은 모두 source = 'PROCEDURE' 로 식별됩니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
DELIMITER $$
CREATE OR REPLACE DEFINER=`admin`@`%` PROCEDURE `bjh`.`ptosctest`(IN num INT)
BEGIN
    DECLARE i INT DEFAULT 0;
    DECLARE LAST_MSHP_ID INT DEFAULT 0;

    SELECT count(1) INTO LAST_MSHP_ID
      FROM bjh.test1 mmm
     WHERE mmm.STR_CD = '012002'
       AND mshp_id LIKE '%test85';

    WHILE i < num DO
        INSERT INTO bjh.test1
        (
            MSHP_ID,
            STR_CD,
            reg_dtm,
            source
        )
        VALUES (
            CONCAT(LAST_MSHP_ID, 'test85'),
            '012002',
            now(),
            'PROCEDURE'
        );
        SET i = i + 1;
        SET LAST_MSHP_ID = LAST_MSHP_ID + 1;
    END WHILE;
END$$
DELIMITER ;

pt-osc trigger (변경 전)

pt-online-schema-change 가 동적으로 만들어 거는 INSERT trigger 는 Perl 스크립트 내부에서 문자열로 조립됩니다. 원본은 $qcols, $new_vals 두 변수를 컬럼 메타데이터에서 자동 생성해 그대로 사용합니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
# ----------------------------------------------------------------------
my $qcols    = join(', ', map { $q->quote($_->{new}) }       @$cols);
my $new_vals = join(', ', map { "NEW.".$q->quote($_->{old}) } @$cols);

my $insert_trigger
    = "CREATE TRIGGER `${prefix}_ins` AFTER INSERT ON $orig_tbl->{name} "
    . "FOR EACH ROW "
    . "BEGIN "
    . "DECLARE CONTINUE HANDLER FOR 1146 begin end; "
    . "REPLACE INTO $new_tbl->{name} ($qcols) VALUES ($new_vals);"
    . "END ";

# ----------------------------------------------------------------------

이 형태에서는 trigger 가 NEW 테이블로 복사하는 행의 source 값이 procedure 가 박아둔 'PROCEDURE' 그대로 따라오기 때문에, 어디서 들어온 행인지 구별이 안 됩니다.

pt-osc trigger (변경 후)

컬럼 리스트와 VALUES 를 명시적으로 풀어쓰고, 마지막 VALUE 자리에 'TRIGGER' literal 을 박아 trigger 경로의 행을 강제 라벨링합니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
# ----------------------------------------------------------------------
my $qcols    = join(', ', map { $q->quote($_->{new}) }       @$cols);
my $new_vals = join(', ', map { "NEW.".$q->quote($_->{old}) } @$cols);

my $insert_trigger = "CREATE TRIGGER `${prefix}_ins` AFTER INSERT ON $orig_tbl->{name} "
                   . "FOR EACH ROW "
                   . "BEGIN "
                   . "DECLARE CONTINUE HANDLER FOR 1146 begin end; "
                   . "REPLACE INTO $new_tbl->{name} "
                   . "(`seq`, `mshp_id`, `str_cd`, `rest_pnt`, `reg_dtm`, `source`) "
                   . "VALUES (NEW.`seq`, NEW.`mshp_id`, NEW.`str_cd`, NEW.`rest_pnt`, NEW.`reg_dtm`, 'TRIGGER');"
                   . "END ";
# ----------------------------------------------------------------------

수정 위치는 pt-online-schema-change 본체의 약 11855 ~ 11867 라인 부근($insert_trigger 가 만들어지는 부분)입니다. UPDATE / DELETE trigger 도 같은 방식으로 패치할 수 있지만, 이번 진단의 핵심은 INSERT trigger 였기 때문에 INSERT 만 손댔습니다.

이 두 곳의 패치가 끝나면, pt-osc 가 끝난 뒤 새 테이블의 source 컬럼만 봐도 어느 경로의 행이 살아남았고 어느 경로가 누락됐는지 한눈에 보입니다.

재현·검증

먼저 MySQL 환경입니다. 패치된 procedure 와 패치된 pt-osc 로 동일 부하를 흘리고, 새 테이블의 source 컬럼 분포를 확인합니다.

MySQL 검증 — source 컬럼이 정상적으로 TRIGGER 라벨로 채워짐

source = 'TRIGGER' 행이 연속된 seq 값으로 빠짐없이 보입니다. trigger 가 모든 INSERT 시점에 정상 동작했다는 뜻이고, 이전 가설(MySQL 에서는 누락 0) 과 일치합니다.

같은 패치를 MariaDB 10.11.7 에 그대로 적용해 다시 돌리면 다른 그림이 나옵니다. 누락 구간의 행을 source 별로 쪼개 보면 source = 'TRIGGER' 가 통째로 사라진 시간 구간 이 존재했습니다. 같은 시간 구간에서 procedure 의 source = 'PROCEDURE' 행은 정상 분포로 들어와 있었습니다.

이는 매우 강한 신호였습니다. 누락 자체가 procedure 의 문제가 아니라, pt-osc 가 건 trigger 가 그 시간 구간에 아예 실행되지 않은 것이 원인 이라는 뜻이기 때문입니다. trigger 가 호출만 되었더라면 우리가 hardcode 한 'TRIGGER' literal 이 적어도 한 번은 박혔어야 했습니다.

Upstream confirm

stored procedure + loop INSERT + pt-osc + MariaDB only 라는 조합으로 MariaDB 의 JIRA 와 Launchpad 를 검색하면 정확히 같은 증상이 보고된 티켓이 있습니다.

이 티켓에 MariaDB 의 메인테이너인 Sergei Golubchik 이 단 댓글이 결정적이었습니다.

MariaDB JIRA — Sergei Golubchik 의 버그 4 조건 확인 댓글

Thanks. It’s a bug.

To trigger it one needs:

  • stored routine
  • a statement which is reexecuted (one INSERT in a loop, two separate INSERTs won’t do)
  • INSERT needs to use more than one table, causing prelocking
  • prelocking set is changed between reexecutions

네 가지 조건을 우리 환경과 매칭해 보면 모두 정확히 일치합니다. procedure 안의 WHILE i < num DO INSERT 는 stored routine 안의 reexecuted INSERT 그 자체이고, pt-osc 가 trigger 를 거는 순간부터 INSERT 의 prelocking set 이 바뀌게 됩니다(Table A_new 가 prelocking 대상에 추가됨). 사고 환경이 정확히 이 네 조건의 교집합 위에 놓여 있었습니다.

여기까지 와서야 비로소 “MariaDB 10.11.7 의 stored routine reexecution + prelocking set 변경 시 trigger 가 누락되는 버그” 라는 root cause 가 확정됩니다.

이 기사는 저작권자의 CC BY 4.0 라이센스를 따릅니다.