MySQL & Aurora

MySQL Position 설정(SBR의 경우 무엇으로 맞출까?)

대담이2 2018. 1. 5. 10:33

슬레이브 비정상 종료, 재구동 이후 복제를 위한 positioning 중, auto_increment 값이 맞지 않는 현상 분석



MySQL 롤백으로 인한 M-S 비일치를 발생시킴

상기의 모델은 마스터-리플간 불일치 발생으로 인한 건으로, 리플리케이션이 늦은 상태가 되나,

원래 테스트하려고 했던 현상은 binlog상태 <> 실제 DB서버에 커밋된 상태(DB서버에 커밋된 상태가 빈로그 상태보다 더 앞선 상태로, 릴레이로그의 커밋된 부분이 커밋 안된 부분으로 나타나는 현상)이나,

해당 현상은 재현하지 못한 관계로 수동으로 상황을 재현하여 테스트.




시나리오 작성

현재 포지션 값 저장

50000건 인서트(슬레이브도 쫓아가도록)

포지션값 1. 의 포지션값으로 변경(50000건 차이 발생했으나, 실제론 데이터 입력된 상태)

어느 값으로 변경했을 때 insert_id가 변경되는지 확인.

-- 현재 슬레이브 상태와 마스터 상태


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
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
mysql> show master status;
+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000128 |  4186214 |              |                  |
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)
 
 
 
mysql> show slave status\G
 
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.30.101.158
                  Master_User: kimgn_test_repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000128
          Read_Master_Log_Pos: 4186214
               Relay_Log_File: kimgn-test-relay-bin.000230
                Relay_Log_Pos: 4186360
        Relay_Master_Log_File: mysql-bin.000128
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 4186214
              Relay_Log_Space: 4186564
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)
 
cs

 


 

-- 50,000건 데이터 입력후, 이전 포지션 값으로 변경 후 테스트 시작.

 

 


 

 

-- 해당 에러 해결을 위해 현재 문제가 된 값을 찾아 binlog open(의도적으로 수행 전으로 돌렸으므로 131번 오픈)

root@kimgn-splunk-test  /data/mysql_1/data

$ /mysql/bin/mysqlbinlog mysql-bin.000131 > ./test.sql

에러가 난 값은 1200001 이나, 현재 들어간 값까지 문제가 없다는 가정 하에 슬레이브의 PK 맥스값  검색

mysql> select max(id) fROM kimgn_test.kimgn_test;

+---------+

| max(id) |

+---------+

| 1250000 |

+---------+

1250000 에 해당하는 positon 탐색(파일의 위치 등은 시간을 통해 유추하나, 여기서는 131번으로 확인(변경 테스트 포지션은 볼드처리)

# at 5477845

#180103 16:14:58 server id 1 end_log_pos 5477872 Xid = 4247603

COMMIT/*!*/;

# at 5477872

#180103 16:14:58 server id 1 end_log_pos 5477954 Query thread_id=257606 exec_time=0 error_code=0

SET TIMESTAMP=1514963698/*!*/;

BEGIN

/*!*/;


# at 5477954

#180103 16:14:58 server id 1 end_log_pos 5477982 Intvar

SET INSERT_ID=1250000/*!*/;

# at 5477982

#180103 16:14:58 server id 1 end_log_pos 5478017 Rand

SET @@RAND_SEED1=22686107, @@RAND_SEED2=1027190506/*!*/;

# at 5478017

#180103 16:14:58 server id 1 end_log_pos 5478172 Query thread_id=257606 exec_time=0 error_code=0

SET TIMESTAMP=1514963698/*!*/;

INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())

/*!*/;

# at 5478172

#180103 16:14:58 server id 1 end_log_pos 5478199 Xid = 4247604

COMMIT/*!*/;



시나리오 : 현재 1250000 번까지 들어가 있으므로 1250000을 인서트 시도 후 에러가 나면 skip 후 정상 인서트 확인.(현재 데이터는 1300000까지 들어가 있음)




케이스 1 :  INSERT_ID를 지정하는 포지션인 5477954 로 지정

케이스 2 : INSERT_ID를 지정하는 포지션 중 end_pos로 지정되어 있는 5477982 로 지정

