본문 바로가기
C.W.K.
Stream
Lesson 05 of 05 · published

가만히 있어도 드는 값

~17 min · performance, observability, sqlite, polling

Level 0메모 쪽지
0 XP0/41 lessons0/12 achievements
0/100 XP to next level100 XP to go0% complete

3주 뒤, 두 번째 리뷰

지난 레슨의 리뷰는 Coop이 부지런히 움직인 게 효과가 있었냐고 물었고, 아무것도 안 바꾼 깨움 74번을 찾아냈어. 3주 뒤 두 번째 리뷰(todo #519)는 다른 걸 물었어. 아무 일도 없을 때 Coop은 얼마를 쓰나? 조용한 채팅 여덟 개를 따라가는 어댑터 여덟 개로, Coop 프로세스들이 CPU 코어 하나의 29%를 쓰고 있었어. 그날 끝날 땐 4.5%였어. 계기는 청구서가 아니었어. 스페인에서 노트북으로 Coop 작업 페이지를 열었는데 Loading work details…가 영영 안 끝나는 걸 아빠가 보고 있었던 거야.

이 리뷰에서 Coop이 뭘 결정하는지는 하나도 안 바뀌었어. 찾아낸 건 전부, 바뀌지 않은 무언가에 시스템이 계속, 또 계속 값을 치르던 자리였어. 한 목록으로 읽어. 실수 하나가 옷 일곱 벌을 갈아입은 거니까.

한 번 훑는 데 프로세스 55개

트랙 4 첫 레슨에서 Claude 세션 레지스트리를 읽는 게 공짜가 아니라고 했지. 살아 있는 채팅과 끝난 채팅을 가르려고 헬퍼가 등록된 프로세스마다 ps로 태어난 시각을 확인한다고. 그 ps를 등록 하나마다 한 번씩 돌렸어. 리뷰 당시 office엔 등록이 55개였으니까, 레지스트리 한 번 읽을 때마다 프로세스 55개가 뜨고 200 ms쯤 걸렸어. 읽는 횟수도 적지 않았어. 어댑터마다 폴링 한 번에 최소 두 번, activity 스윕은 1분마다, 배정 폼은 요청마다. 샘플링 프로파일러 py-spy로 어댑터 둘을 봤더니 샘플의 87%가 그 함수 하나 안에 있었어.

고친 건 모든 pid를 ps 한 번에 묻는 거야(ps -p a,b,c -o pid=,lstart=). 정규화한 문자열은 그대로라서 뒤쪽은 하나도 안 바뀌었어. 레지스트리 한 번 읽기가 193–218 ms에서 36–40 ms가 됐어. 돌려봐야만 배우는 디테일이 하나 있어. 목록에 범위를 벗어난 pid가 하나라도 있으면 ps는 호출 전체를 거부해. 그래서 헬퍼는 0이나 100000 이상인 pid는 아예 안 물어.

커넥션도 공짜가 아니야

엔진은 읽기와 쓰기마다 SQLite 커넥션을 새로 열고 끝나면 닫았어. 별일 아닌 것 같지? 트랙 2를 떠올려봐. 저장소엔 변경 추적과 펜스 트리거가 160개 있고, 커넥션을 열 때마다 스키마 전체를 파싱해. 재보니 한 번 여는 데 2.2 ms, 열어 둔 커넥션은 0.01 ms였어. 그 값이 어댑터 폴링마다, chief tick(5초)마다, 조정자 tick(3초)마다, notifier(15초)마다, 페이지 읽기마다 붙어 다녔어. 조용한 부작용도 있었어. 마지막 커넥션이 닫히면 SQLite가 체크포인트를 하고 write-ahead 로그를 지웠고, 그 틈에 들어온 읽기 전용 접속은 실패했어.

이제 connection()은 열어 둔 커넥션을 많아야 여덟 개까지 보관하는 풀에서 하나를 빌려줘. 그보다 몰리면 더 열었다가, 돌아올 때 닫아. 풀을 일부러 작게 둔 건 launchd가 런타임한테 파일 디스크립터를 256개밖에 안 주기 때문이야. 규칙은 옛 보장을 그대로 지켜. 안쪽 블록은 자기 커넥션을 따로 받고, 트랜잭션은 그걸 시작한 블록보다 오래 못 살고(블록을 나갈 때 롤백돼. 닫을 때랑 똑같이), 망가진 커넥션은 다시 빌려주지 않고 버려. 트랙 2의 펜스도 그대로 버텨. 풀에 든 커넥션은 전부 엔진이 열고 자기 함수를 등록한 것들이니까.

옆에 비용이 둘 더 있었어. 몇 초마다 하는 조회(어댑터 자기 봉투와 바인딩, notifier의 큐, 대기 중 리뷰)가 테이블을 통째로 훑고 있었고, 인덱스 열한 개로 해결했어. 그리고 chief 러너는 리뷰할 때가 됐는지 5초마다 확인하면서 자기 역할을 리뷰 컨텍스트 통째로 읽고 있었어. 대기 중인 의무마다 그 일, 보고, 전달까지 전부. 그게 한 번에 17 ms, 59 KB였고, 워크스페이스와 어댑터까지 함께 돌리는 단 하나의 이벤트 루프 위에서 일어났어. 이제 Chief.role()은 필요한 한 줄만 읽고, 저장소 작업은 그 루프 밖에서 돌아. 워커 스냅샷은 3.3 ms에서 0.1 ms 아래로, chief 컨텍스트는 17.4 ms에서 0.32 ms로 줄었어.

영영 대답 안 할 채팅을 폴링하기

트랙 4에서 어댑터는 전달 중인 게 있으면 채팅을 2초마다 읽는다고 했지. 문제는 그 "전달 중"이었어. 어떤 Codex 채팅의 어댑터는 Codex 앱이 끝내 안 보여준 답글 리뷰 두 개를 기다리며 엿새 동안 2초마다 폴링했어. 다른 하나는 전날 끝난 일의 리뷰를 기다리며 열일곱 시간을 그랬고. "빚진 게 있다"가 슬그머니 "영원히 빠르게 폴링하라"가 돼 있었던 거야.

이제 빠른 속도는 큐가 아니라 채팅이 벌어야 해. 채팅이 살아 있는 티를 내는 동안(턴이 돌거나, 최근 2분 안에 네이티브 기록이 있거나)은 2초, 기다리는 상대 채팅이 조용해졌으면 15초야. 판독엔 원래부터 모든 receiver에 대해 이 두 사실이 들어 있어서, 워커가 답하면 예전만큼 빨리 집어 와. 답 없는 초대장은 한 번에 90초까지 초당 네 번씩 찾던 걸, 이제 다른 전달처럼 2초마다 찾아. 거절당한 유휴 은퇴는 15초마다 재시도하며 매번 로그를 남겼는데(채팅 하나의 거절이 나흘 동안 로그 19,747줄을 채웠어), 이제 이유가 다를 때만 한 번 적고 10분 뒤에 다시 시도해.

끝난 일에 보낸 봉투

일이 끝난 채팅한테 왜 빚진 게 남아 있었을까? 트랙 4의 깨움 레슨에서 앞부분은 봤어. 바인딩이 나중에 끝난 답글 리뷰나, 디스패치가 나중에 끝난 작업 봉투는 확인받을 수가 없어서 보냄, 영수증 불확실 상태로 영원히 남았어. 첫 수리는 owed()가 그런 행을 무시하게 한 거였어. 그래도 어댑터 눈엔 여전히 전달 중이었고, 그게 위의 엿새짜리 폴링이야.

진짜 수리는 규칙 하나를 한 자리에 둔 거야. _settle_finished는 이제 아무도 답할 수 없는 봉투를 전부 work-over라는 영수증 사유와 함께 취소해. 바인딩이 더는 활성이 아닌 답글 리뷰, 그리고 디스패치가 끝났거나 거절됐거나 취소된 초대장과 작업 봉투. 아직 대기 중이든 이미 보냈든 상관없이. 바인딩이나 디스패치를 끝내는 바로 그 트랜잭션 안에서 돌고, 옛 행을 위해 엔진이 시작할 때 한 번 더 돌아. owed()의 예외 조항은 사라졌어. 봐주던 행이 이제 열린 채로 남지 않으니까.

같은 커밋이 거울상도 찾았어. 컨트롤 퍼사드로 일을 닫으면 아직 셋업 중인 배정은 취소됐지만, 이미 보낸 초대장은 열린 채로 남았어. CLI로 닫으면 아무것도 안 거둬들였고. 워커가 닫힌 일에 여전히 COOP_ACCEPT로 답할 수 있었고, 아빠는 나중에 초대가 "수락되지 않았다"는 소식을 들었어. 이제 _withdraw_offers가 일을 끝내는 모든 문의 규칙 하나야. 시작도 안 한 배정은 조용히 취소하고, 아무도 수락 안 한 초대장은 취소하면서 그 채팅에 제안을 거둔다고 알리고, 이미 연결 중인 채팅은 조정자한테 맡겨서 이유를 말해주게 해.

끝내 안 열린 페이지

스페인에서 office까지는 302 ms 거리였고, tailnet 너머로 대략 초당 100에서 500 KB가 나왔어. 워크스페이스는 어느 페이지든 operations 뷰라는 읽기 하나를 먼저 기다렸는데, 그게 그때 2.8 MB였어. 최근 outbox 페이로드와 영수증 전부, 증거가 달린 보고 200개, 세션 245개, 디스패치 200개, 셋업 프롬프트가 달린 배정 100개. 페이지는 그걸 30초마다, 포커스나 화면 표시가 바뀔 때마다, 배정이 도는 동안엔 3초마다 다시 받았고, 다시 받을 때마다 아직 오고 있던 읽기를 취소했어. 그 회선에선 읽기가 한 번도 안 끝났고, 그 뒤에 줄 서 있던 작은 상세 읽기도 마찬가지였어.

이제 엔진은 페이지마다 보여주는 만큼만 잘라서 줘. attention 뷰엔 열려 있거나 빚진 것만 실어. 개수엔 상한을 두고, 페이로드나 프롬프트나 증거는 빼고. 2.8 MB가 114 KB, gzip으로 30 KB가 됐어. 항목 하나의 배정 이야기는 따로 3에서 10 KB짜리 읽기고, 3초마다 폴링하는 건 이것뿐인데 그것도 시도가 진행 중일 때만이야. JSON 응답은 gzip으로 나가. 그리고 페이지의 리더 usePolled는 새로 고치려고 읽기를 취소하는 일이 절대 없어. 읽는 도중 들어온 새로 고침은 그 뒤에 한 번 더 읽는 걸로 바뀌고, 그동안 마지막 데이터는 화면에 남아 있어.

퇴행 하나도 각주로 남길 만해. 날씬해진 뷰는 처음에 실패한 알림을 오래된 것까지 전부 보여줬어. 옛 뷰는 끝난 행을 최근 7일 것만 보여줬는데. 일주일 넘은 실패 셋이 다시 나타났고, 아빠 사이드바의 배지는 새로 결정할 게 없는데도 8에서 11로 올라갔어. 한 시간 안에 일주일 창이 돌아왔어. 뷰를 줄일 땐 옛 뷰가 걸던 필터를 전부 적어 둬. 아무도 고른 기억이 없는 것까지.

아무도 못 쓰는 영수증

마지막으로 찾은 건 트랙 2의 제일 오래된 발견이 새 옷을 입고 나타난 거야. activity 판독 하나하나가 멱등성 영수증과 함께 저장되고 있었는데, 키를 판독마다 새로 만들었으니 어떤 영수증도 재시도에 답할 수가 없었어. 리뷰가 셌을 때 engine_commands 14,521행 중 8,805행, 하루 1,250개 정도였어. 이제 판독은 영수증 없이 자기 트랜잭션에서 커밋돼(자세한 건 트랙 2 세 번째 레슨). 그리고 호출마다 영수증 파일을 fsync하던 호환 클라이언트는 이제 쓰기에만 하나씩 남겨. office에 남아 있던 영수증 19개 중 15개가 읽기였거든.

시스템은 쉬고 있을 때 재. 노는 비용은 뭔가 일어나고 있다고 가정할 때마다 치르는 값이야. 안 바뀐 pid를 또 묻는 프로세스, 안 바뀐 스키마를 읽으려고 다시 여는 커넥션, 올 수 없는 답을 기다리며 폴링하는 채팅, 지난번 로딩이 끝나기도 전에 다시 불러오는 페이지. 이 중 어느 것도 에러로는 안 보여. 코어의 29%로 보이고, 지구 반대편에선 끝내 안 열리는 페이지로 보여.

Code

Coop 엔진: 끝난 일의 봉투를 정리하는 규칙 하나 (원문 발췌, docstring 축약)·python
def _settle_finished(conn):
    """Cancel every envelope whose work is over; nothing can answer it any more."""
    return conn.execute("""UPDATE engine_outbox SET state='cancelled',receipt=?
        WHERE state IN ('pending','uncertain') AND session_id IS NOT NULL AND (
          (kind='reply_review' AND NOT EXISTS (SELECT 1 FROM engine_bindings b
             WHERE b.id=json_extract(engine_outbox.payload,'$.binding_id') AND b.state='active'))
          OR (kind IN ('invitation','work') AND EXISTS (SELECT 1 FROM engine_dispatches d
             WHERE d.id=json_extract(engine_outbox.payload,'$.dispatch_id') AND d.status IN ('resolved','declined','cancelled'))))""",
        (dump({'not_delivered':{'reason':'work-over'}}),)).rowcount
Coop 원격 헬퍼: 모든 pid에 ps 한 번 (원문 발췌, docstring 축약)·python
def process_starts(pids):
    """`ps lstart` for many pids in one call, {pid: birth}, whitespace-normalized, UTC like Claude records it."""
    wanted = sorted(set(p for p in pids if type(p) is int and 0 < p < 100000))
    if not wanted:
        return {}
    try:
        result = subprocess.run(["/bin/ps", "-p", ",".join(str(p) for p in wanted), "-o", "pid=,lstart="],
                                capture_output=True, text=True, timeout=5, env=dict(os.environ, LC_ALL="C", TZ="UTC"))
    except (OSError, subprocess.SubprocessError):
        return {}
    found = {}
    for line in result.stdout.splitlines():
        parts = line.split(None, 1)
        if len(parts) == 2 and parts[0].isdigit() and int(parts[0]) in wanted:
            found[int(parts[0])] = " ".join(parts[1].split())
    return found
직접 돌려보는 최소 스케치: 트리거 160개짜리 스키마, 읽을 때마다 열기 대 열어 두기·python
"""A minimal sketch (not Coop's code): what a store connection costs when
the schema carries many triggers, opened per use versus kept open."""
import os
import sqlite3
import tempfile
import time

path = os.path.join(tempfile.mkdtemp(), 'ledger.db')
setup = sqlite3.connect(path)
setup.execute('PRAGMA journal_mode = WAL')
for t in range(20):                       # 20 tables x 8 triggers = 160 triggers
    setup.execute(f'CREATE TABLE t{t} (id INTEGER PRIMARY KEY, body TEXT)')
    for n in range(8):
        setup.execute(f'CREATE TRIGGER trg_{t}_{n} AFTER UPDATE ON t{t} '
                      f'BEGIN SELECT 1 WHERE NEW.id = {n}; END')
setup.execute("INSERT INTO t0 (body) VALUES ('one row')")
setup.commit()
setup.close()

READS = 300


def per_use():
    for _ in range(READS):
        conn = sqlite3.connect(path)      # opening parses the whole schema
        conn.execute('SELECT body FROM t0 WHERE id = 1').fetchone()
        conn.close()


kept = sqlite3.connect(path)


def pooled():
    for _ in range(READS):
        kept.execute('SELECT body FROM t0 WHERE id = 1').fetchone()


for name, fn in (('open per use', per_use), ('kept open', pooled)):
    start = time.perf_counter()
    fn()
    each = (time.perf_counter() - start) / READS * 1000
    print(f'{name:13} {each:.3f} ms per read')

# One run on an Apple Silicon Mac printed (your numbers will differ; the ratio is the point):
# open per use  1.026 ms per read
# kept open     0.004 ms per read

External links

Exercise

네가 돌리는 서비스 하나를 10분 동안 놀려봐. 사용자도, 작업도, 큐에 쌓인 것도 없이. CPU를 재고 샘플링 프로파일러를 1분 붙여. 샘플이 제일 많은 함수 셋을 적고, 각각 뭘 확인하는지, 그게 두 번 확인하는 사이에 바뀔 수 있는지 적어. 그다음 타이머로 새로 고치는 페이지나 클라이언트 하나를 봐. 이전 읽기가 끝나기 전에 새로 고침이 시작되면 무슨 일이 생겨?
Hint
흔한 범인은 이래. 한 번 부르면 될 걸 항목마다 띄우는 서브프로세스, 쓸 때마다 다시 만드는 커넥션이나 클라이언트, 상대가 살아 있다는 증거가 아니라 큐 때문에 빨라지는 폴링, 재시도마다 반복되는 로그 한 줄. "두 번 확인하는 사이에 바뀔 수 있어?"에 솔직하게 답해서 아니라면, 그 확인은 시계에 매달 게 아니라 바뀔 수 있는 순간에 해야 해.

Progress

Progress is local-only — sign in to sync across devices.
이 페이지에서 버그를 발견하셨거나 피드백이 있으세요?문제 신고
💛 by 피파— warm

댓글 0

🔔 답글 알림 (로그인 필요)
로그인 — 댓글을 남기려면 로그인해 주세요.

아직 댓글이 없어요. 첫 댓글을 남겨보세요.