Replication 문제 해결을 위해 binlog 데이터 추출

Henry Hwang -

대부분 복제 오류의 경우, 오류의 원인은 대개 �show slave status 출력에서 찾을 수 있습니다. 그러나, slave� �지연 문제를 해결하거나 복제된 이벤트에 대해 좀 더 자세한 내용을 알아내고자 하는 경우, binlog� �이벤트를 추출하기 위해 mysqlbinlog (mysql 유틸리티) 또는 repclient (Clustrix 유틸리티)를 사용할 수 있습니다.

Clustrix에서 �Binlog

binlog�를 자신의 개별 파일에 쓰는 mysql�과 달리 Clustrix binlog는 데이터베이스 저장소에 기록되어 데이터베이스 데이터처럼 동일한 보호를 받습니다.

슬레이브 중단 요인

가장 일반적인 슬레이브 중단의 원인은 다음과 같습니다.

  • Row not found: 슬레이브의 행이 복제된 이벤트의 행 세부 정보와 일치하지 않습니다.
  • Duplicate key in container: 동일한 기본키(Primary Key)가 있는 행이 이미 슬레이브에 있습니다.

이러한 오류는 상당히 자명하지만, mysqlbinlog 또는 repclient를 사용하여 복제 이벤트가 독립된 쿼리인지 또는 더 큰 명시적 트랜잭션의 일부인지 여부를 확인하고 싶을 것입니다. 후자의 경우라면 명시적 트랜잭션에 있는 다른 쓰기도 건너 뛸 수 있으므로 해당 이벤트를 건너 뛰고 싶지는 않을 것입니다.

이벤트를 건너 뛰기 위해 설정할 수 있는 설정과 성공적인 쓰기를 위해 행이 얼마나 일치해야 하는지에 대한 자세한 내용은 Controlling Slave Behavior on Error를 참조하십시오.

덜 일반적인 오류는 다음과 같은 것들이 있습니다.

  • arity errors (테이블 정의가 복제 이벤트와 일치하지 않습니다)
  • foreign key contraints

단순한 오류

다음은 마지막으로 성공한 로그 위치 읽기, binlog 파일 이름, 마스터 호스트, 복제 사용자 이름 및 슬레이브 중지 이유가 표시된 일부 show slave status 출력입니다. binlog에서 데이터를 추출할 때 이 정보 중 일부가 필요할 수 있습니다.

*************************** 1. row ***************************
 Slave_Name: default
 Slave_Status: Errored
 Master_Host: 10.0.0.10
 Master_Port: 3306
 Master_User: repl
 Master_Log_File: default
 Slave_Enabled: Enabled
 Log_File_Seq: 28
 Log_File_Pos: 45532636
 Last_Error: Duplicate key in container: test_tbl2.__idx_test_tbl2__PRIMARY (314159). Statement: insert into test_tbl2 (id) values (314159), Database: test
 Connection_Status: Disconnected
 Relay_Log_Bytes_Read: 0
Relay_Log_Current_Bytes: 0
 Seconds_Behind_Master: NULL
 
 *************************** 1. row ***************************
 Slave_Name: default
 Slave_Status: Errored
 Master_Host: 10.0.0.10
 Master_Port: 3306
 Master_User: repl
 Master_Log_File: default
 Slave_Enabled: Enabled
 Log_File_Seq: 2485
 Log_File_Pos: 489659967
 Last_Error: Row Not Found: for delete on test.TEST_TBL3 at default2485.489660488 where TEST_TBL3.__idx_TEST_TBL3__PRIMARY(id)=(271828). Statement: COMMIT, Database:
 Connection_Status: Disconnected
 Relay_Log_Bytes_Read: 0
Relay_Log_Current_Bytes: 0
 Seconds_Behind_Master: NULL
1 row in set (0.00 sec)

A sample SBR slave error:

*************************** 1. row ***************************
 Slave_Name: default
 Slave_Status: Reconnecting
 Master_Host: 10.0.0.10
 Master_Port: 3306
 Master_User: repl
 Master_Log_File: default
 Slave_Enabled: Enabled
 Log_File_Seq: 8051
 Log_File_Pos: 56376112
 Last_Error: Can't find any matching row in the test_tbl4 table: year '1666' does not exist. Statement: update test_tbl4 set event="Great Fire" where year=1666, Database:
 Connection_Status: Disconnected
 Relay_Log_Bytes_Read: 0
Relay_Log_Current_Bytes: 0
 Seconds_Behind_Master: NULL
1 row in set (0.00 sec)

