measure(replication): 08-17 «5초 → 7~11.5초» 원인 분리 — 대부분 재는 방법, 경로를 다 빼도 약 6.5초

docs/decisions/experiment-inventory.md

@@ -91,7 +91,7 @@ DBA 지원축의 결손 3개(백업 · 복제 · 무중단 DDL)는 **셋 다 실
 
 | 우선 | 실험 | 상태 | 왜 지금 |
 |---|---|---|---|
-| ~~1?~~ | ~~**P4 — 복제 지연 · 반동기 대가 (Q1·Q2)**~~ | ✅ **완료 (측정 2026-08-22 · 회수 08-23)** — [결과](../../loadtest/results/replication-aws-2026-08-22/README.md) · [정본](./replication-lag-and-semisync.md) | **EC2 2대**(`c7i.2xlarge` · 같은 AZ) · 1,000만 행 · **10판 전부 유효 · 결함 0**(산포 A 0.6% / B 0.2%). **반동기의 대가 = 처리량 −5.9% · 커밋 p95 +13.0%** 이고 🔴 **H3 이 조건을 만들었다** — 같은 대가가 부하 모양에 따라 **−5.9% ↔ −10.3%** 로 두 배가 된다. 지연은 팔 A 약 60초 · 팔 B 약 57초. 🟢 **급소였던 G3 이 최대 소득** — `lag_net` 이 세 번 통과했고 굵기 **+1.017~1.018초가 무대 100배에도 안 변한다.** 그래서 08-17 이 Q3 을 잃은 원인이 «현상» 이 아니라 **«계측»** 이었음이 사후 확인됐다. 🔴 **인용 전 조건 넷** — 같은 AZ(다른 AZ 는 아래 09-02 라운드) · 앱 경로가 아닌 SQL writer · 계측 바닥 ~1초 · `main` 이 아닌 커밋(`e2fbe6c`, G2 결함 수정 [#380](https://github.com/Shadowfit/init/pull/380) 이 08-23 에 머지되며 해소). ⭐ **스모크 선행이 값을 했다** — 1회차가 G2 에서 막혔고, 1,000만 행 시딩을 마친 뒤에야 만났을 결함이었다. 남아 있던 «안 잰 것»(다른 AZ)은 새 라운드로 닫혔다. **2026-09-01 설계 · 09-02 판 설계 확정**(사용자 confirm) — [정본 §0-4](./replication-lag-and-semisync.md#0-4-설계--다른-az-대조-라운드-2026-09-01-설계--2026-09-02-판-설계-확정--실행회수는-0-5), rig 변경 불필요(AZ 는 인스턴스 배치 문제) 확인. 확정: 소스 2a·리플리카 2c · 옵션 C(버림1+본판4) · 다세션만(H3 제외) · 비용 승인. ✅ **실행·회수 완료 (측정 2026-09-01~02)** — [결과](../../loadtest/results/replication-aws-cross-az-2026-09-02/README.md) · [정본 §0-5](./replication-lag-and-semisync.md). 6판 전부 유효 · 결함 0. **반동기의 대가가 처리량 −17.2% · 커밋 p50 +23.1% · p95 +18.1%** 로 같은 AZ 대비 최대 약 3.8배 — 「자릿수 단위」 예견은 반증. ⚠️ 실행 경위가 불완전하다(다른 세션 경로로 실행돼 산출물만 회수, 정본 §0-5 머리말) |
+| ~~1?~~ | ~~**P4 — 복제 지연 · 반동기 대가 (Q1·Q2)**~~ | ✅ **완료 (측정 2026-08-22 · 회수 08-23)** — [결과](../../loadtest/results/replication-aws-2026-08-22/README.md) · [정본](./replication-lag-and-semisync.md) | **EC2 2대**(`c7i.2xlarge` · 같은 AZ) · 1,000만 행 · **10판 전부 유효 · 결함 0**(산포 A 0.6% / B 0.2%). **반동기의 대가 = 처리량 −5.9% · 커밋 p95 +13.0%** 이고 🔴 **H3 이 조건을 만들었다** — 같은 대가가 부하 모양에 따라 **−5.9% ↔ −10.3%** 로 두 배가 된다. 지연은 팔 A 약 60초 · 팔 B 약 57초. 🟢 **급소였던 G3 이 최대 소득** — `lag_net` 이 세 번 통과했고 굵기 **+1.017~1.018초가 무대 100배에도 안 변한다.** 그래서 08-17 이 Q3 을 잃은 원인이 «현상» 이 아니라 **«계측»** 이었음이 사후 확인됐다. 🔴 **인용 전 조건 넷** — 같은 AZ(다른 AZ 는 아래 09-02 라운드) · 앱 경로가 아닌 SQL writer · 계측 바닥 ~1초 · `main` 이 아닌 커밋(`e2fbe6c`, G2 결함 수정 [#380](https://github.com/Shadowfit/init/pull/380) 이 08-23 에 머지되며 해소). ⭐ **스모크 선행이 값을 했다** — 1회차가 G2 에서 막혔고, 1,000만 행 시딩을 마친 뒤에야 만났을 결함이었다. 남아 있던 «안 잰 것»(다른 AZ)은 새 라운드로 닫혔다. **2026-09-01 설계 · 09-02 판 설계 확정**(사용자 confirm) — [정본 §0-4](./replication-lag-and-semisync.md#0-4-설계--다른-az-대조-라운드-2026-09-01-설계--2026-09-02-판-설계-확정--실행회수는-0-5), rig 변경 불필요(AZ 는 인스턴스 배치 문제) 확인. 확정: 소스 2a·리플리카 2c · 옵션 C(버림1+본판4) · 다세션만(H3 제외) · 비용 승인. ✅ **실행·회수 완료 (측정 2026-09-01~02)** — [결과](../../loadtest/results/replication-aws-cross-az-2026-09-02/README.md) · [정본 §0-5](./replication-lag-and-semisync.md). 6판 전부 유효 · 결함 0. **반동기의 대가가 처리량 −17.2% · 커밋 p50 +23.1% · p95 +18.1%** 로 같은 AZ 대비 최대 약 3.8배 — 「자릿수 단위」 예견은 반증. ⚠️ 실행 경위가 불완전하다(다른 세션 경로로 실행돼 산출물만 회수, 정본 §0-5 머리말). 🔄 **11-07 로컬 — 08-17 계측 오차의 원인 분리**([결과](../../loadtest/results/replication-measure-path-2026-11-07/README.md)): 오차 대부분은 `docker exec` 로 벌어진 하트비트 간격 · 경로를 다 빼도 5초가 약 6.5초 → «계측 바닥 ~1초» 의 일부가 `SOURCE_DELAY` 동작일 수 있다는 **가설**(EC2 미확인) |
 | ~~#204~~ | ~~**[#204](https://github.com/Shadowfit/init/issues/204) 리포트 핵심 쿼리**~~ | ✅ **완료 (2026-08-19~20)** — [결과](../../loadtest/results/report-query-explain-2026-08-19/README.md) | 세 주장 중 **둘은 확인, 하나는 열쇠가 이미 있었다.** ㄱ 프루닝 — 세 팔 전부 **14파티션 전탐색**이고 인덱스로는 못 고친다(`created_at` 을 같이 넘긴 판만 1개). ㄴ 비커버링 — 논리 페이지 **3,777.5 ↔ 779(4.85배)**, 행당 4페이지. ㄷ filesort — A 에서 확인되지만 **[#188](https://github.com/Shadowfit/init/issues/188) 의 `uk_pose_event` 가 정렬 순서를 그대로 가지고 있어** B 에서 사라진다. 🔴 단 V6 은 `origin/main` 에 없다 — 지금 배포본엔 ㄷ 가 살아 있고, **#188 이 머지되면 손 안 대고 닫힌다** |
 | ~~#205 B·C~~ | ~~**[#205](https://github.com/Shadowfit/init/issues/205) 카드 B·C**~~ | ✅ **완료 (2026-08-20)** — [카드 C](../../loadtest/results/card-c-overlap-2026-08-20/README.md) · [카드 B](../../loadtest/results/card-b-avg-2026-08-20/README.md) | **C**: N=8,000 에서 **422배**(22.2초 ↔ 52.6ms), 배가별 4.2~4.4배로 2차식 확인. 🔴 단 근거는 «읽은 행 수» 가 아니었다 — 계획이 `Inner hash join (no condition)` 이라 **읽기는 O(N)·비교가 N²** 다. **B**: 불균일 200/200 갈리고 균일 **0/2,002** — 기제가 예측한 자리에서만. 곡선 쿼리는 커버링으로 **6.7배**인데 **핸들러 동일**(읽는 폭의 차이). 🔴 **두 카드가 «읽은 행 수는 비용의 대리 지표가 아니다» 를 반대 방향으로 보였다** |
 | ~~카드 A~~ | ~~**커버링 인덱스의 쓰기 대가**~~ | ✅ **완료 (2026-08-22)** — [결과](../../loadtest/results/card-a-write-cost-2026-08-22/README.md) · [change buffer 후속](../../loadtest/results/card-a-ibuf-armE-2026-08-22/summary.md) · [처리량(ms) 재설계](./covering-index-write-throughput.md) | **A÷B = 1.245**(논리 페이지 수정) · `log_write_req` 1.242 로 독립 두 카운터가 0.3% 안에서 일치. 행당으로 풀면 **+1.046 페이지 수정/행** — 세컨더리 엔트리 하나가 리프 페이지 수정 1회라는 **산수가 그대로 맞는다**. 팔 간 **겹침 0**(A 최소 106,254 > B 최대 85,556). 🔴 **답을 낸 것은 무대가 아니라 지표다** — 같은 팔이 `ms` 로는 **3.8배**(71.8초 ↔ 272.3초) 벌어지는데 카운터는 0.33% 안이다. ✅ **2026-09-06 처리량(ms) 실측 완료** — [결과](../../loadtest/results/card-a-write-throughput-2026-09-06/README.md): 조용한 EC2 박스(`c7i.2xlarge`)에서 같은 팔을 16판 재현, `bp_write_req` A÷B=1.244로 카드 A와 정합. **그런데 처리량(RPS) A÷B는 0.976·문당 p50은 완전히 동일(1.000)·p99만 1.047** — 논리 대가 +24.4%가 실제 처리량으로는 ~2%로 준다(문당 fsync가 인덱스의 추가 비용을 덮음, `TXN_STMTS=1` 조건 한정). ✅ **2026-09-06(2) 배치 커밋 후속으로 그 한정 조건을 직접 검증** — [결과 §7](../../loadtest/results/card-a-write-throughput-2026-09-06/README.md#7-배치-커밋-후속--가설-확인-2026-09-06-txn_stmts20): `TXN_STMTS=20`(fsync 20분의 1)으로 재현하니 RPS A÷B 0.976→**0.901**(−2.4%→−9.9%)·p99 A÷B 1.047→**2.948**(+4.7%→+195%)로 대가가 그대로 드러난다(`bp_write_req`는 1.244→1.252로 안 변함 — 일 자체는 그대로, fsync 가리개만 걷힘). 즉 "+24.4%→~2%" 축소는 **`TXN_STMTS=1`이라는 조건에 종속**된 결과였다. 채택 여부는 여전히 사용자 결정. ⚠️ **change buffer 는 안 탔다** — 세 페이로드 모양(집중·새 id 분산·**기존 id 분산**) 전부 0이고, 팔 E 는 `bp_reads` 221로 **디스크를 실제로 쳤는데도** 0이라 「페이로드 탓」이 아니다(원인은 가설로 남김) |
@@ -233,6 +233,11 @@ DBA 지원축의 결손 3개(백업 · 복제 · 무중단 DDL)는 **셋 다 실
 
 ## 결정 로그
 
+- **2026-11-08: P4 행에 11-07 계측 경로 분리 실험을 붙였다.** 08-17 팔 C 의 «5초 → 7~11.5초» 는
+  대부분 `docker exec` 가 하트비트 간격을 3~7.6초로 벌린 탓이었고, 클라이언트 경로를 다 빼도 약 6.5초가
+  남았다. 새 측정 항목이 아니라 닫힌 P4 의 조건(계측 바닥)을 다시 읽는 실험이라 행을 새로 만들지 않았다.
+  EC2 에서 확인할 것(서버 안 수신·대기·적용 분해)은 다음 EC2 라운드에 얹을 후보로만 남긴다 — 탑승 목록에는 안 넣었다.
+
 - **2026-09-01: 처음 지목한 드리프트가 오진이었다 — AI 축 3번(팔마다 CPU 다른 이유)은
   08-30에 안 닫혔다.** 사용자가 "실측 남은 것"을 물었을 때 08-30 커밋 셋(#593→#615→#616)이
   §3 3번 행을 닫았다고 짚었는데, 근거 문서(`per-process-ceiling-variance.md`)를 다시 열어

docs/decisions/replication-lag-and-semisync.md

@@ -1,6 +1,6 @@
 # 복제 — 「한 대가 죽어도 된다」를 지연과 대가로 바꾼다
 
-작성일: 2026-08-13 · 갱신: 2026-11-07 (Q4 미복귀 원인 분리 · 리플리카 2대 — §0-2)
+작성일: 2026-08-13 · 갱신: 2026-11-08 (§0-2 팔 C 오차 원인 분리 · §0-3 계측 바닥 가설)
 상태: ✅ **같은 AZ·다른 AZ 두 라운드 모두 완료.** Q1·Q2 에 값이 붙었다 —
 **같은 AZ(08-22)** 는 반동기의 대가 처리량 −5.9% · 커밋 p95 +13.0%, 단일 핫세션이면
 −10.3% 로 거의 두 배(H3). **다른 AZ(09-02, §0-5)** 는 같은 대가가 **처리량 −17.2% ·
@@ -46,6 +46,12 @@ AZ 무관). Q4·Q5 는 로컬 라운드(2026-08-17)가 닫았고, **Q3 은 「
 > 그리고 §0-2 가 Q3 을 잃은 원인이 «현상» 이 아니라 **«계측»** 이었음을 이 표가 사후
 > 확인한다 — 그때는 정확한 5초를 7~11.5초로 찍었고, 왜 그런지를 몰랐다.
 
+> 🔶 **2026-11-07 가설 — 이 «바닥» 의 상당 부분은 자가 아니라 `SOURCE_DELAY` 일 수 있다.**
+> 로컬에서 클라이언트 경로를 전부 빼고 서버 안에서만 재도 5초가 약 6.5초로 나왔다(§0-2 팔 C 의 🔄).
+> +1.018초는 `SOURCE_DELAY=5` 를 넣어 잰 값이라, 그 일부는 계측이 아니라 지연을 거는 방식의 몫일 수 있다.
+> 🔴 **확인 안 함** — 하드웨어·rig 이 다르고 EC2 에서 수신·대기·적용 분해를 안 했다. 그 전까지 아래 조건 3
+> («~1초 이상만 신뢰»)은 **보수적인 쪽이라 그대로 둔다.**
+
 ### 🔴 반동기 쪽 지연이 **더 작다** — 이건 추론이다
 
 팔 B 의 지연이 3초 **더 작게** 찍혔다. 반동기가 지연을 줄인 것이 아니라 **소스를 −5.9%
@@ -123,6 +129,13 @@ AZ 무관). Q4·Q5 는 로컬 라운드(2026-08-17)가 닫았고, **Q3 은 「
 `SOURCE_DELAY=5` 로 **정확히 5초**를 넣었는데 **7~11.5초**로 찍혔다. 지연을 잡기는 하지만
 **크기를 못 맞춘다** — 질의마다 `docker exec` 왕복이 초 단위로 얹히기 때문이다.
 
+> 🔄 **2026-11-07 원인 분리** ([결과](../../loadtest/results/replication-measure-path-2026-11-07/README.md)) —
+> 위 설명은 절반이었다. 같은 무대에서 재는 방법만 바꿔 보니(08-17 루프 · 커넥션 유지 · 서버 안) 오차의
+> 대부분은 **exec 때문에 하트비트 간격이 1초가 아니라 3~7.6초로 벌어진 것** + 읽기 exec 였다(본판 p50
+> 08-17 방식 8.0~13.1초 ↔ 커넥션 유지 6.5~6.8초). 🔴 그리고 **경로를 다 빼도 5초가 아니라 약 6.5초**다 —
+> 남는 약 1.3초는 MySQL 이 5초를 기다리는 단계 안에 있고(수신 0.04 · 적용 0.09초), 원인은 확인 안 했다.
+> 같은 머신의 다른 프로그램(간섭)은 가끔 튀게 할 뿐이고 재는 방법과 상관없이 걸렸다.
+
 > 이게 없었다면 아래 Q3 의 `miss 0/30` 을 **「창이 없다」는 결론으로 발표했을 것이다.**
 > §2 가 팔 C 를 둔 이유가 정확히 이것이었다.
 
@@ -918,3 +931,11 @@ Q1 은 통째로 인위 지연이다.
   본판 기준 P(count=1·1대 죽임) **4/4 버팀** · Q(count=1·2대 죽임) 3/3 강등(양성 대조군) · R(count=2·1대 죽임) 3/3 강등.
   리플리카 반동기는 시작 옵션이라 10/10 자동 복귀. 🔴 강등 뒤에도 `clients` 가 바로 줄지 않아 알람 지표로 부적합(추론,
   언제 줄어드는지는 안 잼). 같은 호스트라 «AZ 별 1대씩» 의 비용은 말하지 못한다.
+- 2026-11-08: ✅ **§0-2 팔 C 의 «5초 → 7~11.5초» 원인을 갈랐다** (로컬 · 8.0.46 · 측정 2026-11-07 ·
+  [결과](../../loadtest/results/replication-measure-path-2026-11-07/README.md)). 같은 무대에서 재는 방법만 바꿨다 —
+  X 08-17 루프 그대로(`docker exec`) · Y 커넥션 유지 클라이언트 · Z 서버 안에서만. 버림 1 + 본판 9 라틴 방격.
+  본판 p50 은 X 13.1·8.0·8.2 · Y 6.8·6.6·6.5 · Z 7.2·6.5·6.5초. 🟢 **오차의 대부분은 재는 방법** — exec 때문에
+  하트비트 간격이 3~7.6초로 벌어졌고 거기에 읽기 exec 가 얹혔다(쓰기 기록으로 다시 계산한 모형이 본판 83/85 맞음).
+  🔴 **경로를 다 빼도 약 6.5초** — 남는 약 1.3초는 수신(0.04)·적용(0.09)이 아니라 «5초를 기다리는» 단계 안이고,
+  왜인지는 확인하지 않았다. 간섭은 판 3·4 에서 Y·Z 둘 다 튀게 했고 늘어난 곳은 서버의 대기·적용이었다(재는 방법과 무관).
+  여기서 §0-3 의 «계측 바닥 ~1초» 도 상당 부분 `SOURCE_DELAY` 의 동작일 수 있다는 **가설**이 나왔다 — EC2 에서 확인 안 함.