평균 CPU는 여유로운데, 커밋은 왜 느릴까?
안녕하세요. 토스증권 DBA Team 조규범입니다.
주문과 체결을 처리하는 API 뒤에는 Oracle DB가 있습니다. 이 DB에서 커밋이 늦어지면 커밋을 기다리던 세션이 모두 함께 멈추고, API 응답도 그만큼 늦어지는데요. 거래가 몰리는 정규장 시간에는 짧은 지연도 그냥 넘기기 어렵습니다.
그런데 어느 날부터 커밋 대기가 0.1초 넘게 이어지는 현상이 반복해서 보이기 시작했습니다. 스토리지, OS, 네트워크, 애플리케이션, Oracle을 차례로 확인했지만 평균 지표는 모두 정상 범위였어요. 호스트 CPU에도 여유가 있었고요.
원인은 CPU 소켓 하나에 몰려 있던 NIC 인터럽트였습니다. 인터럽트를 두 소켓으로 나누자 0.1초 이상의 커밋 대기는 대부분 개선됐고, 같은 조치를 적용한 다른 Oracle RAC에서는 동시접속자가 28% 많은 날에도 개장 직후 10분간 CPU 사용률이 36.6%에서 17.4%로 내려왔습니다. 이번 글에서는 평균 지표 뒤에 가려져 있던 병목을 어떻게 찾았는지, 그리고 왜 설정이 아니라 하드웨어 배치를 바꿔야 했는지 공유하려고 합니다.
평균 지표로는 보이지 않던 지연
커밋은 무엇을 기다릴까
Oracle에서 트랜잭션을 커밋하면, 변경 내용을 담은 리두 로그가 디스크에 기록된 뒤에야 커밋이 완료됩니다. 리두 로그 기록은 LGWR(log writer)라는 백그라운드 프로세스가 전담하는데요. 세션은 LGWR가 기록을 마칠 때까지 기다리고, 이 시간은 log file sync라는 대기 이벤트로 확인할 수 있습니다.
인스턴스의 커밋 기록은 모두 LGWR를 거칩니다. 그래서 LGWR가 잠깐만 밀려도 그사이 커밋한 세션이 모두 함께 기다리게 되죠. 저희가 본 현상도 이것이었습니다. log file sync 대기가 0.1초 이상 이어지는 일이 반복됐어요.
지연은 특정 CPU에서만 생겼습니다
다섯 개 레이어를 모두 점검했지만 특이 사항은 없었습니다. 평균으로 보면 전부 정상 범위였기 때문입니다. 지연이 간헐적으로 생기다 보니 평균에 묻혔을 수 있다고 보고, LGWR 프로세스를 더 잘게 들여다보기로 했습니다.
pidstat으로 LGWR가 어느 CPU에서 실행되는지 기록해 보니 규칙이 보였습니다. 지연은 아무 때나 생기지 않았고, LGWR가 28번 CPU에서 실행될 때만 생기고 있었습니다.
같은 프로세스가 같은 일을 하는데 실행되는 CPU에 따라 결과가 다르다면, 원인은 Oracle보다 아래쪽인 OS나 하드웨어에 있을 가능성이 큽니다. 28번 CPU에서 LGWR 말고 다른 무언가가 함께 처리되고 있다는 뜻이니까요.
소켓 하나에 몰린 NIC 인터럽트
CPU별 인터럽트 확인하기
먼저 서버 구성을 짚고 가겠습니다. 이 서버에는 CPU 소켓 4개에 소켓당 물리 코어가 8개씩, 모두 32개의 물리 코어가 있습니다. 하이퍼스레딩을 켜 두어 OS에서는 논리 CPU 64개로 보이는데요. 아래에서 볼 /proc/interrupts의 CPU 0–31은 물리 코어 스레드, 32–63은 하이퍼스레딩으로 생긴 논리 스레드입니다.
/proc/interrupts는 CPU별로 처리한 인터럽트 수를 장치마다 누적해서 보여 줍니다. 30초 간격으로 두 번 읽어 차이를 구하면, 그사이 각 CPU가 어떤 장치의 인터럽트를 얼마나 처리했는지 알 수 있습니다. 별도 도구 없이 cat 두 번이면 되는 방법이에요.
숫자가 특정 열에만 쌓여 있다면, 그 큐의 인터럽트를 해당 CPU 하나가 전담하고 있다는 뜻입니다. 확인해 보니 NIC 인터럽트가 물리 코어 32개 중 8개에만 몰려 있었습니다. 논리 CPU로 세면 64개 중 16개입니다. 그런데 물리 코어 8개는 정확히 소켓 하나 분량이었어요. NIC 처리가 사실상 소켓 하나에서만 이뤄지고 있었던 거죠.
가장 바쁜 두 작업이 같은 코어에서
인터럽트를 처리하는 코어는 저마다 특정 NIC 포트의 큐를 하나씩 맡고 있었습니다. 그중 트래픽이 가장 많은 Oracle RAC 인터커넥트 포트의 인터럽트는 몇몇 코어에 더 집중돼 있었고요. 이슈 당시 따로 추적했을 때 LGWR 지연이 생기던 28번 CPU도 이렇게 인터럽트를 전담하던 코어 중 하나였습니다.
RAC 인터커넥트는 두 노드가 캐시 블록을 주고받는 경로라, 클러스터에서 가장 바쁜 네트워크 경로입니다. LGWR 역시 DB에서 가장 바쁜 프로세스 중 하나고요. 이 두 작업이 같은 코어를 두고 경합하고 있었습니다.
왜 하필 소켓 하나였을까
하드웨어가 정해 둔 자리
이 서버는 소켓 4개가 각각 하나의 NUMA 노드를 이룹니다. 그리고 각 NIC 포트는 물리적으로 특정 소켓 하나에 연결되도록 설계돼 있는데요. NIC를 어느 슬롯에 꽂느냐에 따라, 그 포트의 인터럽트를 처리할 소켓이 정해지는 셈입니다.
여기에 인터커넥트 NIC 2장은 Active-Standby 본딩으로 묶여 있었습니다. 이중화를 위해 두 장을 묶었지만, 평소에는 활성 포트 하나로만 트래픽이 흐르는 방식입니다. 결국 인터커넥트 트래픽과 그 인터럽트가 모두 활성 포트가 연결된 소켓 하나로 몰렸습니다.
인터럽트가 커밋을 늦추는 과정
NIC 인터럽트는 일반 프로세스보다 먼저 처리됩니다. LGWR가 하필 이 소켓의 코어에서 실행되고 있을 때 패킷이 도착하면, 다음과 같은 일이 벌어집니다.
- 상대 노드에서 패킷이 도착합니다.
- NIC가 인터럽트를 발생시킵니다.
- 커널이 실행 중이던 LGWR를 멈추고, 같은 코어에서 인터럽트를 먼저 처리합니다.
- 그만큼 리두 로그 기록이 밀립니다.
- 커밋을 기다리던 세션이 모두 함께 기다립니다.
한 번 밀리는 시간은 아주 짧습니다. 하지만 트래픽이 몰리는 구간에는 이 일이 계속 반복되면서 커밋 대기가 눈에 띄게 길어질 수 있습니다. 호스트 전체의 CPU에 여유가 있어도, 코어 하나가 바쁘면 그 코어에서 실행되는 프로세스는 기다려야 하는 거죠.
인터럽트를 두 소켓으로 나누기
해결 방법으로 세 가지를 검토했습니다.
먼저 irqbalance로 인터럽트를 다시 분배해 보려 했습니다. 하지만 이 장비에서는 NIC 큐와 CPU의 매핑 제약 때문에 설정이 적용되지 않았고, 인터럽트는 여전히 같은 코어에 몰려 있었습니다.
다음으로는 taskset으로 LGWR를 다른 소켓의 CPU에 고정하는 방법을 생각했습니다. 인터럽트를 피해 LGWR를 옮기는 방식인데요. Oracle을 기동할 때마다 수동으로 설정해야 해서, 운영하다 보면 놓치기 쉽다고 판단했습니다.
마지막은 하드웨어 배치를 바꾸는 방법이었습니다. 인터커넥트 NIC 2장을 서로 다른 소켓에 연결된 슬롯으로 옮기고, 본딩을 Active-Active로 바꿔 두 포트를 동시에 쓰는 겁니다. 이렇게 하면 인터럽트가 자연스럽게 두 소켓으로 나뉘고, 기동할 때마다 챙길 설정도 남지 않습니다. 저희는 이 방법을 선택했습니다.
무엇이 달라졌을까
인터럽트는 실제로 나뉘었을까
같은 피크 시간대에 다시 스냅샷을 떠 보니, 초당 1,000건 넘게 인터럽트를 처리하는 물리 코어가 8개에서 15개로 늘었습니다. 논리 CPU로는 16개에서 31개입니다. 소켓 하나 분량이던 처리가 두 소켓 가까이로 나뉜 셈이죠.
인터럽트가 소수의 코어에 얼마나 몰려 있는지는 Gini 계수로 확인했습니다. 1에 가까울수록 몇몇 코어에 집중됐다는 뜻인데요, 0.80에서 0.67로 낮아졌습니다.
CPU 사용률
같은 조치를 적용한 다른 RAC에서 개장 구간을 비교해 봤습니다. 프로그램은 바뀌지 않았고, 비교한 날은 오히려 동시접속자가 28% 더 많았는데요. 그런데도 CPU 사용률은 모든 구간에서 절반 수준으로 내려왔습니다. 개장 후 첫 10분 평균은 36.6%에서 17.4%로, 10분 구간의 최댓값은 42.5%에서 21.9%로 낮아졌습니다.
처음 문제가 됐던 서버의 피크 15분 구간에서도 방향은 같았습니다. 커널이 사용하는 CPU(%system)는 부하가 33% 더 높은 날이었는데도 평균 7.77%에서 5.89%로 줄었습니다.
SQL 수행시간
개선 전후의 AWR(Oracle 성능 분석 리포트)에 공통으로 잡힌 SQL은 9건이었는데, 그중 8건의 1회당 수행시간이 줄었습니다. 아래는 주요 업무 SQL 6건으로, 10.5%에서 30.8%까지 빨라졌습니다. 실행 계획이나 데이터량의 차이도 섞여 있어 보조 지표로만 보고 있지만, 모두 같은 방향으로 움직였습니다.
이 조치는 이후 운영 중인 Oracle DB 서버 전체에 적용했습니다. 운영 모니터링에서 보면 CPU 사용률 개선은 특정 구간에 그치지 않고 이후 모든 시간대에서 유지되고 있고, 처음 문제였던 0.1초 이상의 log file sync 대기도 대부분 개선됐습니다.
비슷한 지연을 겪고 있다면
이번 일을 겪고 나서, 다른 시스템을 볼 때도 먼저 확인하게 된 것들이 있습니다.
평균은 코어 하나의 병목을 가립니다. 호스트 CPU가 80% 놀고 있어도 특정 코어는 꽉 차 있을 수 있어요. 지연이 간헐적이라면 pidstat -t -p <pid> 1로 프로세스가 어느 CPU에서 실행되는지까지 확인해 보시길 권합니다.
/proc/interrupts도 생각보다 쓸모가 많습니다. 일정한 간격으로 두 번 읽어 차이만 구해도 어떤 장치의 인터럽트가 어느 코어에 몰리는지 바로 보입니다. 이번 분석에 쓴 것도 30초 간격으로 뜬 스냅샷이 전부였습니다.
하드웨어 배치도 성능 설계의 일부였습니다. 다중 소켓 서버에서는 NIC나 HBA 포트가 특정 NUMA 노드에 연결되기 때문에, 장비를 도입하거나 증설할 때 어느 슬롯에 꽂을지를 소켓 분산까지 고려해 정하는 게 좋습니다. 본딩 모드도 마찬가지입니다. Active-Standby는 이중화 설정이지만, 평소 트래픽과 인터럽트를 포트 하나에 싣는 설정이기도 합니다. 핵심 트래픽이 지나는 경로라면 Active-Active 구성과 소켓을 나눈 장착을 함께 검토해 볼 만합니다.
그리고 irqbalance가 늘 답이 되지는 않았습니다. 장비와 드라이버에 따라 소프트웨어만으로는 재분배가 안 될 수 있으니, 하드웨어와 드라이버의 제약부터 확인해 보시는 게 좋습니다.
마치며
본딩을 Active-Standby에서 Active-Active로 바꾸는 작업 자체는 어렵지 않았습니다. 시간이 걸린 건 이 변경이 왜 필요한지 알아내는 과정이었어요.
스토리지도, OS도, 네트워크도, Oracle도 각자는 정상으로 동작하고 있었습니다. 문제는 그 사이에 있었습니다. NIC가 꽂힌 슬롯과 본딩 방식, 그리고 LGWR가 스케줄된 코어가 맞물린 조합이었죠. 한 레이어만 봐서는 설명하기 어려운 문제였습니다.
분석에 쓴 도구는 /proc/interrupts와 pidstat 정도였습니다. 다만 그 숫자에서 원인을 읽어 내려면 커널이 인터럽트를 어떻게 처리하는지, 서버의 소켓과 NIC가 어떻게 연결돼 있는지, Oracle이 커밋을 어떻게 기록하는지를 함께 알아야 했습니다. 이 글이 평균 지표로는 설명되지 않는 지연을 쫓고 계신 분들께 조금이나마 도움이 되었으면 합니다.
측정 조건