케이스 3 : BEGIN과 TIMESTAMP를 지정하는 5477872 로 지정


케이스 1 시나리오 결과

의도한 대로 원하는 곳에서 한번 더 STOP 발생




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
33
34
35
36
37
38
39
40
41
42
43
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.30.101.158
                  Master_User: kimgn_test_repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000134
          Read_Master_Log_Pos: 6770842
               Relay_Log_File: kimgn-test-relay-bin.000002
                Relay_Log_Pos: 253
        Relay_Master_Log_File: mysql-bin.000131
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 5477954
              Relay_Log_Space: 32753048
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)
cs


sql 스레드 스킵 후 데이터 확인 결과 원하는 대로 데이터 입력됨을 확인할 수 있었음.


케이스 2 시나리오 결과

의도한 대로 원하는 곳에서 한번 더 STOP 발생



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
33
34
35
36
37
38
39
40
41
42
43
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.30.101.158
                  Master_User: kimgn_test_repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000134
          Read_Master_Log_Pos: 6770842
               Relay_Log_File: kimgn-test-relay-bin.000002
                Relay_Log_Pos: 253
        Relay_Master_Log_File: mysql-bin.000131
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 5477954
              Relay_Log_Space: 32753048
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)
cs



sql 스레드 스킵(케이스 1의 경우 1회였으나, 케이스 2의 경우 2회) 후 데이터 확인 결과 skip 대상이었던 kimgn_test 테이블의 데이터가 1건 오입력됨을 확인할 수 있었음.


원인 분석 : 데이터 확인 결과, 최초 스킵한  1250001번의 데이터가 1250000번 의 데이터와 데이터가 일치함.


               즉, 앞에서 skip을 의도했던 INSERT구문이 수행 완료되었음을 확인할 수 있었음.


               추가적으로 앞에서 SKIP하려 했던 auto_increment값이 에러가 나도, 그 이후 값은 정상적으로 입력되는 것 확인.




--1. 마스터 서버의 데이터 : 1,300,000건

mysql> select * FROM kimgn_test order by id desc LIMIT 10;

+---------+----------+---------------------+

| id      | contents | date_val            |

+---------+----------+---------------------+

| 1300000 | 2        | 2018-01-03 18:02:29 |

| 1299999 | 32       | 2018-01-03 18:02:29 |

| 1299998 | 67       | 2018-01-03 18:02:29 |

| 1299997 | 72       | 2018-01-03 18:02:29 |

| 1299996 | 87       | 2018-01-03 18:02:29 |

| 1299995 | 65       | 2018-01-03 18:02:29 |

| 1299994 | 71       | 2018-01-03 18:02:29 |

| 1299993 | 54       | 2018-01-03 18:02:29 |

| 1299992 | 50       | 2018-01-03 18:02:29 |

| 1299991 | 66       | 2018-01-03 18:02:29 |

+---------+----------+---------------------+

10 rows in set (0.01 sec)

 

mysql> select * FROM kimgn_test order by id desc LIMIT 49995,10;

+---------+----------+---------------------+

| id      | contents | date_val            |

+---------+----------+---------------------+

| 1250005 | 7        | 2018-01-03 18:02:10 |

| 1250004 | 70       | 2018-01-03 18:02:10 |

| 1250003 | 2        | 2018-01-03 18:02:10 |

| 1250002 | 51       | 2018-01-03 18:02:10 |

| 1250001 | 40       | 2018-01-03 18:02:10 |

| 1250000 | 3        | 2018-01-03 16:14:58 |

| 1249999 | 37       | 2018-01-03 16:14:58 |

| 1249998 | 88       | 2018-01-03 16:14:58 |

| 1249997 | 14       | 2018-01-03 16:14:58 |

| 1249996 | 31       | 2018-01-03 16:14:58 |

+---------+----------+---------------------+

10 rows in set (0.02 sec)

 

--2. 슬레이브 서버의 데이터: 1,300,000건

 

mysql> select * FROM kimgn_test order by id desc LIMIT 10;

+---------+----------+---------------------+

| id      | contents | date_val            |

+---------+----------+---------------------+

