Kafka 핫 파티션, 메시지 수는 같은데 왜 하나만 밀릴까?

이번 시간에는 파티션 하나만 밀리는 핫 파티션을 Docker로 띄운 Kafka와 Python 프로듀서·컨슈머로 직접 만들어 측정하며 배워가는 시간입니다.

예를 들어서 우리가 주문 이벤트를 고객 번호를 키로 Kafka에 보내고 있다고 해볼게요. 컨슈머 그룹의 lag(아직 처리하지 못하고 밀린 메시지 수)를 파티션별로 열어 보니 파티션 하나만 계속 늘고 있는데, 파티션별로 들어오는 메시지 수는 네 파티션이 똑같습니다.

핫 파티션이라고 하면 보통 특정 키에 메시지가 몰리는 경우를 떠올리실 거예요. 여기서는 메시지 수는 같은데 처리 비용이 한쪽에 쏠리는 경우를 만들어 보고, 어느 지표로 찾을 수 있는지, 원인이 되는 키를 어떻게 골라내는지 직접 재 봅니다.

실습 준비

이 글의 명령은 모두 실습 코드의 kafka-hot-partition/ 디렉터리에서 실행합니다.

• compose.yaml: Kafka 4.3 단일 노드(JMX 포함)
• produce.py: 고객 20곳의 주문을 초당 80건 보내는 프로듀서
• consume.py: 키별 처리 시간을 재고 처리 기록을 남기는 컨슈머
• watch.py: 파티션별 유입량과 lag를 주기적으로 찍는 스크립트

브로커와 컨트롤러를 한 컨테이너에서 같이 실행하는 Kafka 4.3 한 대를 띄울게요. 호스트의 Python 스크립트는 localhost:9471로 접속합니다. compose.yaml은 이렇게 생겼습니다.

services:
  kafka:
    image: apache/kafka:4.3.1
    environment:
      KAFKA_NODE_ID: 1
      KAFKA_PROCESS_ROLES: broker,controller
      KAFKA_LISTENERS: PLAINTEXT://:9092,CONTROLLER://:9093,EXTERNAL://:9094
      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://kafka:9092,EXTERNAL://localhost:9471
      KAFKA_CONTROLLER_LISTENER_NAMES: CONTROLLER
      KAFKA_LISTENER_SECURITY_PROTOCOL_MAP: CONTROLLER:PLAINTEXT,PLAINTEXT:PLAINTEXT,EXTERNAL:PLAINTEXT
      KAFKA_CONTROLLER_QUORUM_VOTERS: 1@kafka:9093
      KAFKA_OFFSETS_TOPIC_REPLICATION_FACTOR: 1
      KAFKA_TRANSACTION_STATE_LOG_REPLICATION_FACTOR: 1
      KAFKA_TRANSACTION_STATE_LOG_MIN_ISR: 1
      KAFKA_GROUP_INITIAL_REBALANCE_DELAY_MS: 0
      KAFKA_HEAP_OPTS: -Xmx512m -Xms256m
      KAFKA_JMX_PORT: 9999
      KAFKA_JMX_HOSTNAME: localhost
    ports:
      - "9471:9094"

KAFKA_JMX_PORT로 연 JMX 포트는 이 글에서는 쓰지 않아요.

컨테이너를 띄우고, 자주 쓰는 명령은 셸 함수로 만들어 놓을게요.

아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.

docker compose up -d

kafka() { docker compose exec -T kafka /opt/kafka/bin/"$@"; }

topic() { kafka kafka-topics.sh --bootstrap-server kafka:9092 --create --topic "$1" --partitions 4; }

describe() { kafka kafka-consumer-groups.sh --bootstrap-server kafka:9092 --describe --group "$1" 2>/dev/null | awk 'NF {print $3, $4, $5, $6}' | column -t; }

consumers() { for n in c1 c2 c3 c4; do python consume.py "$1" "$2" "$3" $n > $n.out & done; sleep 8; }

python3 -m venv venv && source venv/bin/activate
pip install confluent-kafka

• topic: 파티션 4개짜리 토픽을 만들어요.
• describe: 컨슈머 그룹의 파티션, CURRENT-OFFSET, LOG-END-OFFSET, LAG 열만 보여 줍니다.
• consumers: 같은 그룹으로 컨슈머 4개를 띄우고, 파티션을 하나씩 나눠 받을 때까지 8초 기다려요.

produce.py는 python produce.py <토픽> <초>처럼 부르면 되고, 고객 20곳의 주문을 차례로 돌아가며 초당 80건씩 보냅니다. 고객 번호는 파티션 4개에 5곳씩 들어가도록 골라서, 파티션마다 초당 20건씩 똑같이 들어갑니다.

