레이스 컨디션.

로그 한 줄과 레이스 컨디션

물류 현장의 자율주행 로봇(AMR)을 관제하는 서버를 만들고 있습니다. 이 서버는 현장 지도(노드와 링크로 이루어진 그래프)를 메모리에 들고 있다가, "이 작업은 어느 로봇에게 줄까"를 계산하는 배차 요청을 처리합니다. 지도로 인접 그래프를 만들고, 후보 로봇마다 A*로 최단 경로를 구하고, 거리와 배터리를 종합해 한 대를 고르는 식입니다.

지도는 외부 지도 서버에서 받아와 갱신합니다. 즉 같은 전역 자료구조를 한쪽에서는 갱신하고 다른 쪽에서는 읽습니다.

1. 막아둔 구역이 저절로 열림

운영자는 공사 중인 구역이나 사람이 들어간 통로를 차단할 수 있습니다. 그런데 차단을 걸어둔 뒤 대시보드를 새로고침하면 풀려 있었습니다.

POST /map/block/node/N-01
GET  /map/blocked   → {"blocked_nodes": ["N-01"]}

GET  /map           ← 지도를 "조회"만 했다
GET  /map/blocked   → {"blocked_nodes": []}

원인입니다.

def update_topology_data(data: dict) -> None:
    NODE_COORDINATES.clear()
    LINKS.clear()
    BLOCKED_NODES.clear()    # ← 지도 데이터가 아닌데 같이 지운다
    BLOCKED_LINKS.clear()

차단은 지도 데이터가 아니라 운영자가 지정한 설정입니다. 게다가 이 갱신 함수는 업로드뿐 아니라 조회 API에서도 호출됩니다. 읽기만 해도 차단이 풀립니다. 로그도 알림도 남지 않습니다.

이건 쉬운 문제였습니다. 진짜 문제는 같은 함수를 들여다보다 나왔습니다.

2. 반쯤 지워진 지도를 읽는다

갱신 함수는 전역 dict/list를 clear() 하고 제자리에서 다시 채웁니다. 그리고 배차 쪽은 이 전역을 복사 없이 참조로 받아 그대로 순회합니다.

from topology import LINKS, NODE_COORDINATES

graph = build_graph(NODE_COORDINATES, LINKS)
#                   ↑ 살아있는 전역 객체를 그대로 넘긴다

동기 핸들러는 실제 스레드풀에서 돌기 때문에, 갱신과 배차는 서로 다른 OS 스레드에서 동시에 진행됩니다. 2000노드 기준 clear() 이후 재구성이 끝날 때까지 약 4ms의 창이 열리고, 그 사이 배차는 비어 있거나 절반만 채워진 지도를 봅니다.

증상이 대부분 예외가 아니라는 점입니다. 지도가 절반이면 그래프도 절반이고, A*는 조용히 "경로 없음"을 반환합니다. 배차 엔진은 그 로봇을 후보에서 제외하는데, 그 판정은 진짜로 길이 막혔을 때 나오는 정상 동작과 로그상 구분되지 않습니다. 멀쩡한 로봇이 조용히 빠지고 버그라 생각되어지는 형태가 아닙니다. 일부만 RuntimeError: dictionary changed size during iteration으로 터져 500이 되는데, 눈에 보이는 쪽이 오히려 운이 좋은 경우입니다.

3. 그런데 왜 지금까지 멀쩡했나

현장 맵은 22노드입니다. 이 코드로 몇 달을 돌렸는데 문제가 없었습니다. 재현 스크립트를 짜보니 로그 레벨을 INFO에서 WARNING으로 올리는 것만으로 97.5%가 재현됐습니다. 없앤 건 갱신 함수 맨 마지막 줄 하나뿐입니다.

    logger.info(f"토폴로지 갱신 완료: 노드 {len(NODE_COORDINATES)}개, 링크 {len(LINKS)}개")

스레드가 실행권을 넘기는 두 가지 방법

CPython에는 GIL이 있어 한 번에 한 스레드만 바이트코드를 실행합니다. 실행권이 넘어가는 경로는 둘뿐입니다.

강제 선점 — 지점이 임의. 인터프리터는 약 5ms(sys.getswitchinterval())마다 "다음 바이트코드 경계에서 비켜라"라고 요청합니다. 어느 줄에서 넘어갈지는 아무도 모릅니다. 재구성 루프 동작중 일수도 있습니다.
자발 반납 — 지점이 고정. 블로킹 I/O(파일 쓰기, 소켓) 중에는 GIL을 쥐고 있을 이유가 없어 CPython이 놓았다가 되찾습니다. 이 지점은 코드에 박혀 있습니다.

로그 한 줄이 한 일

clear()부터 재구성 완료까지는 순수 파이썬 연산뿐이라 자발 반납 지점이 하나도 없습니다. 유일한 반납 지점이 함수 맨 끝의 logger.info()이고, 그 자리가 하필 지도가 완성된 직후입니다.

[갱신 스레드] clear() → 재구성 ... 완료 → logger.info() ─┐
                                                          │ 여기서 GIL 반납
[배차 스레드] ─────────────── (GIL 대기) ────────────────┘ ← 완결된 지도를 본다

배차 스레드는 GIL을 기다리다 항상 안전한 지점에서 실행권을 받습니다. 22노드면 재구성 전체가 약 40µs라 5ms 강제 선점이 끼어들 확률도 낮고, 배차 쪽도 한 타임슬라이스 안에 그래프 구축을 끝냅니다. 즉 두 조건이 우연히 맞아떨어져 안전했던 겁니다.