| 1300000 | 2        | 2018-01-03 18:02:29 |

| 1299999 | 32       | 2018-01-03 18:02:29 |

| 1299998 | 67       | 2018-01-03 18:02:29 |

| 1299997 | 72       | 2018-01-03 18:02:29 |

| 1299996 | 87       | 2018-01-03 18:02:29 |

| 1299995 | 65       | 2018-01-03 18:02:29 |

| 1299994 | 71       | 2018-01-03 18:02:29 |

| 1299993 | 54       | 2018-01-03 18:02:29 |

| 1299992 | 50       | 2018-01-03 18:02:29 |

| 1299991 | 66       | 2018-01-03 18:02:29 |

+---------+----------+---------------------+

10 rows in set (0.00 sec)

 

mysql> select * FROM kimgn_test order by id desc LIMIT 49995,10;

+---------+----------+---------------------+

| id      | contents | date_val            |

+---------+----------+---------------------+

| 1250005 | 7        | 2018-01-03 18:02:10 |

| 1250004 | 70       | 2018-01-03 18:02:10 |

| 1250003 | 2        | 2018-01-03 18:02:10 |

| 1250002 | 51       | 2018-01-03 18:02:10 |

| 1250001 | 3        | 2018-01-03 16:14:58 |

| 1250000 | 3        | 2018-01-03 16:14:58 |

| 1249999 | 37       | 2018-01-03 16:14:58 |

| 1249998 | 88       | 2018-01-03 16:14:58 |

| 1249997 | 14       | 2018-01-03 16:14:58 |

| 1249996 | 31       | 2018-01-03 16:14:58 |

+---------+----------+---------------------+

10 rows in set (0.01 sec)




케이스 3 시나리오 결과

의도한 대로 원하는 곳에서 한번 더 STOP 발생



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
33
34
35
36
37
38
39
40
41
42
43
44
 
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.30.101.158
                  Master_User: kimgn_test_repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000134
          Read_Master_Log_Pos: 6770842
               Relay_Log_File: kimgn-test-relay-bin.000002
                Relay_Log_Pos: 253
        Relay_Master_Log_File: mysql-bin.000131
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 5477954
              Relay_Log_Space: 32753048
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1250000' for key 'PRIMARY'' on query. Default database: 'kimgn_test'. Query: 'INSERT INTO kimgn_test (contents,date_val) VALUES ( CEILING(RAND()*100),now())'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
1 row in set (0.00 sec)
cs

sql 스레드 스킵 후 데이터 확인 결과 원하는 대로 데이터 입력됨을 확인할 수 있었음.




추가 테스트 사항, UPDATE시 결정 값이 고정적이지 않을 때 SBR에서 두번 실행되지 않을까?

상기의 케이스에서 , UPDATE하려는 칼럼의 값이 기존 값에서 계산하는 형식이라면, 해당 명령이 두번 수행되어 마스터와 슬레이브 노드의 데이터가 일치하지 않지 않을지 확인




테스트 시나리오


PK 데이터 입력

UPDATE 구문 수행(UPDATE test_temp SET info= info + 1 where id=1)\

PK 데이터 입력

슬레이브 포지션 1 이전의 상태로 복원

set global sql_slave_skip_counter=1; 문장을 이용해 sync 동기화



테스트 결과 

  상기와 같은 결과값이 일정하지 않은 쿼리 또한 반영하여 처리하는 것으로 보임. 해당 쿼리를 포함한 binlog 값을 변경하였음에도 불구하고 계속적으로 test_temp 테이블의 info 칼럼의 값이 일치하는 것을 확인할 수 있었음




결론

begin에 해당하는 at ... 번호를 찍는 것이 가장 좋을 것으로 보임


end_log_pos는 해당 명령을 수행하고 난 후의 포지션을 의미하기 때문에,


실제 포지션은 명령 이전에 존재하는 # at 포지션번호 임.




# at 5477872

#180103 16:14:58 server id 1 end_log_pos 5477954 Query thread_id=257606 exec_time=0 error_code=0

SET TIMESTAMP=1514963698/*!*/;

BEGIN




저작자표시 비영리 동일조건