다만 두 고객은 다른 고객과 건수는 같지만 처리하기가 무거워요.

• cust-07: 대량 주문 고객이에요. 주문 한 건에 품목이 300개 들어 있어 메시지가 큽니다. 다른 고객은 품목이 3개예요.
• cust-23: 주문을 받으면 이 고객사의 웹훅을 호출해야 하는데, 응답이 느립니다. 메시지 크기는 다른 고객과 같아요.

consume.py는 <그룹> <토픽> <초> <이름>을 인자로 받아요. 주문 하나를 처리할 때 기본 7ms에 품목마다 1ms씩 걸리게 해 두어서, 보통 고객의 주문은 10ms, cust-07의 주문은 307ms가 걸려요. cust-23의 주문은 웹훅 300ms가 더해져 310ms 남짓 걸립니다.

컨슈머는 메시지를 처리할 때마다 키별로 처리 시간을 더해 두었다가, 끝날 때 처리 시간이 가장 긴 키 3개를 출력해요. commit 주기는 lag 변화를 촘촘히 보려고 1초로 줄였어요.

watch.py는 <토픽> <그룹> <간격 초> <횟수>를 인자로 받아요. Admin API로 파티션마다 로그 끝 offset과 그룹의 committed offset을 가져와, 직전 측정과 비교해서 초당 몇 건이 들어왔는지(유입)와 lag를 파티션별로 출력해 줍니다.

실습 1: 메시지 수가 같아도 파티션 하나가 밀립니다

이제 orders 토픽을 만들고 billing 그룹으로 컨슈머 4개를 55초 동안 띄워 볼게요. 그다음 40초 동안 주문을 보냅니다.

topic orders
consumers billing orders 55
python produce.py orders 40 &
python watch.py orders billing 5 9
wait

Created topic orders.
08:56:08 p0 유입  20/s lag   20 | p1 유입  20/s lag   20 | p2 유입  20/s lag   45 | p3 유입  20/s lag   31
08:56:13 p0 유입  20/s lag   20 | p1 유입  20/s lag   19 | p2 유입  20/s lag   75 | p3 유입  20/s lag   61
08:56:18 p0 유입  20/s lag   20 | p1 유입  20/s lag   19 | p2 유입  20/s lag  105 | p3 유입  20/s lag  106
08:56:23 p0 유입  20/s lag   20 | p1 유입  20/s lag   18 | p2 유입  20/s lag  135 | p3 유입  20/s lag  136
08:56:28 p0 유입  20/s lag   20 | p1 유입  20/s lag   19 | p2 유입  20/s lag  170 | p3 유입  20/s lag  166
08:56:33 p0 유입  20/s lag   20 | p1 유입  20/s lag   20 | p2 유입  20/s lag  200 | p3 유입  20/s lag  196
08:56:38 p0 유입  20/s lag   20 | p1 유입  20/s lag   20 | p2 유입  20/s lag  233 | p3 유입  20/s lag  226
orders: 3200개 보냄
08:56:43 p0 유입  19/s lag   15 | p1 유입  19/s lag   15 | p2 유입  20/s lag  265 | p3 유입  20/s lag  261
08:56:48 p0 유입   0/s lag    0 | p1 유입   0/s lag    0 | p2 유입   0/s lag  200 | p3 유입   0/s lag  191

출력을 보면 네 파티션 모두 초당 20건씩 들어왔어요. 그런데 lag는 갈렸습니다.

• 파티션 0과 1(p0, p1): lag가 20 안팎에 머뭅니다. commit 주기 1초 동안 들어온 20건이 아직 commit 전으로 보이는 정도라 밀린 건 없어요.
• p2, p3: 5초마다 30건 남짓씩, 초당 6건꼴로 계속 늘어 260을 넘겼습니다.

p2에는 cust-23이, p3에는 cust-07이 들어 있어요. p2를 맡은 컨슈머는 1초에 cust-23 주문 4건(310ms씩)과 다른 고객 주문 16건(10ms씩)을 처리해야 합니다. 1.4초가 걸리는 일이 1초마다 들어오니 따라가지 못하는 거죠.

컨슈머가 멈춘 뒤에 그룹 상태를 볼게요.

describe billing

PARTITION  CURRENT-OFFSET  LOG-END-OFFSET  LAG
0          800             800             0
1          800             800             0
2          640             800             160
3          649             800             151