임계 구역 끝에 자발 반납 지점(로그)이 있다
맵이 작아 임계 구역 전체가 한 타임슬라이스에 들어간다

로그 레벨을 올리면 로깅 라이브러리가 레벨에 걸린 호출에서 I/O를 아예 하지 않으므로 조건 1이 사라집니다. 맵이 커지면 재구성이 5ms에 근접해 강제 선점이 그 안에 떨어지기 시작하고, 조건 2가 사라집니다.

조건	이상 발생률
22노드 · `INFO`	0%
22노드 · `WARNING`	97.5%
300노드 · `INFO`	93.0%
2000노드 · `INFO`	99.1%

현장이 조금만 커지거나 운영 편의로 로그 레벨을 한 칸 올리는 순간 문제 지속 발생.

4. 불변 스냅샷으로 교체

원인은 "가변 객체를 제자리에서 고친다"였습니다.
그러면 제자리에서 고치지 않으면 됩니다.

@dataclass(frozen=True)
class TopologySnapshot:
    nodes: Mapping[str, Pose]
    links: tuple[dict, ...]
    revision: str


_snapshot: TopologySnapshot = _EMPTY_SNAPSHOT


def get_topology_snapshot() -> TopologySnapshot:
    return _snapshot

갱신은 새 객체를 다 만든 뒤 마지막에 참조만 바꿉니다.

    nodes = {...}   # 새 dict를 따로 만든다
    links = [...]

    _snapshot = TopologySnapshot(
        nodes=MappingProxyType(nodes),
        links=tuple(links),
        revision=revision,
    )                            # ← 이 재바인딩 한 번만이 "교체"다

읽는 쪽에서 보면 이렇습니다.

새 스냅샷을 만드는 4ms 동안 기존 스냅샷은 손대지 않은 채 살아 있습니다. 그동안 배차는 온전한 지도를 봅니다.
교체는 참조 재바인딩 한 번이라 중간 상태가 존재할 수 없습니다.
이미 스냅샷을 쥔 계산은 교체가 일어나도 영향받지 않습니다.

RCU(Read-Copy-Update) 또는 copy-on-write라고 부르는 패턴인데, 파이썬에서는 불변 객체와 참조 재바인딩만으로 구현됩니다.

한 번의 배차 계산은 시작 시점에 스냅샷을 딱 한 번 확보합니다. 이전에는 그래프와 좌표를 전역에서 따로 읽어 서로 다른 버전의 지도가 한 계산에 섞일 수 있었는데, 이제 구조적으로 불가능합니다.

전역 이름 자체도 제거하고 접근자 함수로 일원화했습니다.
from topology import NODE_COORDINATES로 임포트하면 임포트 시점의 객체에 이름이 묶여서, 나중에 원본을 재바인딩해도 임포트한 쪽은 영원히 옛 객체를 봅니다. 부수 효과로, 전역을 지우자 옮기지 않은 코드가 전부 ImportError로 터져 마이그레이션 누락을 실행 전에 전부 잡았습니다.

곁들여 두 가지를 더 고쳤습니다. 차단 검사를 그래프 구축이 아니라 A* 이웃 확장 시점으로 옮겨 그래프가 차단 상태에 묶이지 않게 했고, 그 덕에 같은 스냅샷에 대한 그래프를 캐시해 재사용할 수 있게 됐습니다.

5. 왜 락이 아니었나

가장 먼저 떠오르는 답은 Lock입니다. 쓰지 않았습니다.

읽기와 쓰기의 비대칭이 극단적으로 발생합니다. 배차는 초당 수십 번, 지도 갱신은 사용자가 맵을 바꿀 때만 일어납니다.
압도적으로 많은 쪽에 비용을 물리는 구조.

그리고 락은 규약이고, 규약은 지켜지기 힘듬.
락 방식에서는 지도를 읽는 모든 코드가 락을 잡아야 합니다.
만약, 반년 뒤 누군가 배차에 함수를 추가하며 락을 빠뜨리면 코드는 잘 돌고 테스트도 통과하고 아무 경고 없이 같은 버그가 돌아옵니다. 스냅샷 방식은 읽는 쪽에 아무 규약도 요구하지 않습니다. 함수 한 번 부르면 끝이고, 잘못 쓸 방법이 없습니다.

여기서 버그 발견.

# 수정 전 — 컴프리헨션은 파이썬 레벨 루프라 항목마다 실행권이 넘어간다
return [{"source": k[0], "target": k[1]} for k in BLOCKED_LINKS]

# 수정 후 — 원자적으로 뜬 사본을 순회한다
return [{"source": k[0], "target": k[1]} for k in BLOCKED_LINKS.copy()]

반면 바로 옆의 list(BLOCKED_NODES)는 C 레벨 단일 연산이라 원래부터 안전한 상태.
"컬렉션을 순회한다"가 아니라 "그 순회가 C 레벨인가 파이썬 레벨인가"가 기준.

결과

	수정 전	수정 후
차단 소실	100%	0%
지도 레이스 (2000노드)	99.1%	0%
배차 1건 (2000노드)	3.19ms	1.78ms

22~2000노드 × 로그 레벨 INFO/WARNING 여섯 조건 전부 0%입니다. 성능이 44% 좋아진 건 그래프 캐시 덕분이라 덤에 가깝습니다.

이 작업에서 가장 도움이 된 건 서버를 띄우지 않고 두 결함을 재현하는 독립 스크립트를 먼저 만든 것이었습니다. 노드 수와 로그 레벨을 환경변수로 돌릴 수 있게 해두니 "왜 현장에서는 안 터지나"에 추측이 아니라 숫자로 답할 수 있었습니다.

임재성

조금씩 앞으로

이전 포스트