CDC 커넥터가 RUNNING인 채 5분 동안 아무것도 보내지 않았다
목차
DB 연결을 5분 동안 막았는데 Kafka Connect는 커넥터 상태를 내내 RUNNING으로 답했습니다. 상태만 보는 감시였다면 5분을 통째로 놓쳤을 겁니다. 커넥터가 주기적으로 찍는 하트비트의 나이를 함께 보자, 막은 지 39초 만에 60초를 넘겨 잡았습니다. 커넥터를 멈추는(pause) 장애는 반대로 상태 지표가 11초 만에 잡았습니다. 두 지표가 서로 다른 장애를 잡습니다.
개요
이 쇼핑몰은 데이터베이스 변경 로그를 읽어 Kafka로 흘리는 CDC(Change Data Capture) 커넥터를 두 개 씁니다. 하나는 사용자 활동을 개인화 컨텍스트로, 하나는 상품·재고 변경을 검색 색인으로 나릅니다(ch46). 커넥터를 감시하는 것은 없었습니다.
예전에 커넥터가 RUNNING인 채 안에서 재시작만 반복하던 일이 있었습니다. 그때도 상태만 보면 정상이었습니다. 그리고 변경이 빨리 반영되도록 커넥터의 poll.interval.ms를 500에서 100으로 줄였는데 그 대가(커넥터와 DB 부하)는 재지 않았습니다. 이 글은 그 둘을 쟀습니다.
poll.interval.ms 100의 비용
검색 색인용 커넥터 하나로, poll 값만 바꿔 다시 등록하며 쟀습니다. 조용한 구간 60초와 상품 가격을 초당 50건 바꾸는 구간 60초에서 Connect와 MySQL 컨테이너의 CPU를 2초마다 찍었습니다. 지연은 DB 커밋 시각부터 Kafka 레코드 시각까지입니다. 컴파일이 겹쳤을 수 있는 첫 회차도 버리지 않았습니다. 대신 아무것도 안 돌리는 상태에서 한 번 더 쟀습니다.
| poll.interval.ms | Connect CPU 조용 | Connect CPU 변경 중 | MySQL CPU 변경 중 | 지연 p95 |
|---|---|---|---|---|
| 100 | 2.5 · 3.0% | 7.7 · 10.0% | 8.5 · 8.1% | 97ms |
| 500 | 1.5 · 1.6% | 5.7 · 7.5% | 9.6 · 9.1% | 478ms |
| 1000 | 1.1 · 1.3% | 2.8 · 4.0% | 9.7 · 9.5% | 953ms |
CPU는 두 회차 값이고 100%가 한 코어입니다. poll 100은 500보다 Connect CPU를 조용할 때 1.0~1.4%p, 변경 중에 2.0~2.5%p 더 썼습니다. 측정 전에 정한 기준(5%p 미만)을 넘지 않아 100을 유지했습니다.
MySQL CPU는 poll 값과 상관이 없었습니다. 커넥터는 DB를 폴링하지 않고 binlog를 흘려받습니다. poll.interval.ms는 커넥터 안의 큐를 몇 ms마다 비우는가라서 비용이 Connect에만 생깁니다. 지연은 p50이 poll의 절반, p95가 poll 값에 거의 정확히 맞았습니다.
떠 있는지와 흐르는지
앱에 감시 컴포넌트를 붙여 지표 두 개를 냈습니다.
- 상태: Connect REST API에서 커넥터와 모든 태스크가 RUNNING이면 1
- 흐름: 커넥터의 하트비트 토픽에 마지막 레코드가 찍힌 뒤 지난 초
하트비트를 켜면서 예상한 문제가 하나 있었습니다. 두 커넥터 모두 모든 레코드를 한 토픽으로 보내고 값에서 키를 만드는 변환을 씁니다. 하트비트 레코드에는 그 필드가 없어서 그대로 켜면 데이터 토픽에 섞이고 키 변환에서 깨집니다. 변환에 “데이터 토픽일 때만” 조건을 붙이고 데이터 레코드가 그대로 나가는 것을 확인했습니다.
알림 문턱을 정하기 전에 확인한 것도 있습니다. 하트비트는 10초로 설정했는데 DB가 완전히 조용할 때는 약 48~49초 간격으로 왔습니다. 10초 간격은 binlog 이벤트를 처리할 때의 값이었습니다. 그래서 “하트비트 나이 60초 초과가 2분 지속”을 알림 조건으로 잡았습니다.
장애를 넣어 본 결과
커넥터를 toxiproxy 뒤의 MySQL에 붙이고 5초마다 지표와 Connect 상태를 찍었습니다.
| 구간 | Connect 상태 | 상태 지표 | 하트비트 나이 |
|---|---|---|---|
| 조용함 150초 | RUNNING | 1 | 최대 51초(오탐 없음) |
| DB 연결을 5분 막음 | 내내 RUNNING | 내내 1 | 39초 뒤 60초 초과 |
| 막힘을 풂 | RUNNING | 1 | 39초 뒤 회복 |
| 커넥터 pause | PAUSED | 11초 뒤 0 | 61초 뒤 60초 초과 |
연결을 막는 동안 커넥터 로그에는 약 58초 뒤부터 binlog 클라이언트가 약 70초 간격으로 재연결을 시도한 기록만 남았습니다. 예전에 겪은 “RUNNING인데 안에서 재시작만 도는” 모양과 같습니다.
정리
- poll 100을 유지합니다. 비용은 Connect에만 생기고 한 코어의 몇 %p입니다
- 상태는 pause와 실패를, 하트비트 나이는 RUNNING인데 흐르지 않는 경우를 잡습니다. 이번에 넣은 장애 둘은 어느 한 지표만으로는 다 잡히지 않았습니다
- 조용할 때 하트비트 최대 나이가 51초라 문턱 60초와의 여유가 9초뿐입니다. 조용할 때 간격을 무엇이 정하는지는 확인하지 못했습니다
- 막힘은 toxiproxy로 만든 것입니다. 예전 장애와 같은 경로인지는 모릅니다. 같은 것은 “상태는 RUNNING, 흐름은 없음”이라는 겉모습입니다
댓글
댓글 수정/삭제는 GitHub Discussions에서 가능합니다.