.png&blockId=39ef240a-d85e-4c3a-83eb-7706adb34b8b){kind=logo}
.png&blockId=326e7fe2-1a62-441d-9a59-038c3fb561ac&width=3600)
여러분의 마음을 사로잡을(?) 썸네일 이미지
소개
안녕하세요, 라포랩스 서버 플랫폼 팀의 지수환입니다. 이번 글에서는 데이터베이스의 CPU 사용률이 간헐적으로 튀는 문제를 해결한 경험에 대해 이야기를 나눠 보려고 합니다.
목차
.png&blockId=30aefbeb-41d8-4d19-be3f-c261013df28a)
2022년 여름의 어느 날, 자고 일어났더니 메인 DB의 CPU 사용률이 80%가 넘었다는 알림이 슬랙에 남아 있었습니다. 메트릭을 확인해 보니, 메인 DB 인스턴스 한 대의 CPU 사용률이 약 80% 선에서 12분 정도 유지되다가 다시 정상적인 패턴으로 돌아갔습니다. 퀸잇 서비스에서 DB의 CPU 사용률은 일반적으로 트래픽에 비례하는 패턴을 그리는데, 알람이 울린 시점에는 지표 상 트래픽이 튀지 않았습니다. 따라서 DB의 CPU 사용률이 높아진 현상이 트래픽 증가에 따른 결과라고 보기는 어려웠습니다.
트래픽과는 독립적인 이유로 DB의 CPU 사용률이 높게 유지된 것이라면, 트래픽이 높은 시점에 이 현상이 트리거될 경우 서비스 장애로 이어질 수 있다고 판단했습니다. 따라서 팀 내에서 우선순위를 높여서 이 현상의 원인을 파악하기 시작했습니다.
시스템 메트릭 확인
DB의 CPU 사용률이 비정상적으로 높았다는 것은, 어딘가 DB에 부하를 주는 시스템 요소가 있었다는 의미입니다. 이 시스템 요소를 식별하기 위해 두 가지를 확인해 보았습니다.
첫 번째는 pod의 network I/O rate 메트릭입니다. DB의 부하를 주는 시스템 요소는 DB와의 네트워크 통신량이 많을 가능성이 높고, 이는 pod의 network I/O rate 메트릭을 통해 쉽게 확인할 수 있습니다. 확인 결과, DB의 CPU 사용률이 튄 시점과 정확히 맞물려서 debezium connect pod의 network received bytes가 약 200~400 MiB/s로 매우 높게 유지되었습니다.
사진 1. DB의 CPU 사용률이 튄 당시의 debezium connect pod의 network I/O rate 그래프.
debezium은 다양한 데이터베이스에 대해 Change Data Capture(CDC)를 하기 위한 플랫폼으로, 보다 자세한 설명은 debezium 공식 문서에서 찾아보실 수 있습니다.
두 번째는 AWS에서 제공하는 RDS performance insight입니다. Performance insight 기능을 활용하면 어떤 쿼리가 어느 정도의 부하를 발생시켰는지 쉽게 확인할 수 있습니다. 확인 결과, SHOW BINARY LOGS라는 쿼리가 대부분의 부하를 발생시키고 있었습니다. 라포랩스에서는 메인 DB로 Amazon Aurora MySQL를 사용하고 있는데, MySQL에 대해 debezium을 사용할 경우 debezium은 DB가 생성하는 binlog를 읽어들여 kafka record로 변환합니다. 이러한 동작 원리를 고려했을 때, debezium connect pod이 binlog를 많이 읽는 것은 충분히 가능한 시나리오였습니다.
이 두 가지 지표를 기반으로, DB에 부하를 준 범인을 debezium connect pod으로 좁혔습니다.
debezium 관련 정보 확인
다음은 debezium connect pod이 DB에 과도한 부하를 발생시킨 이유를 알아낼 차례입니다. 이를 위해 debezium connect pod의 로그와 메트릭을 확인하고, debezium connector의 설정을 검토해 보았습니다. 그 결과, 세 가지의 특이사항을 발견했습니다.
•
debezium connector의 재시작 - 조사 결과 과거에도 동일한 현상이 1주~1달 정도의 불규칙한 간격으로 발생하고 있었는데, 이 때마다 connector가 재시작되었다는 로그가 찍혀 있었습니다.
•
MillisecondsBehindSource - 라포랩스 서버 플랫폼팀은 debezium의 내부 동작과 관련된 다양한 메트릭을 JMX를 통해 수집하고 있습니다. 이 중 MillisecondsBehindSource라는 메트릭이 DB의 CPU가 튄 기간 동안 이상한 패턴을 보였습니다(사진 2).
사진 2. DB의 CPU 사용률이 튄 당시의 debezium connector의 MillisecondsBehindSource 메트릭 그래프.
debezium 공식 문서에 따르면, MillisecondsBehindSource 메트릭의 정의는 다음과 같습니다.
The number of milliseconds between the last change event’s timestamp and the connector processing it. The values will incoporate any differences between the clocks on the machines where the database server and the connector are running.
요약하면 MillisecondsBehindSource 메트릭은 [binlog 이벤트 생성 시각] ~ [debezium connector가 해당 binlog 이벤트를 처리한 시각] 사이의 시간차로, 오래된 binlog 이벤트를 처리할수록 값이 커집니다. 즉, 사진 2의 메트릭 그래프에 따르면 DB의 CPU 사용량이 튀었을 때, debezium connector는 꽤 오래 전의 binlog를 읽어들여 처리했다고 해석할 수 있습니다.
•
snapshot mode - debezium은 평상시에는 binlog를 읽어들여 CDC를 처리하지만, 최초 실행 등의 상황에서는 현재 적재되어 있는 데이터의 snapshot을 찍고 kafka record로 넣는 snapshot 동작을 수행합니다. 이때 snapshot mode 옵션을 통해 debezium이 언제 snapshot 동작을 수행할지를 조절할 수 있습니다. snapshot과 snapshot mode에 대한 보다 자세한 설명은 debezium 공식 문서에서 찾아보실 수 있습니다.
퀸잇 서비스의 경우 initial과 when_needed snapshot mode를 섞어서 사용하고 있는데, 과거에 동일한 문제를 발생시킨 connector는 모두 snapshot mode가 when_needed였습니다.
원인 파악 - binlog position이 제대로 기록되지 않는다
세 가지 특이사항으로부터 자연스럽게 도출된 가설은 ‘snapshot mode가 when_needed인 debezium connector의 재시작이 문제의 원인일 것이다’라는 가설이었습니다. 구체적으로, snapshot mode가 when_needed인 connector를 재시작하면 binlog를 대량으로 읽는 시나리오가 있을 것이라고 추측했습니다.
하지만 며칠간 집중하여 조사를 해도 위 가설과 들어맞는 근거를 찾을 수 없었습니다. 인터넷을 통해 debezium을 사용 중 유사한 문제를 겪은 케이스가 있는지 조사했지만, 비슷한 케이스는 없었습니다. 수집한 메트릭과 로그를 전수조사해도 위에서 언급한 3가지의 특이사항 외의 새로운 점을 발견하지 못했습니다. 결국 debezium의 소스 코드를 다운 받아서 snapshot mode가 when_needed일 때 debezium connector가 어떻게 동작하는지를 조사해 보았는데, binlog를 대량으로 읽어들일만한 시나리오를 찾지 못했습니다.
며칠 동안 조사에 진전이 없고, 심지어 소스 코드에서도 별다른 문제점을 찾지 못하자, when_needed snapshot mode가 문제의 원인이라는 가설이 잘못되었을 수 있다는 생각이 들었습니다. 그래서 해당 가설을 버리고, 혹시 놓친 정보가 있을까봐 밑바닥부터 다시 조사하기 시작했습니다. 이번에는 가설을 세우지 않은 중립적인 상태로 로그와 메트릭을 신중히 재확인했습니다.
그 결과, 문제가 발생한 시점 근처의 debezium connect pod의 로그를 정독하는 과정에서 수상한 로그 하나를 발견했습니다.
Found previous partition offset io.debezium.connector.mysql.MySqlPartition@7b4fc813: MySqlOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.mysql.Source:STRUCT}, sourceInfo=SourceInfo [currentGtid=null, currentBinlogFilename=mysql-bin-changelog.013817, currentBinlogPosition=107847249, currentRowNumber=0, serverId=0, sourceTime=null, threadId=-1, currentQuery=null, tableIds=[], databaseName=null], snapshotCompleted=false, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0], restartGtidSet=null, currentGtidSet=null, restartBinlogFilename=mysql-bin-changelog.013817, restartBinlogPosition=107847249, restartRowsToSkip=0, restartEventsToSkip=0, currentEventLengthInBytes=0, inTransaction=false, transactionId=null, incrementalSnapshotContext =IncrementalSnapshotContext [windowOpened=false, chunkEndPosition=null, dataCollectionsToSnapshot=[], lastEventKeySent=null, maximumKey=null]] [io.debezium.connector.common.BaseSourceTask]
Plain Text
복사
수상한 부분은 restartBinlogFilename=mysql-bin-changelog.013817이라는 내용이었습니다. 변수명으로 추측하기에 이는 connector가 재시작될 때 읽기 시작하는 binlog의 파일명으로 보였습니다. 이 파일명에 해당하는 binlog를 조회해보니, 해당 binlog는 connector의 재시작 시점보다 며칠 전에 기록된 binlog였습니다. 즉, connector가 재시작될 때 가장 최신 binlog가 아니라 며칠 전의 binlog부터 읽어들인 것입니다. 이는 DB에 부하가 발생한 기간 동안 대량의 SHOW BINARY LOGS가 발생한 것과 잘 맞아 떨어지는 정보였습니다.
문제는, connector가 재시작될 때 최신 binlog가 아닌 며칠 전의 binlog부터 읽는 이유가 전혀 짐작되지 않았습니다. connector가 재시작되는 경우 자신이 마지막으로 읽은 지점부터 binlog를 다시 읽기 시작할 텐데, 문제를 발생시킨 connector는 새로 만들어진 것이 아니라 계속 동작 중이어서 이미 가장 최신 binlog를 읽고 있는 상태였습니다. 사진 2에서 재시작 직전까지 MillisecondsBehindSource 메트릭이 매우 낮게 유지되는 것이 그 증거입니다.
하지만 실제로 connector의 상태 저장소를 확인해 보니, MillisecondsBehindSource 지표와는 상반되게 과거의 binlog position이 기록되어 있었습니다(사진 3).
사진 3. 문제를 일으킨 connector의 상태가 저장된 Kafka topic. 가장 마지막으로 읽은 binlog position이 mysql-bin-changelog.013817의 107847249임을 확인할 수 있다.
처음에는 connector의 상태가 제대로 기록되지 않고 누락된 것이 아닐까 의심했습니다. 하지만 팀원들과 이 문제에 대해 논의하던 도중, 위 connector가 추적하는 테이블은 변경이 매우 적다는 이야기를 전해 들었습니다. 이 정보를 들으니, connector가 마지막으로 읽은 binlog 위치를 상시로 기록하는 것이 아니라 connector가 추적하는 테이블에 변경사항이 있을 때만 기록할 수도 있겠다는 생각이 들었습니다. 데이터를 확인해 보니, 사진 3의 상태가 기록된 시각과 product_category 테이블의 가장 최신 row가 적힌 시간이 동일했습니다. 동일한 현상을 일으킨 다른 connector들에 대해서도 마찬가지였습니다.
위와 같은 논의 및 관찰을 바탕으로, debezium이 connector의 상태를 기록하는 시점은 해당 connector가 추적하는 테이블에 변화가 있을 때이고, 이로 인해 변경이 잦지 않은 테이블을 추적하는 connector가 재시작되는 경우 대량의 binlog를 읽게 된다는 결론을 내렸습니다.
해결 - heartbeat.interval.ms 옵션
DB의 CPU 사용률이 튀는 메커니즘은 파악했으니, 이제 문제를 해결하는 일만 남았습니다. 문제가 되는 connector가 추적하는 테이블은 앞으로도 변경이 잦지 않을 테니, 추적하는 테이블에 변경이 발생하지 않더라도 debezium이 connector의 상태를 기록하게 하는 방법이 필요했습니다. 이를 쉽게 할 수 있는 방법이 있는지 확인하기 위해, debezium의 소스 코드를 다시 한 번 분석하여 debezium이 connector의 상태를 기록하는 시점을 파악했습니다. 코드 분석 결과, heartbeat.interval.ms 옵션을 제공하면 옵션으로 제공된 주기마다 debezium이 connector의 상태를 기록하는 것을 알 수 있었습니다.
Controls how frequently the connector sends heartbeat messages to a Kafka topic. The default behavior is that the connector does not send heartbeat messages.
Heartbeat messages are useful for monitoring whether the connector is receiving change events from the database. Heartbeat messages might help decrease the number of change events that need to be re-sent when a connector restarts. To send heartbeat messages, set this property to a positive integer, which indicates the number of milliseconds between heartbeat messages.
heartbeat.interval.ms 옵션을 제공하여 connector를 재배포하고, 예상한대로 문제가 해결되었는지 지속적으로 모니터링했습니다. 마지막으로 읽은 binlog position이 Kafka topic에 주기적으로 기록되는 것을 확인했고, MillisecondsBehindSource 메트릭과 DB의 CPU 사용량이 간헐적으로 튀는 현상 역시 이 글을 적고 있는 현재까지 발생하지 않았습니다.
무엇을 배웠나?
이번 문제 해결 과정은 debezium에 대한 이해도를 높일 수 있었던 기회이기도 하지만, 제게는 애플리케이션 로직 범위를 벗어난 문제를 깊게 분석한 첫 번째 경험이라는 점에서 더 뜻깊은 기회였습니다. 글에는 다 담지 못한 다양한 삽질을 하는 과정에서 많은 것을 배울 수 있었습니다.
상관관계를 인과관계로 착각하지 말자
글 중간에서 언급한 debezium 관련 특이사항 3개를 다시 돌아보면, snapshot mode과 관련된 점은 문제의 원인이 아니라 그저 문제와 상관관계가 있을 뿐이었습니다. 문제를 일으킨 connector의 snapshot mode가 모두 when_needed로 설정된 이유는 도메인 로직상 해당 테이블의 사이즈가 작아서 snapshot을 뜨는 것에 대한 부담이 거의 없다시피 했기 때문입니다. 즉, snapshot mode가 when_needed인 것(= 관찰 결과 A)과 DB의 CPU 사용량이 튄 것(= 현상 B)은 '테이블의 변경이 잦지 않다'라는 공통된 원인에서 파생된 결과였습니다. 하지만 저는 A와 B의 관찰 결과를 보고 A가 B의 원인이라고 착각했고, 존재하지 않는 인과관계를 증명할 증거를 찾기 위해 며칠을 낭비했습니다.
이러한 시간 낭비를 통해, 서로 관련 있어 보이는 패턴이 인과관계를 가질 것이라는 확신은 명확한 증거 없이는 해서는 안 된다는 것을 배웠습니다.
성급하게 결론을 내리지 말자
조사 과정에서 저지른 또 다른 실수는 결론을 내린 채로 조사를 진행했다는 점입니다. 결론을 내려놓고 이에 대한 근거를 찾으려고 하니, 내린 결론과 무관해 보이는 정보를 무의식 중에 필터링하고 있었습니다. 중립적인 태도로 조사를 수행했다면 첫 번째 조사 사이클에서 restartBinlogFilename이 포함된 로그를 바로 발견할 수 있었을 것입니다.
특정 가설을 올바르다고 단정지을 때는 더 신중해야 하고, 아직 확신할 만한 증거가 부족하다면 특정 가설에 매몰되지 않고 다양한 가능성을 열어놓은 채로 문제에 접근해야 함을 배웠습니다. 물론 특정 생각에 매몰되지 않는 것은 매우 어려운 일입니다. 문제 원인을 정확하게 이해하고 있는 현재는 when_needed snapshot mode 가설이 근거가 부족해 보이지만, 당시 가지고 있던 지식으로는 해당 가설을 떠올리자마자 '와 이거다!' 하면서 모든 퍼즐이 맞춰지는 듯했습니다. 하지만 이전과는 달리 '정말 확실해?' 라고 기계적으로 자문하고, 자신의 확신을 견제할 수 있는 소중한 경험을 하나 얻었다고 생각합니다.
공식 문서를 잘 활용하자
debezium의 소스 코드를 열심히 뒤적거리며 찾았던 heartbeat.interval.ms 옵션은, 사실 이미 debezium 공식 문서에 언급되어 있던 것이었습니다. 심지어 옵션의 설명에 'Heartbeat messages might help decrease the number of change events that need to be re-sent when a connector restarts', 즉 heartbeat 메세지를 보내면 connector의 재시작 시 다시 처리해야 하는 이벤트의 수를 줄이는 데 도움을 준다는 내용까지 언급되어 있습니다. 이미 원인 분석을 위해 debezium의 소스 코드를 분석하고 있어서 해결법을 찾기 위해서도 관성적으로 소스 코드부터 파헤쳤는데, 공식 문서를 잘 활용했다면 문제 해결에 걸린 시간을 며칠 단축할 수 있었을 것입니다.
특정 기술을 사용하기 위해 공식 문서를 완독해야 하는 것은 아니지만, 찾고자 하는 정보가 명확한 경우 공식 문서가 좋은 레퍼런스가 될 수 있음을 배웠습니다.
가시성을 확보하는 것이 중요하다
마지막으로, 가장 크게 배운 점은 운영하는 시스템 요소에 대한 가시성 확보가 중요하다는 것이었습니다. Performance insight 없이는 DB의 CPU를 많이 사용하는 행동이 binlog를 읽는 것임을 파악하기 어려웠을 것이고, 로그와 메트릭을 수집 및 보관하는 파이프라인과 검색할 수 있는 시스템이 갖춰져 있지 않았다면 원인을 파악하는 데 결정적인 역할을 한 정보들을 찾지 못했을 것입니다. 또한 Kafka에 저장된 record를 쉽게 조회할 수 있는 시스템이 이미 갖춰져 있던 덕분에 connector의 상태로 저장되어 있는 binlog position이 상당히 오래된 위치임을 빠르게 확인할 수 있었습니다. 이 시스템 중 하나라도 빠졌다면 문제 해결이 느려지는 것뿐만 아니라 원인 파악 자체가 불가능했을 수도 있습니다.
시스템 요소에 대한 가시성 확보는 운영 단계에서 발생하는 다양한 문제를 해결하기 위한 핵심입니다. 이미 문제가 터진 이후에 가시성을 확보하는 것은 이미 발생한 문제 해결에는 도움이 되지 않기 때문에, 합리적인 비용을 부담하는 선에서 최대한의 가시성을 선제적으로 확보하는 것이 중요함을 배웠습니다.
마치며
CDC 기술은 데이터 파이프라인 구성이나 CQRS 설계 등 데이터의 이동이 필요한 다양한 상황에서 활용하기 적합한 도구입니다. 하지만 debezium은 동작 원리 상 이번 글에서 소개 드린 케이스처럼 특정 시나리오에서 과도한 DB 부하를 발생시킬 수 있습니다. 따라서 debezium을 사용하는 경우, debezium의 이상 동작을 감지하고 문제가 발생했을 때 쉽게 분석할 수 있도록 가시성을 확보하는 것이 필요합니다. 단순히 DB 지표를 수집하는 것 외에도 debezium의 로그와 debezium이 JMX로 노출하는 메트릭을 수집하고, kafka에 저장된 debezium의 상태를 확인할 수 있는 어드민을 구축하면 debezium을 운영하는 데 큰 도움이 될 것입니다.
감사합니다.
Reference
지수환 Jee Suhwan
라포랩스 서버 플랫폼팀 리드 : 서버 엔지니어
“새로운 경험과 몰입, 성취를 좋아합니다.”
빠르게 성장하는 서비스를 개발하고 운영하는 경험에 함께 하고 싶으시다면?
Update : 2023.03.16.
2020 Rapport Labs Inc. All rights reserved.