네 파티션 모두 800건을 받았는데, p2와 p3에는 150건 넘게 남았어요.

p2를 맡은 컨슈머는 하나뿐이고, 같은 그룹에서 한 파티션은 한 컨슈머만 읽습니다. 그래서 컨슈머를 늘려도 p2의 처리 속도는 그대로예요. 그룹 안에서 파티션을 나누는 방식이 더 궁금하면 컨슈머 그룹을 다룬 글을 참고하세요.

실습 2: 브로커의 바이트 지표는 p3만 가리킵니다

이번에는 원인을 모르는 운영자라고 생각하고 브로커가 아는 값을 볼게요. 건수는 앞의 describe에서 본 것처럼 네 파티션이 정확히 800건씩이에요.

파티션별로 디스크에 쌓인 크기는 kafka-log-dirs.sh로 봅니다. 출력이 JSON 한 줄이라서 jq로 파티션과 크기만 뽑아 볼게요.

kafka kafka-log-dirs.sh --bootstrap-server kafka:9092 --describe --topic-list orders \
  | grep '^{' | jq -r '.brokers[].logDirs[].partitions[] | "\(.partition) \(.size)"' | sort

orders-0 171450
orders-1 171389
orders-2 171450
orders-3 1692410

p3만 다른 파티션의 10배 가까이 돼요. 품목 300개짜리 주문이 들어 있기 때문이죠.

반면 p2는 다른 파티션과 크기가 같습니다. cust-23의 메시지는 다른 고객과 크기가 같고 처리만 느리기 때문이에요.

건수와 바이트는 브로커가 아는 값이지만, 메시지 하나를 처리하는 데 몇 초가 걸리는지는 브로커가 모릅니다. 그래서 처리 시간이 쏠린 핫 파티션은 파티션별 lag를 보고 있어야 찾을 수 있어요.

실습 3: 키별 처리 시간은 컨슈머가 재야 합니다

한 파티션에는 키 여러 개가 섞여 있어요. p2의 원인 키는 처리하는 쪽에서만 보입니다. 실습 1에서 실행한 컨슈머 4개가 끝날 때 출력한 처리 시간 상위 키를 볼게요.

cat c1.out c2.out c3.out c4.out

c1 할당 [0]
c1 처리 시간 상위 키: cust-04 2.0초/160건, cust-09 2.0초/160건, cust-10 2.0초/160건
c2 할당 [1]
c2 처리 시간 상위 키: cust-30 2.0초/160건, cust-21 2.0초/160건, cust-36 2.0초/160건
c3 할당 [2]
c3 처리 시간 상위 키: cust-23 40.6초/128건, cust-19 1.6초/128건, cust-18 1.6초/128건
c4 할당 [3]
c4 처리 시간 상위 키: cust-07 40.5초/130건, cust-06 1.6초/130건, cust-13 1.6초/129건

p2를 맡은 컨슈머 c3에서 cust-23은 다른 키와 같은 128건을 처리하는 데 40.6초가 걸렸어요. 같은 파티션의 cust-19는 1.6초가 걸렸습니다. 25배 차이죠. p3의 cust-07도 마찬가지예요.

운영 중인 컨슈머에서 이 값을 모을 때는 키를 지표의 라벨로 그대로 쓰면 안 돼요. 고객 번호처럼 종류가 많은 값을 라벨로 쓰면 지표 시계열이 키 수만큼 늘어나거든요. 그래서 이 실습처럼 컨슈머 안에서 키별로 더해 두었다가, 일정 주기로 상위 몇 개만 로그나 지표로 내보내는 편이 낫습니다.

정리

범위: Kafka 4.3(apache/kafka:4.3.1) 한 대, 파티션 4개, confluent-kafka 2.15.1, 고객 20곳이 초당 80건씩 40초.

• 네 파티션 모두 초당 20건씩 들어왔지만, 처리 시간이 긴 고객이 든 p2와 p3의 lag만 260을 넘겼습니다. 핫 파티션은 건수가 아니라 파티션별 lag로 찾아 주세요.
• 품목 300개짜리 주문이 든 p3은 로그 크기가 다른 파티션의 10배 가까이였고, 처리만 느린 cust-23의 p2는 크기가 같았습니다. 처리 시간 쏠림은 브로커 지표로 찾으려 하지 마세요.
• p2의 cust-23은 컨슈머가 잰 처리 시간(128건에 40.6초, 같은 파티션 cust-19는 1.6초)에서만 드러났습니다. 컨슈머 안에서 키별 처리 시간을 더해 상위 몇 개만 로그나 지표로 내보내세요.