작업 부하에 따라 이벤트가 더 큰 트랜잭션의 일부가 아닌 독립된 쿼리인지 확인하기 위해 binlog 이벤트를 추출해야 할 수 있습니다. 그렇지 않고, 이벤트를 건너 뛰거나 그것이 더 큰 트랜잭션의 일부인 경우 해당 명시적 트랜잭션의 모든 쓰기를 건너 뛰게 될 것입니다.

show slave 출력에서 마지막으로 성공한 로그 위치와 로그 파일 이름을 사용하여 슬레이브가 정지했거나 지연된 이유를 해결하기 위해 binlog에서 이벤트 세부 사항을 추출할 수 있습니다.

mysqlbinlog와 repclient의 차이점

mysqlbinlog와 repclient 유틸리티는 동일하게 binlog에서 이벤트를 추출하는 작업을 수행합니다. 가장 큰 차이점은 출력과 그것들이 얼마나 읽기 쉽고 mysqlbinlog가 모든 clustrix 복제 이벤트를 이해하지 못한다는 점입니다.

repclient의 좋은 점은 시작 로그 위치에서 추출할 이벤트 수(-count=###)를 지정할 수 있다는 것입니다. repclient는 또한 Clustrix에서 원시(raw) binlog 덤프를 생성하여 이벤트를 다른 슬레이브로 재생하거나 백업 계획의 일부로 사용할 수 있습니다.

mysqlbinlog의 유용한 측면은 특히 RBR(row-based replication)에서 이해하기 쉬운 형식으로 쓰기 이벤트를 제공한다는 점입니다. RBR을 사용하면 행 변경만 복제되므로 쓰기 이벤트를 생성하기 위해 처리된 실제 쿼리를 사져올 수 없습니다.

이러한 도구를 사용하여 SBR 문제를 해결할 수도 있습니다.

매개변수

두 명령의 기본 매개 변수는 다음과 같습니다.

  • log position: 처리된 마지막 성공 이벤트가 스레이브 클러스터의 show slave status에 표시됩니다.
  • binlog file name: binlog 이름과 새로운 binlog가 생성될 때 증가하는 6자리 접미사로 구성됩니다.
  • master host: 마스터 클러스터에 있는 노드 중 하나의 IP 주소 또는 호스트명.
  • username and password: binlog 데이터에 액세스 할 사용자 이름 및 패스워드.

슬레이브가 중지하면 해당 이벤트의 로그 위치와 읽고 있던 binlog와 함께 처리된 마지막으로 성공한 이벤트를 표시합니다.

repclient와 mysqlbinlog 간의 출력 비교

다음은 동일한 binlog를 쿼리하는 두 유틸리티의 출력입니다. binlog 이벤트를 추출하기 전에 binlog 추출 파일이 매우 빠르게 커질 수 있기 때문에 충분한 공간을 가진 파일 시스템으로 이동(cd)해야 합니다.

cd /clustrix # or wherever you have the most available space
repclient -logname statd.006870 -logpos 59900827 -count 100 -verbose > binlog.output

트랜잭션 시작을 정의하는 BEGIN을 찾으십시오.

00000000 42 45 47 49 4E |BEGIN |

다음 섹션은 statd.statd_history에 대한 테이블 매핑을 보여줍니다. 여러 테이블에 쓰는 다른 복제 이벤트의 경우 각 테이블에 다음과 같은 항목을 갖고 있습니다.

}
2014-11-14 12:47:06.599042 UTC eukanuba002 INFO mysql/replication/repclient.c:445 repdump_event(): MsgType19 [pos: 59900886, log_offset: 59900943]
message mysql_table_map {
 header = message mysql_event_header {
  timestamp = 1415960473
   type = 19
    server_id = 2101898466
     size = 57
      log_offset = 59900943
       flags = 0
        }
        table_id = 1
         flags = 0
          db = "statd"
           table = "statd_history"
            columns = [
             mysql_type_long,
              mysql_type_long,
               mysql_type_datetime,
                mysql_type_double
                 ]
                 }
                 

다음 이벤트는 실제 INSERT입니다. 이 경우, the mysql_write_rows = INSERT 입니다. table_id 값에 유의하십시오. 이벤트에 다수의 테이블 매핑이 있는 경우 table_id는 쓰기가 적용되는 테이블을 식별합니다 .

2014-11-14 12:47:06.599135 UTC eukanuba002 INFO mysql/replication/repclient.c:445 repdump_event(): MsgType23 [pos: 59900943, log_offset: 59900997]
message mysql_write_rows {
 header = message mysql_event_header {
 timestamp = 1415960473
 type = 23
 server_id = 2101898466
 size = 54
 log_offset = 59900997
 flags = 0
 }
 table_id = 1
 flags = 0
 used_columns = [1111]
 rowdata =
00000000 F0 6D 00 00 00 DF 2F 00 00 F5 90 F3 77 51 12 00 |.m..../.....wQ..|
00000010 00 00 00 A0 69 8F 5C E5 41 |....i.\.A |

}

이 다음 섹션은 입력될 실제 데이터(괄호 안의 값)입니다. 따라서 이벤트에 다음 데이터가 삽입됩니다(109,12255,'2014-11-14 10:20:05',2867100493).

1 Rows:
 [t_vu32(109), t_vu32(12255), t_datetime(2014-11-14 10:20:05), t_vf64(2867100493)]
2014-11-14 12:47:06.599270 UTC eukanuba002 INFO mysql/replication/repclient.c:445 repdump_event(): MsgType23 [pos: 59900997, log_offset: 59901051]
message mysql_write_rows {
 header = message mysql_event_header {
 timestamp = 1415960473
 type = 23
 server_id = 2101898466
 size = 54
 log_offset = 59901051
 flags = 0
 }
 table_id = 1
 flags = 0
 used_columns = [1111]
 rowdata =
00000000 F0 6E 00 00 00 A8 41 00 00 FD 8E F3 77 51 12 00 |.n....A.....wQ..|
00000010 00 00 00 00 00 00 00 00 00 |......... |

트랜잭션이 완전히 COMMIT될 때까지 몇 개의 추가적인 mysql_write_rows (inserts)가 있습니다.

00000000 43 4F 4D 4D 49 54 |COMMIT |

repclient 출력을 mysqlbinlog의 출력과 비교하십시오.

mysqlbinlog를 사용하여 binlog에서 이벤트를 추출할 때 --hexdump 옵션을 사용하면 언제 트랜잭션이 시작되고 커밋되는지를 알려주지만 더 많은 데이터를 출력하게 됩니다.

mysqlbinlog --verbose --base64-output=ALWAYS --hexdump --start-position=59900827 -R statd.006870 > mysqbinlog.output
1~2초 후에 ctrl-c를 누르십시오.

일부 로그 위치와 함께 16진수 출력이 있지만 다시 BEGIN을 찾고 싶습니다.

# Start: binlog v 4, server v 5.0.45 created 700101 0:00:00
BINLOG '
AAAAAA/ibEh9ZgAAAAAAAAAAAAQANS4wLjQ1AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 59900866
#141114 10:21:13 server id 2101898466 end_log_pos 59900886
# Position Timestamp Type Master ID Size Master Pos Flags
# 39203c2 99 d7 65 54 02 e2 6c 48 7d 3b 00 00 00 d6 03 92 03 00 00
# 39203d5 04 bc b8 0f 00 00 00 00 00 00 00 15 00 00 00 00 |................|
# 39203e5 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# 39203f5 21 00 00 42 45 47 49 4e 00 00 00 04 21 00 21 00 |...BEGIN|
#
BINLOG '
mddlVALibEh9OwAAANYDkgMAAAS8uA8AAAAAAAAAFQAAAAAAAAEAAAgAAAAAAAQhACEAIQAAQkVH
SU4=
'/*!*/;
# at 59900925
# at 59900982
# at 59901036
# at 59901090
# at 59901144
# at 59901198

다음은 테이블이 매핑되는 이벤트입니다.

#141114 10:21:13 server id 2101898466 end_log_pos 59900943
# Position Timestamp Type Master ID Size Master Pos Flags
# 39203fd 99 d7 65 54 13 e2 6c 48 7d 39 00 00 00 0f 04 92 03 00 00
# 3920410 01 00 00 00 00 00 00 00 05 73 74 61 74 64 00 0d |.........statd..|
# 3920420 73 74 61 74 64 5f 68 69 73 74 6f 72 79 00 04 03 |statd.history...|
# 3920430 03 0c 05 01 08 08 |......|
# Table_map: `statd`.`statd_history` mapped to number 1

[...일부 행이 삭제되었습니다...]

#141114 10:21:13 server id 2101898466 end_log_pos 59901219
# Position Timestamp Type Master ID Size Master Pos Flags
# 392050e 99 d7 65 54 02 e2 6c 48 7d 3c 00 00 00 23 05 92 03 00 00
# 3920521 04 bc b8 0f 00 00 00 00 00 00 00 15 00 00 00 00 |................|
# 3920531 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# 3920541 21 00 00 43 4f 4d 4d 49 54 |...COMMIT|

16진수 덤프가 끝나면 mysqlbinlog는 디코딩된 쓰기를 좀 더 읽기 쉽게 파싱합니다.

BINLOG '
mddlVBPibEh9OQAAAA8EkgMAAAEAAAAAAAAABXN0YXRkAA1zdGF0ZF9oaXN0b3J5AAQDAwwFAQgI
mddlVBfibEh9NgAAAEUEkgMAAAEAAAAAAAAABA/wbQAAAN8vAAD1kPN3URIAAAAAoGmPXOVB
### INSERT INTO statd.statd_history
### SET
### @1=109
### @2=12255
### @3=2014-11-14 10:20:05
### @4=2867100493
mddlVBfibEh9NgAAAHsEkgMAAAEAAAAAAAAABA/wbgAAAKhBAAD9jvN3URIAAAAAAAAAAAAA
### INSERT INTO statd.statd_history
### SET
### @1=110
### @2=16808
### @3=2014-11-14 10:15:01
### @4=0
mddlVBfibEh9NgAAALEEkgMAAAEAAAAAAAAABA/wfQAAAPIAAADxkPN3URIAAAAAAMCJ9lJB
### INSERT INTO statd.statd_history
### SET
### @1=125
### @2=242
### @3=2014-11-14 10:20:01
### @4=4971047
mddlVBfibEh9NgAAAOcEkgMAAAEAAAAAAAAABA/wbQAAAOEvAAD1kPN3URIAAAAAAAAAAAAA
### INSERT INTO statd.statd_history
### SET
### @1=109
### @2=12257
### @3=2014-11-14 10:20:05
### @4=0
mddlVALibEh9PAAAACMFkgMAAAS8uA8AAAAAAAAAFQAAAAAAAAEAAAgAAAAAAAQhACEAIQAAQ09N
TUlU
'/*!*/;

BEGIN으로 표시된 다음 트랜잭션의 시작

# at 59901258
#141114 10:21:13 server id 2101898466 end_log_pos 59901278
# Position Timestamp Type Master ID Size Master Pos Flags
# 392054a 99 d7 65 54 02 e2 6c 48 7d 3b 00 00 00 5e 05 92 03 00 00
# 392055d 01 44 a7 14 00 00 00 00 00 00 00 15 00 00 00 00 |.D..............|
# 392056d 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# 392055d 01 44 a7 14 00 00 00 00 00 00 00 15 00 00 00 00 |.D..............|
# 392056d 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# 392057d 21 00 00 42 45 47 49 4e 00 00 00 04 21 00 21 00 |...BEGIN|

mysqlbinlog에서 발견한 한 가지 사소한 문제는 때로 올바른 시작 로그 위치에서 시작하지 않는다는 것이나 시작 로그 위치에서 그렇게 멀지는 않습니다.


인자 개수 오류

다음과 같은 슬레이브 중지 에러가 발생했다고 가정해 봅시다.

*************************** 1. row ***************************
 Slave_Name: default
 Slave_Status: Errored
 Master_Host: 10.0.0.10
 Master_Port: 3306
 Master_User: repl
 Master_Log_File: clx-binlog
 Slave_Enabled: Enabled
 Log_File_Seq: 5
 Log_File_Pos: 1000000
 Last_Error: Row Type Mismatch: Column arity mismatch between slave and master for the table test.test_tbl
 Connection_Status: Disconnected
 Relay_Log_Bytes_Read: 0
Relay_Log_Current_Bytes: 0
 Seconds_Behind_Master: NULL

마스터 클러스터 중 하나의 노드에서 다음과 같이 하십시오.

cd /clustrix # 또는 사용 가능한 공간이 가장 큰 위치
mysqlbinlog -u repl -h 127.0.0.1 -p'xxxxxxxxx' --verbose --base64-output=ALWAYS --hexdump --start-position=1000000 -R clx-binlog.000005 > mysqlbinlog.output

또는 다음을 사용할 수도 있습니다.

repclient -logname clx-binlog.000005 -logpos 1000000 -count 100 -verbose > repclient.output?

다음은 mysqlbinlog 추출 파일의 일부입니다.

#141022 8:55:17 server id 193994141 end_log_pos 1003393
# Position Timestamp Type Master ID Size Master Pos Flags
# f4f6b f5 70 47 54 02 9d 1d 90 0b 3c 00 00 00 81 4f 0f 00 00 00
# f4f7e 04 fc 96 c2 00 00 00 00 00 00 00 15 00 00 00 00 |................|
# f4f8e 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# f4f9e 21 00 00 43 4f 4d 4d 49 54 |...COMMIT|
#
BINLOG '
[...some output that can be ignored...]
### UPDATE test.TEST_TBL
### WHERE
### @1=15871698
### @2=1
### @3=3109804
### @4='Test'
### @5='User'
### @6=0
### @7=0
### @8=3336901
### @9=3128759
### @10=0
### @11=1413951934
### SET
### @1=15871698
### @2=1
### @3=3109804
### @4='Test'
### @5='User2'
### @6=1
### @7=1
### @8=3336901
### @9=3128759
### @10=0
### @11=1413968117
[...some output that can be ignored...]
'/*!*/;
# at 1003431
#141022 8:55:17 server id 193994141 end_log_pos 1003452
# Position Timestamp Type Master ID Size Master Pos Flags
# f4fa7 f5 70 47 54 02 9d 1d 90 0b 3b 00 00 00 bc 4f 0f 00 00 00
# f4fba 09 48 dd b8 00 00 00 00 00 00 00 15 00 00 00 00 |.H..............|
# f4fca 00 00 01 00 00 08 00 00 00 00 00 04 21 00 21 00 |................|
# f4fda 21 00 00 42 45 47 49 4e 00 00 00 04 21 00 21 00 |...BEGIN|
위의 예제 출력을 다음과 같은 세부 정보를 수집할 수 있습니다.
  • 현지 시각으로 08:55:17에 이벤트가 처리되었습니다
  • 다음 이벤트가 BEGIN으로 시작하기 때문에 하나의 단일 update 쓰기가 처리되었습니다.
  • test.TEST_TBL의 컬럼 5, 6, 7, 11이 유일하게 다르기 때문에 업데이트 되었습니다.
  • @1, @2, @3...@11로 표시된 필드는 show create table의 열 순서와 일치합니다.

이것이 인자 개수 오류 때문에 슬레이브 중지를 유발한 이벤트인 경우 이는 슬레이브 테이블의 컬럼수가 쓰기 이벤트의 컬럼수와 일치하지 않기 때문입니다. 그러면, TEST_TBL에 대한 DDL를 보고 검증할 수 있습니다.

이 문제를 해결하려면 동일한 열 개수의 다른 쓰기가 있는지 여부와 이러한 문이 명시적 트랜잭션인지 여부를 확인하는데 도움을 받으려면 기술지원에 문의하십시오. 그러면, 저희는 슬레이브를 중지하고 슬레이브에 수동으로 변경 사항(들)을 적용하고 이벤트를 건너뛸 것입니다.

쓰기가 많은 이벤트에서 슬레이브 지연

슬레이브가 계속 지연되고 로그 위치가 증가하지 않는 경우, binlog에서 이벤트를 추출할 수 있습니다.

binlog 추출에 긴 로그 위치 목록이 있는 이벤트가 있다면 이것은 이 이벤트가 큰 트랜잭션임을 나타냅니다.

# 3333333
# 3333432
# 3334023
# 3336023
...
# 12312341
...
# 23423233

이 항목을 스크롤할 때 " Position "을 검색하면 출력의 다음 섹션으로 이동하게 됩니다.

결국, 이벤트가 기록중인 테이블과 UPDATE, DELETE 또는 INSERT인지 여부를 식별하는 테이블 매핑을 찾게 될 것입니다. 그런 다음, 마스터로 돌아가서 실제로 사용된 쿼리를 찾을 수 있습니다. 쿼리 실행에 약간의 시간이 걸리면 query.log에 기록되어야 합니다. 그렇지 않다면, 마스터의 clustrix_statd.qpc_history에서 찾을 수 있어야 합니다.


이벤트 중간에 시작 로그 위치 지정

binlog 출력 결과에서 다음과 같은 오류가 발생하면:

Could not decode row data: Generic Error: table_id 1 not found

이는 이벤트의 시작 지점에 있지 않은 시작 로그 위치를 지정했고 유틸리티가 테이블 매핑 정보를 필요로 하기 때문입니다. 이전 시작 로그 위치로 이동할 때 시작 로그 위치가 큰 트랜잭션의 중간에 있는 경우 몇 번의 시도가 필요할 수 있지만 중지된 슬레이브 이벤트에서 로그 위치를 사용하는 경우라면 이 오류가 발생하면 안됩니다.


Reptool

Reptool은 새로운 기능을 추가하고 좀 더 읽기 쉬운 출력으로 이벤트를 디코딩할 수 있는 새로운 유틸리티입니다. 향후 릴리스에서 사용할 수 있습니다.

또 다른 질문이 있으십니까? 문의 등록

0 댓글

댓글을 남기려면 로그인하세요.
Zendesk 제공