From 2e60170701c435298f60d634216903f01283c7e5 Mon Sep 17 00:00:00 2001 From: GiJung <101462387+GiJungPark@users.noreply.github.com> Date: Thu, 3 Sep 2026 16:45:36 +0900 Subject: [PATCH] =?UTF-8?q?[TEST]=20=EB=8F=99=EC=8B=9C=20=EC=A2=8B?= =?UTF-8?q?=EC=95=84=EC=9A=94=20=EC=9D=B8=EA=B8=B0=20=ED=94=BC=EB=93=9C=20?= =?UTF-8?q?=EB=93=B1=EB=A1=9D=20=EB=88=84=EB=9D=BD=EC=9D=84=20=EC=9E=AC?= =?UTF-8?q?=ED=98=84=ED=95=9C=EB=8B=A4?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/popular-feed-like-race-report.md | 243 +++++++++++++++++ .../load/popular-feed-like-race/.gitignore | 1 + scripts/load/popular-feed-like-race/README.md | 233 ++++++++++++++++ scripts/load/popular-feed-like-race/lib.sh | 148 ++++++++++ .../load/popular-feed-like-race/like-race.js | 257 ++++++++++++++++++ .../observe-timeline.sh | 129 +++++++++ .../load/popular-feed-like-race/run-race.sh | 161 +++++++++++ .../popular-feed-like-race/seed-fixture.sh | 111 ++++++++ .../load/popular-feed-like-race/summarize.py | 236 ++++++++++++++++ .../feed/PopularFeedLikeRaceScriptTest.java | 224 +++++++++++++++ 10 files changed, 1743 insertions(+) create mode 100644 docs/popular-feed-like-race-report.md create mode 100644 scripts/load/popular-feed-like-race/.gitignore create mode 100644 scripts/load/popular-feed-like-race/README.md create mode 100644 scripts/load/popular-feed-like-race/lib.sh create mode 100644 scripts/load/popular-feed-like-race/like-race.js create mode 100755 scripts/load/popular-feed-like-race/observe-timeline.sh create mode 100755 scripts/load/popular-feed-like-race/run-race.sh create mode 100755 scripts/load/popular-feed-like-race/seed-fixture.sh create mode 100755 scripts/load/popular-feed-like-race/summarize.py create mode 100644 src/test/java/org/websoso/WSSServer/feed/feed/PopularFeedLikeRaceScriptTest.java diff --git a/docs/popular-feed-like-race-report.md b/docs/popular-feed-like-race-report.md new file mode 100644 index 000000000..649eeaf1e --- /dev/null +++ b/docs/popular-feed-like-race-report.md @@ -0,0 +1,243 @@ +# 동시 좋아요 시 인기 피드 등록 측정 결과 (#620) + +같은 피드에 서로 다른 사용자 6명이 거의 동시에 좋아요를 보냈을 때 +`popular_feed` 행이 어떤 상태로 남는지, 좋아요 API 응답 시간이 어떤지를 로컬에서 반복 측정했다. +프로덕션 코드와 DB 스키마는 바꾸지 않았다. + +재현 스크립트와 실행 방법은 [`scripts/load/popular-feed-like-race/README.md`](../scripts/load/popular-feed-like-race/README.md)에 있다. + +## 요약 + +1. **`popular_feed` 미등록이 100% 재현된다.** 6명 동시 30회 + 발사 간격을 벌린 30회, 총 60회 모두 + `popular_feed` 행이 0건이었다(`popular_state = not_registered`). + 좋아요 자체는 60회 모두 6건씩 정상 저장됐고 요청 오류는 0건(`request_state = clean`)이다. + 이 수치는 관측값이고, 원인은 아래 타임라인으로 따로 확인했다. +2. **동시 요청일 때 임계값 경쟁 (A)이 실제로 성립한다.** 커밋 6건이 0.37ms 안에 끝나고 + AFTER_COMMIT 리스너의 `count(*)`는 그보다 19ms 뒤에 6건이 몰려서 실행됐다. + 전원이 `6`을 읽고 `!= 5`로 빠져나가, `popular_feed` 조회조차 발생하지 않았다. +3. **그런데 동시성을 완전히 없애도 등록되지 않는다.** 400ms 간격으로 서로 다른 사용자 5명이 + 한 명씩 좋아요를 보내 최종 `like` 개수를 정확히 5로 만든 대조 실행 5라운드도 전부 `popular_feed` 0건, + `notification` 0건이었다. 모든 응답은 `204`이고 예외도 로그도 없다. + 5번째 리스너는 `count(*) = 5`를 읽고 임계값을 통과해 `popular_feed` 존재 확인 쿼리까지 갔지만, + 그 뒤 `insert into popular_feed`가 아예 발생하지 않았다. +4. 따라서 **중복 등록 경쟁 (B)는 관측할 수 없었다.** 등록 자체가 어떤 타이밍에서도 성립하지 않기 때문이다. +5. 좋아요 API 응답 시간은 6명 동시 기준 **p95 49.6ms** (med 32.0ms, max 54.7ms, n=180)다. + +3번은 이번 이슈가 전제한 동시성 경쟁과는 다른 층위의 결함이다. +이 이슈의 범위(재현 자산 작성)를 벗어나므로 고치지 않고 아래에 후속 이슈 후보로 적어 둔다. + +## 측정 환경 + +| 항목 | 값 | +| --- | --- | +| 대상 | 로컬 `http://localhost:8080`, `./gradlew bootRun` (`local` 프로파일) | +| 호스트 | macOS 26.6, Apple M4 (10 core) | +| 서버 | Spring Boot 3.2.5 / Hibernate 6.4.4 / Java 17 툴체인 | +| DB | MySQL 8.4.11 (Docker `websoso-mysql`, `localhost:3306`) | +| Redis | Redis 8 (Docker `websoso-redis`, `localhost:6379`) | +| 부하 도구 | k6 v2.2.0 (darwin/arm64) | +| 서버 옵션 | `--logging.level.p6spy=OFF --decorator.datasource.p6spy.enable-logging=false` (SQL 로깅으로 응답 시간이 흔들리지 않게 끔) | +| 대상 피드 | `feed_id=331` (`novel_id=1`, 공개, 미숨김) | +| 좋아요 사용자 | 서로 다른 6명 (`user_id` 2~7), 피드 작성자(1)와 차단 관계 없음 | +| 측정일 | 2026-09-03 | + +운영·공유 개발 서버는 대상으로 삼지 않았고, 스크립트가 로컬 호스트 외에는 실행을 거부한다. + +## 실행 결과 + +`--stagger-ms`는 VU별 발사 간격이다. `0`이면 6명이 같은 절대 시각에 동시에 쏘고, +키우면 순차 요청에 가까워진다. 모든 라운드는 시작 전에 대상 피드의 +`like` / `popular_feed` / `notification` 행을 지워 초기 상태로 되돌린 뒤 실행했다. + +표의 `not_registered` / `registered` / `duplicate_rows`는 `popular_feed` 행 개수(0 / 1 / 2 이상)에서 +바로 나오는 관측값이다. 원인은 담지 않는다. 요청 오류는 `request_state`로 따로 기록되며 +이번 측정에서는 전 라운드가 `clean`이었다. +(측정 당시 집계기는 이 상태들을 `missing` / `registered` / `duplicate_conflict` / `duplicate_rows`로 +불렀다. 이후 원인을 단정하지 않도록 이름과 분류를 바꿨고, 위 수치는 그 매핑을 적용한 값이다. +`duplicate_conflict`에 해당하는 라운드는 0건이었으므로 수치 자체는 달라지지 않는다.) + +| 실행 | 발사 간격 | 라운드 | `not_registered` | `registered` | `duplicate_rows` | HTTP 실패율 | duration med | **p95** | max | +| --- | --- | --- | --- | --- | --- | --- | --- | --- | --- | +| A 동시 | 0ms | 30 | **30 (100%)** | 0 | 0 | 0.0 (0/180) | 32.0ms | **49.6ms** | 54.7ms | +| B-1 | 20ms | 10 | **10 (100%)** | 0 | 0 | 0.0 (0/60) | 15.1ms | **28.9ms** | 31.8ms | +| B-2 | 100ms | 10 | **10 (100%)** | 0 | 0 | 0.0 (0/60) | 25.2ms | **37.7ms** | 70.2ms | +| B-3 | 300ms | 10 | **10 (100%)** | 0 | 0 | 0.0 (0/60) | 29.0ms | **36.8ms** | 172.6ms | +| C 대조 (5명) | 400ms | 5 | **5 (100%)** | 0 | 0 | 0.0 (0/25) | 28.9ms | **33.0ms** | 35.4ms | + +C는 동시성을 완전히 제거한 대조 실행이다. 사용자 5명이 400ms 간격으로 한 명씩 좋아요를 보내 +최종 `like` 개수가 정확히 임계값 5가 되도록 만들었다. 그래도 등록되지 않는다. +`./run-race.sh --vus 5 --stagger-ms 400 --rounds 5` 로 그대로 재현된다. + +- 모든 라운드에서 최종 `like` 개수는 참여 사용자 수와 같았고(A·B 6, C 5), `popular_feed` 개수는 0이었다. + 좋아요가 유실된 라운드(`like_count_mismatch`)는 없다. +- 동시 발사 정렬 오차(`fire_skew_max_ms`)는 A 실행 30라운드 중 28라운드가 0ms, 2라운드가 1ms였다. + 즉 "거의 동시"가 아니라 사실상 동시에 도착했다. +- HTTP 5xx와 전송 오류는 전체 385건 중 0건이다. 모든 요청이 `204 No Content`로 끝났다. +- `popular_feed` 행이 2건 이상인 라운드(`duplicate_rows`)는 **0건**이다. + +응답 시간은 발사 간격과 상관관계를 보인다. 6명이 완전히 겹치는 A에서 p95가 49.6ms로 가장 높고, +간격을 벌린 B·C에서는 29~38ms 대다. 여기까지가 관측된 상관관계이고, 이 차이가 커넥션 풀 대기인지 +Tomcat 스레드 경합인지 DB 쪽 경합인지는 컴포넌트별로 분리 측정하지 않았으므로 단정하지 않는다. +300ms 간격의 max 172.6ms는 한 라운드의 단일 요청에서 나온 값이다. 원인은 확인하지 않았다. + +## 근거: 쿼리 타임라인 + +`observe-timeline.sh`로 MySQL general log를 켜고 한 라운드씩 관찰했다. +general log는 문장마다 기록하므로 이 구간의 응답 시간은 위 측정치와 비교하지 않는다. + +### (A) 동시 6건 — 전원이 `6`을 읽는다 + +``` +16:10:14.900338 227027 insert into `like` ... user_id=3 +16:10:14.900338 227028 insert into `like` ... user_id=2 +16:10:14.900411 227030 insert into `like` ... user_id=5 +16:10:14.900624 227025 insert into `like` ... user_id=6 +16:10:14.900834 227029 insert into `like` ... user_id=7 +16:10:14.900863 227026 insert into `like` ... user_id=4 +16:10:14.900857 227030 commit <- 커밋 6건이 +16:10:14.900881 227028 commit +16:10:14.901013 227027 commit +16:10:14.901067 227025 commit +16:10:14.901198 227026 commit +16:10:14.901224 227029 commit <- 0.37ms 안에 모두 끝난다 +16:10:14.920019 227030 select count(l1_0.like_id) from `like` ... feed_id=331 +16:10:14.920252 227029 select count(...) <- 마지막 커밋보다 19ms 뒤, +16:10:14.920422 227025 select count(...) 6건이 0.7ms 안에 몰려서 실행된다 +16:10:14.920608 227026 select count(...) +16:10:14.920650 227027 select count(...) +16:10:14.920731 227028 select count(...) +``` + +판정 구간(count 쿼리 이후)에 `popular_feed` SELECT도 INSERT도 없다. +6개 리스너 전원이 `count = 6`을 읽고 `likeCount != 5`에서 빠져나갔다는 뜻이다. +(이 측정 당시에는 초기화 `DELETE FROM popular_feed`가 타임라인 앞머리에 함께 찍혔다. +지금은 초기화를 general log를 켜기 전에 끝내므로 그 행이 아예 남지 않는다.) + +`count(*)`가 커밋보다 19ms 늦은 이유는, 커밋과 리스너 사이에 좋아요 알림 리스너 +(`FeedLikeNotificationListener`)가 먼저 실행되면서 차단 확인 / 소설 / 소설 통계 / +알림 타입 / 사용자 / 사용자 기기 조회를 6번 하기 때문이다. +즉 **리스너 판정이 커밋보다 늦어지는 폭이 커질수록 (A) 누락 확률이 올라간다.** +6명의 커밋 간격(0.37ms)보다 커밋→판정 지연(19ms)이 50배 이상 크므로, +동시 요청에서는 누락이 사실상 결정적으로 일어난다. + +### (C) 순차 실행 — 임계값을 통과해도 INSERT가 없다 + +동시성을 제거한 대조 실행이다. 서로 다른 사용자 5명이 400ms 간격으로 한 명씩 좋아요를 보냈다. +같은 조건을 손으로 한 번 더 돌려 초기화 없이 최종 상태를 직접 읽어 보면 이렇다. + +``` +user=2 http=204 user=3 http=204 user=4 http=204 user=5 http=204 user=6 http=204 + +likes 5 <- 임계값 조건을 정확히 만족한다 +popular_feed 0 <- 그런데 등록되지 않는다 +notifications 0 <- 좋아요 알림도 저장되지 않는다 +``` + +왜 간격을 벌려도 누락인지 general log로 확인했다. +`VUS=5 STAGGER_MS=400`으로 한 라운드를 돌리고 마지막(5번째) 요청이 쓴 커넥션만 따라간 것이다. +직전 요청의 커밋은 `02.340644`, 이 요청의 커밋은 `02.741432`로 400ms 떨어져 있다. +요청끼리 겹치는 구간이 전혀 없다. + +``` +16:20:02.740488 227029 insert into `like` ... user_id=6 +16:20:02.741432 227029 commit <- 좋아요 트랜잭션 커밋 +16:20:02.748622 227029 SET autocommit=1 <- 트랜잭션이 여기서 정리된다 +16:20:02.749895 227029 select 1 from block ... ┐ +16:20:02.750972 227029 select ... from novel ... │ FeedLikeNotificationListener +16:20:02.751480 227029 select ... from novel_statistics │ (AFTER_COMMIT) +16:20:02.752373 227029 select ... from notification_type │ +16:20:02.753151 227029 select ... from user ... │ +16:20:02.754046 227029 select ... from user_device ... ┘ <- insert into notification 없음 +16:20:02.755002 227029 select count(l1_0.like_id) from `like` ... feed_id=331 + <- PopularFeedCheckEventListener. count = 5 이므로 임계값 통과 +16:20:02.756076 227029 select pf1_0.popular_feed_id from popular_feed pf1_0 where pf1_0.feed_id=331 limit 1 + <- existByFeed. 결과 없음(false) 이므로 create()로 진행 + <- general log는 여기서 끝난다. insert into popular_feed 가 없다 +``` + +`popular_feed` 조회가 로그 전체의 마지막 문장이다. +`likeCount != 5`도 `existByFeed`도 통과해 `popularFeedService.create(feed)`까지 갔는데 +INSERT가 DB로 나가지 않았다. 즉 **간격을 벌려도 누락인 이유는 임계값 경쟁이 아니다.** +(A)는 동시 요청에서만 성립하고, 순차 요청의 누락은 이 별개 원인 때문이다. + +공통점은 커밋 직후의 `SET autocommit=1`이다. +AFTER_COMMIT 이후 문장이 전부 autocommit 상태에서 실행되고 그 뒤로 `SET autocommit=0`이 다시 나오지 않는다. +좋아요 트랜잭션이나 그 앞의 사용자 조회 트랜잭션이 시작될 때는 `SET autocommit=0`이 찍히는 것과 대비된다. +리스너 안의 `@Transactional` 메서드들이 **새 트랜잭션을 열지 않은 채** 실행됐다는 뜻이다. +읽기는 autocommit으로 그대로 동작하지만, `save()`로 만든 엔티티는 flush될 자리가 없어 +그대로 사라지는 것으로 보인다. 그래서 `notification`도 `popular_feed`도 INSERT가 나가지 않는다. +여기까지가 general log로 확인한 사실이고, 왜 새 트랜잭션이 열리지 않는지(전파 속성인지, +이미 완료된 트랜잭션 자원이 스레드에 남아 있어서인지)는 후속 이슈에서 코드로 확인해야 한다. + +응답은 `204`, 서버 로그에 ERROR도 WARN도 없다. 조용히 유실된다. +측정 기간 전체에 걸쳐 서버 로그의 ERROR는 0건, WARN은 기동 시 2건(`open-in-view`, 임시 보안 비밀번호)뿐이었다. + +## 해석 + +| 가설 | 결과 | 근거 | +| --- | --- | --- | +| (A) `count == 5` 체크 누락 | **성립 확인** | 동시 6건에서 커밋 6건(0.37ms) 뒤 19ms 지나 count 6건이 모두 `6`을 읽음. `popular_feed` 조회 미발생 | +| (B) `exist` 확인과 `save` 사이 경쟁 | **관측 불가** | 등록 자체가 성립하지 않아 두 리스너가 동시에 저장을 시도하는 상황이 만들어지지 않음. 전 라운드에서 5xx 0건, `duplicate_rows` 0건 | +| (C) AFTER_COMMIT 리스너 쓰기 유실 | **신규 발견** | 동시성 없는 대조 실행(400ms 간격 5명)에서 `like`=5인데 `popular_feed`=0, `notification`=0. general log에 INSERT 자체가 없음 | + +`AFTER_COMMIT 리스너는 요청 스레드에서 동기 실행된다`는 가설은 맞다. 근거는 두 가지이고 층위가 다르다. + +- **코드 계약** — `PopularFeedCheckEventListener`와 `FeedLikeNotificationListener` 어디에도 `@Async`가 없고, + `applicationEventMulticaster`에 `TaskExecutor`를 주입하는 설정도 없다. 기본 이벤트 전달은 호출 스레드에서 + 수행되므로 두 리스너는 요청 스레드에서 동기 실행된다. 동기 실행의 근거는 이쪽이다. +- **general log 관측** — 커밋 뒤에 리스너 SQL이 같은 `thread_id`로 이어서 찍힌다. + `thread_id`는 MySQL 커넥션 식별자이므로 이것으로 말할 수 있는 것은 리스너 쿼리가 + 좋아요 트랜잭션과 **같은 DB 커넥션**에서 이어졌다는 사실까지다. JVM 요청 스레드와 같다는 뜻은 아니다. + +(B)를 관측하려면 (C)가 먼저 해결되어야 한다. +(C)가 해결된 뒤에도 (B)는 (A)보다 훨씬 좁은 창을 노려야 한다. +두 리스너가 **모두** `5`를 읽어야 하는데, 위 타임라인에서 보듯 커밋들은 서로 0.4ms 안에 붙고 +판정은 그보다 19ms 뒤에 몰려서 실행되기 때문이다. +로컬 스키마의 `popular_feed.feed_id`에는 유니크 키(`UK_ggr3ta3ux4vhitypguhgc6y13`)가 있다. +(B)가 실제로 일어난다면 중복 행이 아니라 무결성 위반 예외(응답 5xx)로 드러날 것으로 보이지만, +이번 측정에서는 5xx가 한 건도 없어 확인하지 못했다. +집계기는 5xx를 `request_state = http_5xx`로만 기록하고 유니크 충돌이라고 단정하지 않는다. +그 원인은 서버 로그에서 해당 예외가 실제로 보일 때만 쓴다. + +## 후속 이슈 후보 + +이번 이슈 범위 밖이라 고치지 않았다. + +1. **AFTER_COMMIT 리스너 안의 쓰기가 저장되지 않는다.** + `PopularFeedService.create`, `NotificationService.create*` 모두 해당한다. + 인기 피드 등록과 모든 푸시 알림 기록이 동작하지 않는 상태로 보인다. + 영향 범위가 넓으므로 먼저 실제 dev 환경에서 같은 증상인지 확인이 필요하다. + (`select count(*) from notification where created_date > ...` 로 빠르게 확인할 수 있다.) +2. **`likeCount != 5` 등호 비교.** (C)를 고쳐도 동시 요청에서는 전원이 `6`을 읽어 누락된다. + 임계값 비교 방식 자체를 다시 볼 필요가 있다. +3. **`existByFeed` 확인과 `create` 저장 사이의 비원자성.** (1),(2)를 고친 뒤 남는 문제다. +4. **좋아요 응답 시간에 알림 리스너가 동기로 포함된다.** 커밋 이후 조회 6건이 요청 스레드에서 + 그대로 이어져 응답 시간에 들어간다. 응답 시간에서 이 구간이 차지하는 비중은 분리 측정하지 않았다. + +## 재현 방법 + +```bash +cd scripts/load/popular-feed-like-race + +# 1) 로컬 픽스처 (최초 1회) +DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 ./seed-fixture.sh + +# 2) 반복 측정 +export FEED_ID=<위 출력값> USER_IDS=<위 출력값> +export JWT_SECRET='' +export DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 +./run-race.sh --rounds 30 --stagger-ms 0 # A: 6명 동시 +./run-race.sh --rounds 5 --vus 5 --stagger-ms 400 # C: 동시성 없는 대조 + +# 3) 쿼리 타임라인 (원인 확인용) +./observe-timeline.sh # 동시 6건: 전원이 count=6을 읽는 것을 본다 +VUS=5 STAGGER_MS=400 ./observe-timeline.sh # 순차 5건: count=5를 읽고도 INSERT가 없는 것을 본다 +``` + +## 한계 + +- 로컬 단일 인스턴스 측정이다. 여러 인스턴스가 뜨는 환경에서는 리스너가 서로 다른 JVM에서 돌아 + (A)와 (B)의 창이 달라질 수 있다. +- 로컬 스키마는 `ddl-auto: update`로 만들어졌다. `popular_feed.feed_id` 유니크 키가 + dev/운영 스키마에도 있는지는 확인하지 않았다. 없다면 (B)는 5xx가 아니라 중복 행으로 나타난다. +- MySQL general log를 켠 상태의 타임라인은 순서 관찰용이며 응답 시간 근거로 쓰지 않았다. diff --git a/scripts/load/popular-feed-like-race/.gitignore b/scripts/load/popular-feed-like-race/.gitignore new file mode 100644 index 000000000..fbca22537 --- /dev/null +++ b/scripts/load/popular-feed-like-race/.gitignore @@ -0,0 +1 @@ +results/ diff --git a/scripts/load/popular-feed-like-race/README.md b/scripts/load/popular-feed-like-race/README.md new file mode 100644 index 000000000..33bbabd54 --- /dev/null +++ b/scripts/load/popular-feed-like-race/README.md @@ -0,0 +1,233 @@ +# 인기 피드 등록 동시성 재현 (#620) + +같은 피드에 서로 다른 사용자 6명이 거의 동시에 좋아요를 보냈을 때 +`popular_feed` 행이 어떤 상태로 남는지, 그리고 좋아요 API 응답 시간이 어떤지를 +반복 측정하기 위한 자산이다. 프로덕션 코드는 바꾸지 않고 관측만 한다. +관측값만 기록하고 원인은 판정하지 않는다. + +측정 결과는 [`docs/popular-feed-like-race-report.md`](../../../docs/popular-feed-like-race-report.md)에 있다. + +## 무엇을 보는가 + +좋아요 요청은 `FeedLikeApplication.create`의 트랜잭션이 커밋된 뒤 +`PopularFeedCheckEventListener`(AFTER_COMMIT)가 요청 스레드에서 그대로 이어서 실행한다. +그 안의 `PopularFeedApplication.checkAndRegister`는 이렇게 판정한다. + +``` +likeCount = count(like where feed_id = ?) +if (likeCount != 5) return; // (A) 정확히 5일 때만 통과한다 +if (popularFeedService.existByFeed) return; // (B) 확인과 +popularFeedService.create(feed); // (B) 저장 사이가 원자적이지 않다 +``` + +확인하려는 가설은 둘이다. **가설이지 이 스크립트의 판정 결과가 아니다.** + +- **(A) 임계값 경쟁** — 6개 트랜잭션이 모두 커밋된 뒤에야 리스너들이 카운트를 읽으면 + 모두 `6`을 보고 `!= 5`로 빠져나갈 수 있다. +- **(B) exist/save 경쟁** — 두 리스너가 모두 `5`를 읽으면 둘 다 임계값을 통과하고, + `exist` 확인과 `save` 사이에서 경쟁한다. + 유니크 키가 있는 스키마라면 두 번째 저장이 무결성 위반으로 터지고, + 없는 스키마라면 행이 2건 남는다. + +`run-race.sh`는 이 가설들을 자동으로 판정하지 않는다. +`popular_feed` 행 개수와 요청 오류 여부를 **관측값으로만** 기록한다. +어느 가설이 성립했는지, 5xx가 무엇 때문이었는지는 서버 로그와 `observe-timeline.sh`의 +쿼리 순서로 따로 확인해야 한다. + +> 로컬 실측에서는 (A), (B)와 별개로, 리스너가 임계값과 존재 확인을 통과한 뒤에도 +> `popular_feed` INSERT가 발생하지 않는 현상을 관측했다. 자세한 근거는 결과 문서를 본다. + +## 사전 조건 + +- 로컬(또는 개인 전용 비운영) 서버가 떠 있어야 한다. **운영·공유 개발 서버 대상 실행은 스크립트가 거부한다.** +- 로컬 MySQL 접근. `mysql` 클라이언트가 있거나, 컨테이너 이름을 `DB_DOCKER_CONTAINER`로 넘길 수 있어야 한다. +- [k6](https://k6.io) (`brew install k6`) +- `python3` (집계용. 표준 라이브러리만 쓴다) + +측정 시에는 SQL 로깅이 응답 시간을 크게 흔들기 때문에 꺼 두고 서버를 띄우는 편이 낫다. + +```bash +./gradlew bootRun --args='--logging.level.p6spy=OFF --decorator.datasource.p6spy.enable-logging=false' +``` + +## 환경 변수 + +| 변수 | 필수 | 기본값 | 설명 | +| --- | --- | --- | --- | +| `FEED_ID` | O | – | 좋아요 대상 피드 PK. `novel_id`가 있는 피드여야 인기 피드 판정 대상이 된다 | +| `TOKENS` | △ | – | 콤마로 구분한 Access Token 목록. VU 수만큼 필요하다 | +| `USER_IDS` | △ | – | `TOKENS` 대신 쓸 사용자 PK 목록. `JWT_SECRET`과 함께 쓴다 | +| `JWT_SECRET` | △ | – | `USER_IDS` 모드에서 Access Token을 서명할 시크릿 | +| `BASE_URL` | | `http://localhost:8080` | 대상 서버. 로컬 호스트만 허용한다 | +| `DB_HOST` / `DB_PORT` / `DB_USER` / `DB_PASSWORD` / `DB_NAME` | | `127.0.0.1` / `3306` / `root` / (빈 값) / `websoso` | 판정용 DB 접속 정보 | +| `DB_DOCKER_CONTAINER` | | – | 지정하면 `docker exec <이름> mysql`로 접속한다 | +| `K6_BIN` | | `k6` | k6 실행 파일 경로 | + +`TOKENS` 또는 (`USER_IDS` + `JWT_SECRET`) 중 하나는 반드시 있어야 한다. +**어떤 값도 저장소에 커밋하지 않는다. 전부 환경 변수로만 주입한다.** + +`USER_IDS` 모드는 `JwtProvider`/`JwtKeyProvider`와 같은 방식으로 토큰을 만든다. +HMAC 키가 시크릿 원문이 아니라 `Base64(시크릿 UTF-8)` 문자열의 바이트라는 점까지 맞춰 놓았다. +로그인 API를 6번 태우지 않고도 서로 다른 사용자 6명을 만들 수 있어 반복 실행이 쉽다. + +## 실행 + +### 1. 픽스처 만들기 (로컬에서 처음 한 번) + +소설 1건, 작성자 1명, 좋아요를 누를 사용자 6명, 대상 피드 1건과 +알림 타입 마스터 데이터를 만든다. 이미 있으면 다시 만들지 않는다. + +```bash +cd scripts/load/popular-feed-like-race +DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 ./seed-fixture.sh +``` + +출력에 나온 `FEED_ID`와 `USER_IDS`를 그대로 다음 단계에 쓴다. + +### 2. 반복 실행 + +```bash +export FEED_ID=331 +export USER_IDS=2,3,4,5,6,7 +export JWT_SECRET='' +export DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 + +./run-race.sh --rounds 30 +``` + +한 라운드는 이렇게 돈다. + +1. 대상 피드에 묶인 `like` / `popular_feed` / `notification` 행만 지워 초기 상태로 되돌린다 +2. k6가 VU 6개를 공통 시작 시각까지 대기시켰다가 동시에 `POST /feeds/{feedId}/likes`를 쏜다 +3. `--settle-ms`만큼 유예를 둔 뒤 DB 최종 상태를 읽어 관측값으로 기록한다 + +### 옵션 + +| 옵션 | 기본값 | 설명 | +| --- | --- | --- | +| `--rounds` | 10 | 반복 횟수 | +| `--vus` | 6 | 동시 사용자 수. 임계값(5)보다 하나 많아야 경쟁이 생긴다 | +| `--stagger-ms` | 0 | VU별 발사 간격. `0`이면 완전 동시, 키우면 순차에 가까워진다 | +| `--start-delay-ms` | 1500 | 공통 시작 시각까지의 리드타임 | +| `--settle-ms` | 1000 | DB 최종 상태를 읽기 전 유예. 현재 구현에서는 필수 대기가 아니다 | +| `--out` | `results/` | 결과 디렉터리 | + +`--settle-ms`는 DB 최종 상태 관측을 안정화하기 위한 유예다. +현재 구현의 `PopularFeedCheckEventListener`에는 `@Async`가 없고 이벤트가 호출 스레드에서 +전달되므로, 응답이 돌아온 시점에는 리스너가 이미 끝나 있다. 그래서 이 대기는 필수가 아니며 +`0`으로 두어도 된다. 리스너를 비동기로 바꾸는 변경이 들어오면 다시 필요해질 수 있어 옵션으로 남겨 둔다. + +동시 시작은 VU마다 공통 절대 시각을 정해 두고 맞춘다. +대기 대부분은 `sleep()`으로 CPU를 양보하고 마지막 `SPIN_MS`(기본 20ms)만 busy-spin으로 정렬한다. +전 구간을 busy-spin으로 돌리면 VU들이 CPU를 잡아먹어 측정 자체가 흔들리기 때문이다. +`fire_skew_max_ms` 컬럼이 실제 발사 시각이 목표에서 얼마나 벗어났는지 보여준다. + +### 3. 쿼리 타임라인 관찰 (선택) + +판정이 왜 그렇게 났는지 서버가 실제로 보낸 쿼리 순서로 확인하고 싶을 때 쓴다. +MySQL general log를 잠깐 켰다가 한 라운드를 돌리고, 대상 피드와 관련된 문장만 시간순으로 뽑는다. + +```bash +FEED_ID=331 USER_IDS=2,3,4,5,6,7 JWT_SECRET='...' \ +DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 ./observe-timeline.sh +``` + +```bash +# 동시 6건: 리스너 6개가 모두 count = 6을 읽는다 +./observe-timeline.sh + +# 순차 5건: 마지막 리스너가 count = 5를 읽고 존재 확인까지 가는 것을 본다 +VUS=5 STAGGER_MS=400 ./observe-timeline.sh +``` + +`STAGGER_MS`를 바꿔 가며 돌리면 동시일 때와 순차일 때 리스너가 읽는 값이 어떻게 달라지는지 볼 수 있다. +general log는 문장마다 기록하므로 이 모드의 응답 시간은 `run-race.sh` 측정치와 비교하지 않는다. +끝나면 원래 general log 설정으로 되돌린다. +기존 `mysql.general_log` 행은 지우지 않고, marker 이후 구간만 잘라서 본다. +라운드 초기화는 general log를 켜기 전에 끝내므로 초기화 `DELETE`는 타임라인에 섞이지 않는다. + +## 결과 읽기 + +`/rounds.csv`에 라운드마다 한 줄씩 쌓인다. + +``` +round,stagger_ms,like_count,popular_count,status_2xx,status_4xx,status_5xx, +transport_error,http_failed_rate,p95_ms,max_ms,fire_skew_max_ms,popular_state,request_state +``` + +상태는 두 축으로 나뉜다. **둘 다 관측값이고, 원인은 담지 않는다.** + +`popular_state` — `popular_feed` 행 개수에서 바로 나온다. + +| popular_state | 조건 | 뜻 | +| --- | --- | --- | +| `not_registered` | `popular_count == 0` | 인기 피드 행이 없다. 그 이상은 말하지 않는다 | +| `registered` | `popular_count == 1` | 인기 피드 행이 1건 있다 | +| `duplicate_rows` | `popular_count >= 2` | 중복 행이 실제로 남았다. 직접 관측이다 | + +`request_state` — 요청 단위 이상 여부. `popular_state`와 분리해서 본다. + +| request_state | 조건 | +| --- | --- | +| `clean` | 4xx / 5xx / 전송 오류 없음, `like_count == --vus` | +| `http_4xx` / `http_5xx` / `transport_error` / `like_count_mismatch` | 해당 오류가 있음. 여러 개면 `+`로 이어 붙는다 | + +`request_state`가 `clean`이 아닌 라운드는 `popular_state`만으로 결론을 내리지 않는다. +집계 출력이 그 라운드 번호를 따로 뽑아 준다. + +원인은 이 표에 없다. 예를 들어 + +- `not_registered`가 `count == 5` 시점을 놓쳐서인지, 리스너의 쓰기가 유실돼서인지 +- `http_5xx`가 유니크 제약 충돌 때문인지 다른 예외 때문인지 + +는 서버 로그의 예외와 `observe-timeline.sh`의 쿼리 순서로 확인한다. +유니크 충돌은 서버 로그에서 해당 예외가 실제로 보일 때만 원인으로 쓴다. + +`/summary.json`과 마지막 `[total]` 출력에 전체 집계가 있다. + +- `popular_state` 분포와 미등록 라운드 비율 (관측값) +- `request_state` 분포와 수동 확인이 필요한 라운드 목록 +- HTTP 실패율 (`4xx + 5xx + 전송 오류` / 전체 요청) +- 전체 라운드의 `http_req_duration` 원시 값을 합쳐 계산한 med / p95 / p99 / max + +라운드별 원시 데이터는 `round-N-raw.csv`(k6 `--out csv`), +k6 콘솔 로그는 `round-N-k6.log`, k6 요약은 `round-N.json`에 남는다. + +`results/`는 git에 올라가지 않는다. + +## 안전 규칙 + +- `BASE_URL`과 `DB_HOST`가 로컬 호스트가 아니면 실행을 거부한다. 우회 옵션은 두지 않았다. +- 라운드 초기화 `DELETE`는 전부 `feed_id = <대상>` 으로 범위를 좁힌다. + 다른 피드, 다른 사용자, 다른 테이블 데이터는 건드리지 않는다. +- 초기화 직후 `like`/`popular_feed`가 0이 아니면 즉시 중단한다. +- **SQL에 들어가는 값은 조회와 `DELETE`보다 먼저 형식을 검증한다.** + - `FEED_ID`는 1 이상의 정수여야 한다. `feed_like_count` / `popular_feed_count` / + `feed_exists` / `reset_feed_state` 각각이 실행 직전에 다시 확인한다. + - `ROUNDS` / `VUS` / `LIKER_COUNT`는 1 이상의 정수, + `START_DELAY_MS` / `SPIN_MS` / `STAGGER_MS` / `SETTLE_MS`는 0 이상의 정수여야 한다. + - `FIXTURE_TAG`는 SQL 문자열 리터럴에 들어가므로 영숫자와 밑줄만, 7자 이하만 허용한다. +- **`observe-timeline.sh`는 `mysql.general_log`를 지우지 않는다.** + 라운드 시작 직전에 남긴 marker 행 시각 이후의 행만 필터링하므로 + 이미 쌓여 있던 로컬 general log가 보존된다. +- 토큰·시크릿·DB 비밀번호는 전부 환경 변수로만 받는다. + +## 자동 검증 + +`PopularFeedLikeRaceScriptTest`가 `./gradlew test`에서 아래를 정적으로 확인한다. +서버나 DB, k6 없이 돈다. + +- 재현 자산 파일이 모두 있는지 +- k6가 호출하는 경로가 `FeedController#likeFeed`의 실제 매핑과 같은지 +- 기본 VU 수가 `PopularFeedApplication`의 임계값 + 1인지 +- 반복 횟수·동시 시작 조절 옵션이 살아 있는지 +- 초기화 `DELETE`가 `feed_id`로 한정되는지, 로컬 가드가 있는지 +- 숫자 입력과 `FIXTURE_TAG` 검증이 걸려 있는지, 피드 조회·삭제 함수가 `FEED_ID`를 다시 확인하는지 +- `observe-timeline.sh`가 `mysql.general_log`를 `TRUNCATE`하지 않고 marker로 구간을 자르는지 +- 집계기가 원인을 단정하는 상태값을 쓰지 않고 `popular_state`와 `request_state`를 분리하는지 +- 토큰이나 시크릿 리터럴이 섞여 들어가지 않았는지 + +> 이 테스트는 스크립트 파일을 Gradle `test` 태스크의 입력으로 선언하지 않았다. +> 자바 코드를 건드리지 않고 스크립트만 고치면 `test`가 UP-TO-DATE로 건너뛴다. +> 스크립트를 고친 뒤에는 `./gradlew test --tests "*PopularFeedLikeRaceScriptTest*" --rerun-tasks` +> 로 확인한다. diff --git a/scripts/load/popular-feed-like-race/lib.sh b/scripts/load/popular-feed-like-race/lib.sh new file mode 100644 index 000000000..e2a52ecf2 --- /dev/null +++ b/scripts/load/popular-feed-like-race/lib.sh @@ -0,0 +1,148 @@ +#!/usr/bin/env bash +# 이슈 #620 재현 스크립트 공용 함수. +# 직접 실행하지 않고 seed-fixture.sh / run-race.sh 에서 source 한다. + +set -euo pipefail + +# --- 환경 변수 기본값 ------------------------------------------------------- +BASE_URL="${BASE_URL:-http://localhost:8080}" + +DB_HOST="${DB_HOST:-127.0.0.1}" +DB_PORT="${DB_PORT:-3306}" +DB_USER="${DB_USER:-root}" +DB_NAME="${DB_NAME:-websoso}" +# DB_PASSWORD 는 기본값을 두지 않는다. 없으면 빈 문자열로 접속을 시도한다. +DB_PASSWORD="${DB_PASSWORD:-}" +# 로컬 MySQL이 컨테이너 안에만 있으면 컨테이너 이름을 지정한다. 예: websoso-mysql +DB_DOCKER_CONTAINER="${DB_DOCKER_CONTAINER:-}" + +# --- 안전 가드 -------------------------------------------------------------- +# 운영/공유 개발 서버를 대상으로는 절대 실행하지 않는다. 우회 옵션을 두지 않는다. +LOCAL_HOSTS_REGEX='^(localhost|127\.0\.0\.1|\[::1\]|::1|0\.0\.0\.0|host\.docker\.internal)$' + +extract_host() { + # http://host:port/path -> host + printf '%s' "$1" | sed -E 's#^[a-zA-Z]+://##; s#/.*$##; s#:[0-9]+$##; s#^.*@##' +} + +assert_local_target() { + local url_host db_host + url_host="$(extract_host "${BASE_URL}")" + db_host="$(extract_host "${DB_HOST}")" + + if ! printf '%s' "${url_host}" | grep -Eq "${LOCAL_HOSTS_REGEX}"; then + echo "거부: BASE_URL 호스트가 로컬이 아니다 (${url_host}). 이 스크립트는 로컬/비운영 환경 전용이다." >&2 + exit 2 + fi + if [[ -z "${DB_DOCKER_CONTAINER}" ]] \ + && ! printf '%s' "${db_host}" | grep -Eq "${LOCAL_HOSTS_REGEX}"; then + echo "거부: DB_HOST가 로컬이 아니다 (${db_host}). 공유 DB에 대한 초기화는 수행하지 않는다." >&2 + exit 2 + fi +} + +# --- MySQL 실행 ------------------------------------------------------------- +mysql_exec() { + # stdin으로 받은 SQL을 실행하고 결과를 탭 구분 텍스트(헤더 없음)로 출력한다. + if [[ -n "${DB_DOCKER_CONTAINER}" ]]; then + docker exec -i "${DB_DOCKER_CONTAINER}" \ + mysql -u"${DB_USER}" ${DB_PASSWORD:+-p"${DB_PASSWORD}"} \ + -D "${DB_NAME}" --default-character-set=utf8mb4 -N -B \ + 2> >(grep -v 'Using a password on the command line' >&2) + else + mysql -h "${DB_HOST}" -P "${DB_PORT}" -u "${DB_USER}" \ + ${DB_PASSWORD:+-p"${DB_PASSWORD}"} \ + -D "${DB_NAME}" --default-character-set=utf8mb4 -N -B \ + 2> >(grep -v 'Using a password on the command line' >&2) + fi +} + +mysql_scalar() { + # $1: SQL. 첫 컬럼 첫 행만 반환한다. + printf '%s\n' "$1" | mysql_exec | head -n 1 +} + +assert_db_reachable() { + if ! printf 'SELECT 1;\n' | mysql_exec >/dev/null; then + echo "거부: MySQL에 접속할 수 없다. DB_HOST/DB_PORT/DB_USER/DB_PASSWORD/DB_NAME 또는 DB_DOCKER_CONTAINER를 확인한다." >&2 + exit 2 + fi +} + +require_env() { + local name="$1" + if [[ -z "${!name:-}" ]]; then + echo "거부: 환경 변수 ${name}가 필요하다." >&2 + exit 2 + fi +} + +# --- 입력 검증 -------------------------------------------------------------- +# 아래 값들은 SQL 문자열이나 셸 명령에 그대로 들어간다. +# 조회와 DELETE보다 먼저 형식을 확인해서 의도하지 않은 문장이 만들어지지 않게 한다. + +# 1 이상의 정수. 앞자리 0이나 부호, 공백을 허용하지 않는다. +require_positive_int() { + local name="$1" value="$2" + if ! [[ "${value}" =~ ^[1-9][0-9]*$ ]]; then + echo "거부: ${name}는 1 이상의 정수여야 한다 (현재 값: '${value}')." >&2 + exit 2 + fi +} + +# 0 이상의 정수. +require_non_negative_int() { + local name="$1" value="$2" + if ! [[ "${value}" =~ ^(0|[1-9][0-9]*)$ ]]; then + echo "거부: ${name}는 0 이상의 정수여야 한다 (현재 값: '${value}')." >&2 + exit 2 + fi +} + +# SQL 문자열 리터럴에 들어가는 식별자. 영숫자와 밑줄만 허용한다. +require_sql_safe_tag() { + local name="$1" value="$2" max_length="$3" + if ! [[ "${value}" =~ ^[A-Za-z0-9_]+$ ]]; then + echo "거부: ${name}는 영문자·숫자·밑줄만 쓸 수 있다 (현재 값: '${value}')." >&2 + exit 2 + fi + if [[ ${#value} -gt ${max_length} ]]; then + echo "거부: ${name}는 ${max_length}자 이하여야 한다 (현재 길이: ${#value})." >&2 + exit 2 + fi +} + +# 피드 PK. 모든 조회와 DELETE 앞에서 호출한다. +require_feed_id() { + require_positive_int "FEED_ID" "${1:-}" +} + +# --- 피드 상태 조회/초기화 -------------------------------------------------- +feed_like_count() { + require_feed_id "${1:-}" + mysql_scalar "SELECT COUNT(*) FROM \`like\` WHERE feed_id = ${1};" +} + +popular_feed_count() { + require_feed_id "${1:-}" + mysql_scalar "SELECT COUNT(*) FROM popular_feed WHERE feed_id = ${1};" +} + +feed_exists() { + require_feed_id "${1:-}" + mysql_scalar "SELECT COUNT(*) FROM feed WHERE feed_id = ${1};" +} + +# 대상 피드 한 건에만 한정된 초기화다. 다른 피드나 사용자 데이터는 건드리지 않는다. +reset_feed_state() { + require_feed_id "${1:-}" + local feed_id="$1" + printf '%s\n' " + DELETE rn FROM read_notification rn + JOIN notification n ON n.notification_id = rn.notification_id + WHERE n.feed_id = ${feed_id}; + DELETE FROM notification WHERE feed_id = ${feed_id}; + DELETE FROM popular_feed WHERE feed_id = ${feed_id}; + DELETE FROM \`like\` WHERE feed_id = ${feed_id}; + " | mysql_exec +} diff --git a/scripts/load/popular-feed-like-race/like-race.js b/scripts/load/popular-feed-like-race/like-race.js new file mode 100644 index 000000000..2a814c814 --- /dev/null +++ b/scripts/load/popular-feed-like-race/like-race.js @@ -0,0 +1,257 @@ +/* + * 이슈 #620 재현 시나리오 + * + * 하나의 피드에 서로 다른 사용자 N명(기본 6명)이 거의 동시에 좋아요를 보낸다. + * 모든 VU는 setup()이 정한 공통 시작 시각까지 대기했다가 동시에 POST를 발사한다. + * + * 프로덕션 코드는 건드리지 않는다. 이 스크립트는 관측만 한다. + * + * 필수 환경 변수 + * BASE_URL 대상 서버 (예: http://localhost:8080). 로컬/비운영 환경만 사용한다. + * FEED_ID 좋아요 대상 피드 PK + * + * 토큰 지정 방식 (둘 중 하나) + * TOKENS 콤마로 구분한 Access Token 목록. VU 수만큼 필요하다. + * JWT_SECRET + USER_IDS. 로컬에서 Access Token을 직접 서명해 만든다. + * 서명 방식은 JwtProvider/JwtKeyProvider 계약과 동일하다. + * HMAC 키는 시크릿 원문이 아니라 Base64(시크릿 UTF-8)의 ASCII 바이트다. + * + * 선택 환경 변수 + * VUS 동시 사용자 수 (기본 6) + * START_DELAY_MS setup() 이후 동시 발사까지의 리드타임 (기본 1500) + * SPIN_MS 발사 직전 busy-spin 구간 (기본 20). 이 구간만 sleep 없이 돈다. + * STAGGER_MS VU별 발사 간격 (기본 0 = 완전 동시). n번째 VU는 (n-1)*STAGGER_MS만큼 늦게 쏜다. + * 0에서 키워 가며 어느 간격부터 판정이 정상으로 돌아오는지 관찰할 수 있다. + * ROUND 반복 회차 라벨. 결과 JSON에 그대로 기록된다. + * SUMMARY_PATH 라운드 요약 JSON 출력 경로 (기본 stdout만) + * TOKEN_TTL_SEC JWT_SECRET 모드에서 발급할 토큰 수명 (기본 600) + */ + +import { sleep } from 'k6'; +import http from 'k6/http'; +import crypto from 'k6/crypto'; +import encoding from 'k6/encoding'; +import exec from 'k6/execution'; +import { Counter, Trend } from 'k6/metrics'; + +const BASE_URL = requireEnv('BASE_URL').replace(/\/+$/, ''); +const FEED_ID = requireEnv('FEED_ID'); +const VUS = intEnv('VUS', 6); +const START_DELAY_MS = intEnv('START_DELAY_MS', 1500); +const SPIN_MS = intEnv('SPIN_MS', 20); +const STAGGER_MS = intEnv('STAGGER_MS', 0); +const ROUND = __ENV.ROUND || '1'; +const SUMMARY_PATH = __ENV.SUMMARY_PATH || ''; +const TOKEN_TTL_SEC = intEnv('TOKEN_TTL_SEC', 600); + +const TOKENS = resolveTokens(VUS); + +const likeDuration = new Trend('like_req_duration', true); +const likeStatus2xx = new Counter('like_status_2xx'); +const likeStatus4xx = new Counter('like_status_4xx'); +const likeStatus5xx = new Counter('like_status_5xx'); +const likeTransportError = new Counter('like_transport_error'); +const fireSkew = new Trend('like_fire_skew_ms', true); + +export const options = { + scenarios: { + simultaneous_like: { + executor: 'per-vu-iterations', + vus: VUS, + iterations: 1, + maxDuration: '60s', + }, + }, + // 이 시나리오는 임계값으로 실행을 중단시키지 않는다. 판정은 DB 상태로 한다. + thresholds: {}, + summaryTrendStats: ['avg', 'min', 'med', 'p(90)', 'p(95)', 'p(99)', 'max'], + discardResponseBodies: false, +}; + +export function setup() { + return { startAtMs: Date.now() + START_DELAY_MS }; +} + +export default function (data) { + const vu = exec.vu.idInTest; // 1..VUS + const token = TOKENS[(vu - 1) % TOKENS.length]; + + const targetAtMs = data.startAtMs + (vu - 1) * STAGGER_MS; + waitUntil(targetAtMs); + + const firedAt = Date.now(); + fireSkew.add(firedAt - targetAtMs); + + const res = http.post( + `${BASE_URL}/feeds/${FEED_ID}/likes`, + null, + { + headers: { Authorization: `Bearer ${token}` }, + tags: { name: 'POST /feeds/{feedId}/likes', round: ROUND }, + timeout: '30s', + }, + ); + + likeDuration.add(res.timings.duration); + + if (res.error_code !== 0 && res.status === 0) { + likeTransportError.add(1); + } else if (res.status >= 500) { + likeStatus5xx.add(1); + } else if (res.status >= 400) { + likeStatus4xx.add(1); + } else { + likeStatus2xx.add(1); + } + + console.log(JSON.stringify({ + round: ROUND, + vu, + staggerMs: STAGGER_MS, + firedAtMs: firedAt, + skewMs: firedAt - targetAtMs, + status: res.status, + errorCode: res.error_code, + durationMs: Math.round(res.timings.duration * 1000) / 1000, + body: res.status >= 400 ? String(res.body || '').slice(0, 500) : '', + })); +} + +export function handleSummary(summary) { + const duration = summary.metrics.like_req_duration || { values: {} }; + const skew = summary.metrics.like_fire_skew_ms || { values: {} }; + const httpFailed = summary.metrics.http_req_failed || { values: {} }; + + const round = { + round: ROUND, + vus: VUS, + staggerMs: STAGGER_MS, + feedId: FEED_ID, + requests: counter(summary, 'like_status_2xx') + counter(summary, 'like_status_4xx') + + counter(summary, 'like_status_5xx') + counter(summary, 'like_transport_error'), + status2xx: counter(summary, 'like_status_2xx'), + status4xx: counter(summary, 'like_status_4xx'), + status5xx: counter(summary, 'like_status_5xx'), + transportError: counter(summary, 'like_transport_error'), + httpReqFailedRate: numberOrNull(httpFailed.values && httpFailed.values.rate), + durationMs: { + avg: numberOrNull(duration.values['avg']), + min: numberOrNull(duration.values['min']), + med: numberOrNull(duration.values['med']), + p90: numberOrNull(duration.values['p(90)']), + p95: numberOrNull(duration.values['p(95)']), + p99: numberOrNull(duration.values['p(99)']), + max: numberOrNull(duration.values['max']), + }, + fireSkewMs: { + min: numberOrNull(skew.values['min']), + med: numberOrNull(skew.values['med']), + max: numberOrNull(skew.values['max']), + }, + }; + + const out = { stdout: `round ${ROUND}: ${JSON.stringify(round)}\n` }; + if (SUMMARY_PATH) { + out[SUMMARY_PATH] = JSON.stringify(round, null, 2); + } + return out; +} + +// ---------------------------------------------------------------- helpers + +function counter(summary, name) { + const metric = summary.metrics[name]; + return metric && metric.values ? metric.values.count || 0 : 0; +} + +function numberOrNull(value) { + return typeof value === 'number' && isFinite(value) ? Math.round(value * 1000) / 1000 : null; +} + +function requireEnv(name) { + const value = __ENV[name]; + if (!value) { + throw new Error(`환경 변수 ${name}가 필요하다.`); + } + return value; +} + +function intEnv(name, fallback) { + const raw = __ENV[name]; + if (raw === undefined || raw === '') return fallback; + const parsed = parseInt(raw, 10); + if (isNaN(parsed)) { + throw new Error(`환경 변수 ${name}는 정수여야 한다: ${raw}`); + } + return parsed; +} + +/** + * 목표 시각까지 대기한다. + * 대기 대부분은 sleep으로 CPU를 양보하고, 마지막 SPIN_MS 구간만 busy-spin으로 정렬한다. + * 전 구간을 busy-spin으로 돌면 VU들이 CPU를 잡아먹어 측정 자체가 흔들린다. + */ +function waitUntil(targetAtMs) { + for (;;) { + const remainingMs = targetAtMs - Date.now() - SPIN_MS; + if (remainingMs <= 0) break; + sleep(Math.min(remainingMs, 100) / 1000); + } + while (Date.now() < targetAtMs) { + // 최종 정렬 구간 + } +} + +/** + * TOKENS가 있으면 그대로 쓰고, 없으면 JWT_SECRET + USER_IDS로 Access Token을 서명한다. + * 토큰은 절대 저장소에 커밋하지 않는다. 환경 변수로만 주입한다. + */ +function resolveTokens(required) { + const raw = __ENV.TOKENS; + if (raw) { + const tokens = raw.split(',').map((t) => t.trim()).filter(Boolean); + if (tokens.length < required) { + throw new Error(`TOKENS에 ${required}개가 필요하다. 현재 ${tokens.length}개.`); + } + return tokens; + } + + const secret = __ENV.JWT_SECRET; + const userIds = (__ENV.USER_IDS || '').split(',').map((v) => v.trim()).filter(Boolean); + if (!secret || userIds.length === 0) { + throw new Error('TOKENS 또는 (JWT_SECRET + USER_IDS)를 지정해야 한다.'); + } + if (userIds.length < required) { + throw new Error(`USER_IDS에 ${required}개가 필요하다. 현재 ${userIds.length}개.`); + } + if (new Set(userIds).size !== userIds.length) { + throw new Error('USER_IDS에 중복된 사용자 ID가 있다. 서로 다른 사용자여야 한다.'); + } + return userIds.map((id) => signAccessToken(secret, id)); +} + +/** + * JwtProvider와 동일한 Access Token을 만든다. + * - alg HS256, typ JWT + * - sub "access", iat/exp(초), userId 클레임 + * - HMAC 키는 JwtKeyProvider와 같이 Base64(secret UTF-8) 문자열의 바이트다. + */ +function signAccessToken(secret, userId) { + const nowSec = Math.floor(Date.now() / 1000); + const header = { typ: 'JWT', alg: 'HS256' }; + const payload = { + sub: 'access', + iat: nowSec, + exp: nowSec + TOKEN_TTL_SEC, + userId: parseInt(userId, 10), + }; + + const signingInput = `${b64url(JSON.stringify(header))}.${b64url(JSON.stringify(payload))}`; + const key = encoding.b64encode(secret, 'std'); + const signature = crypto.hmac('sha256', key, signingInput, 'base64rawurl'); + return `${signingInput}.${signature}`; +} + +function b64url(text) { + return encoding.b64encode(text, 'rawurl'); +} diff --git a/scripts/load/popular-feed-like-race/observe-timeline.sh b/scripts/load/popular-feed-like-race/observe-timeline.sh new file mode 100755 index 000000000..c1101ddcb --- /dev/null +++ b/scripts/load/popular-feed-like-race/observe-timeline.sh @@ -0,0 +1,129 @@ +#!/usr/bin/env bash +# 한 라운드를 MySQL general log와 함께 실행해 서버가 실제로 어떤 순서로 쿼리를 보냈는지 본다. +# +# 무엇을 알 수 있나 +# - 좋아요 INSERT/COMMIT이 얼마나 촘촘히 붙어 있는지 +# - AFTER_COMMIT 리스너의 count(*)가 커밋들보다 앞서는지 뒤서는지 +# - 판정 구간에 popular_feed SELECT/INSERT가 나오는지, 어디까지 진행되고 멈추는지 +# +# 주의 +# general log는 문장마다 기록하기 때문에 응답 시간을 늘린다. +# 이 모드에서 나온 latency는 run-race.sh의 측정치와 비교하지 않는다. +# 로컬 전용이며, 끝나면 general log 설정을 원래대로 되돌린다. +# +# mysql.general_log 테이블은 지우지 않는다. 라운드 시작 직전에 남긴 marker 행을 찾아 +# 그 시각 이후의 행만 필터링하므로, 이미 쌓여 있던 로컬 general log는 그대로 보존된다. +# +# 사용법 +# FEED_ID=331 USER_IDS=2,3,4,5,6,7 JWT_SECRET='...' \ +# DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=1234 ./observe-timeline.sh + +set -euo pipefail +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +# shellcheck source=lib.sh +source "${SCRIPT_DIR}/lib.sh" + +VUS="${VUS:-6}" +STAGGER_MS="${STAGGER_MS:-0}" +OUT_DIR="${OUT_DIR:-${SCRIPT_DIR}/results/timeline-$(date +%Y%m%d-%H%M%S)}" +K6_BIN="${K6_BIN:-k6}" + +require_env FEED_ID +if [[ -z "${TOKENS:-}" ]]; then + require_env USER_IDS + require_env JWT_SECRET +fi + +# DB 조회와 DELETE가 실행되기 전에 숫자 입력을 먼저 검증한다. +require_feed_id "${FEED_ID}" +require_positive_int "VUS" "${VUS}" +require_non_negative_int "STAGGER_MS" "${STAGGER_MS}" + +assert_local_target +assert_db_reachable +mkdir -p "${OUT_DIR}" + +# 이번 실행 구간을 찾기 위한 marker. 영숫자와 밑줄만 쓴다. +MARKER="WSS620_MARKER_$(date +%s)_$$" +require_sql_safe_tag "MARKER" "${MARKER}" 64 + +PREV_LOG_OUTPUT="$(mysql_scalar "SELECT @@global.log_output;")" +PREV_GENERAL_LOG="$(mysql_scalar "SELECT @@global.general_log;")" + +restore_general_log() { + printf '%s\n' " + SET GLOBAL general_log = ${PREV_GENERAL_LOG}; + SET GLOBAL log_output = '${PREV_LOG_OUTPUT}'; + " | mysql_exec || true +} +trap restore_general_log EXIT + +# 초기화는 general log를 켜기 전에 끝낸다. 초기화 DELETE가 타임라인에 섞이지 않게 한다. +reset_feed_state "${FEED_ID}" + +echo "[timeline] general log를 켠다 (원래 값: log_output=${PREV_LOG_OUTPUT}, general_log=${PREV_GENERAL_LOG})" +echo "[timeline] 기존 general log 행은 지우지 않는다. marker=${MARKER}" +printf '%s\n' " + SET GLOBAL log_output = 'TABLE'; + SET GLOBAL general_log = 'ON'; + SELECT '${MARKER}' AS marker; +" | mysql_exec > /dev/null + +BASE_URL="${BASE_URL}" \ +FEED_ID="${FEED_ID}" \ +VUS="${VUS}" \ +STAGGER_MS="${STAGGER_MS}" \ +ROUND="timeline" \ +SUMMARY_PATH="${OUT_DIR}/round.json" \ +TOKENS="${TOKENS:-}" \ +USER_IDS="${USER_IDS:-}" \ +JWT_SECRET="${JWT_SECRET:-}" \ + "${K6_BIN}" run --quiet --no-usage-report "${SCRIPT_DIR}/like-race.js" \ + > "${OUT_DIR}/k6.log" 2>&1 + +python3 -c "import time; time.sleep(1.5)" + +printf '%s\n' "SET GLOBAL general_log = 'OFF';" | mysql_exec + +LIKE_COUNT="$(feed_like_count "${FEED_ID}")" +POPULAR_COUNT="$(popular_feed_count "${FEED_ID}")" + +# marker 행 이후, 대상 피드와 관련된 문장만 시간순으로 뽑는다. +# marker를 심은 문장 자체와 general log를 읽는 문장은 결과에서 제외한다. +printf '%s\n' " + SET @marker_at := ( + SELECT MIN(event_time) FROM mysql.general_log + WHERE command_type = 'Query' + AND CONVERT(argument USING utf8mb4) LIKE '%${MARKER}%' + ); + SELECT DATE_FORMAT(event_time, '%H:%i:%s.%f') AS at, + thread_id, + REPLACE(REPLACE(LEFT(CONVERT(argument USING utf8mb4), 160), '\n', ' '), '\t', ' ') AS stmt + FROM mysql.general_log + WHERE command_type = 'Query' + AND @marker_at IS NOT NULL + AND event_time >= @marker_at + AND CONVERT(argument USING utf8mb4) NOT LIKE '%${MARKER}%' + AND CONVERT(argument USING utf8mb4) NOT LIKE '%general_log%' + AND ( + CONVERT(argument USING utf8mb4) LIKE '%popular_feed%' + OR CONVERT(argument USING utf8mb4) LIKE '%\`like\`%' + OR CONVERT(argument USING utf8mb4) LIKE 'commit' + OR CONVERT(argument USING utf8mb4) LIKE 'SET autocommit%' + ) + ORDER BY event_time, thread_id; +" | mysql_exec > "${OUT_DIR}/timeline.tsv" + +cat <&2; usage 2 ;; + esac +done + +require_env FEED_ID +if [[ -z "${TOKENS:-}" ]]; then + require_env USER_IDS + require_env JWT_SECRET +fi + +# DB 조회와 DELETE가 실행되기 전에 숫자 입력을 먼저 검증한다. +require_feed_id "${FEED_ID}" +require_positive_int "ROUNDS" "${ROUNDS}" +require_positive_int "VUS" "${VUS}" +require_non_negative_int "START_DELAY_MS" "${START_DELAY_MS}" +require_non_negative_int "SPIN_MS" "${SPIN_MS}" +require_non_negative_int "STAGGER_MS" "${STAGGER_MS}" +require_non_negative_int "SETTLE_MS" "${SETTLE_MS}" + +if ! command -v "${K6_BIN}" >/dev/null 2>&1; then + echo "거부: k6를 찾을 수 없다 (${K6_BIN}). 설치 후 다시 실행한다." >&2 + exit 2 +fi + +assert_local_target +assert_db_reachable + +if [[ "$(feed_exists "${FEED_ID}")" != "1" ]]; then + echo "거부: feed_id=${FEED_ID} 가 존재하지 않는다. seed-fixture.sh로 픽스처를 먼저 만든다." >&2 + exit 2 +fi + +if ! curl -sS -o /dev/null -m 5 "${BASE_URL}/actuator/health" 2>/dev/null; then + echo "경고: ${BASE_URL}/actuator/health 응답을 확인하지 못했다. 서버 기동 상태를 확인한다." >&2 +fi + +if [[ -z "${OUT_DIR}" ]]; then + OUT_DIR="${SCRIPT_DIR}/results/$(date +%Y%m%d-%H%M%S)" +fi +mkdir -p "${OUT_DIR}" + +CSV="${OUT_DIR}/rounds.csv" +echo "round,stagger_ms,like_count,popular_count,status_2xx,status_4xx,status_5xx,transport_error,http_failed_rate,p95_ms,max_ms,fire_skew_max_ms,popular_state,request_state" > "${CSV}" + +echo "[run] 대상 ${BASE_URL} / feed_id=${FEED_ID} / vus=${VUS} / rounds=${ROUNDS} / stagger=${STAGGER_MS}ms" +echo "[run] 결과 디렉터리 ${OUT_DIR}" + +for ((round = 1; round <= ROUNDS; round++)); do + reset_feed_state "${FEED_ID}" + + before_like="$(feed_like_count "${FEED_ID}")" + before_popular="$(popular_feed_count "${FEED_ID}")" + if [[ "${before_like}" != "0" || "${before_popular}" != "0" ]]; then + echo "거부: 초기화 후에도 like=${before_like}, popular_feed=${before_popular} 이다. 중단한다." >&2 + exit 3 + fi + + summary_json="${OUT_DIR}/round-${round}.json" + raw_csv="${OUT_DIR}/round-${round}-raw.csv" + k6_log="${OUT_DIR}/round-${round}-k6.log" + + set +e + BASE_URL="${BASE_URL}" \ + FEED_ID="${FEED_ID}" \ + VUS="${VUS}" \ + START_DELAY_MS="${START_DELAY_MS}" \ + SPIN_MS="${SPIN_MS}" \ + STAGGER_MS="${STAGGER_MS}" \ + ROUND="${round}" \ + SUMMARY_PATH="${summary_json}" \ + TOKENS="${TOKENS:-}" \ + USER_IDS="${USER_IDS:-}" \ + JWT_SECRET="${JWT_SECRET:-}" \ + "${K6_BIN}" run --quiet --no-usage-report \ + --out "csv=${raw_csv}" \ + "${SCRIPT_DIR}/like-race.js" > "${k6_log}" 2>&1 + k6_exit=$? + set -e + + if [[ ${k6_exit} -ne 0 || ! -f "${summary_json}" ]]; then + echo "실패: 라운드 ${round} k6 실행 오류(exit=${k6_exit}). ${k6_log} 참고." >&2 + tail -n 20 "${k6_log}" >&2 + exit 4 + fi + + # DB 최종 상태 관측을 안정화하기 위한 유예다. + # 현재 구현의 AFTER_COMMIT 리스너에는 @Async가 없어 요청 스레드에서 동기 실행되므로 + # 응답이 돌아온 시점에는 리스너가 이미 끝나 있다. 즉 필수 대기는 아니다. + python3 -c "import time,sys; time.sleep(int(sys.argv[1])/1000)" "${SETTLE_MS}" + + like_count="$(feed_like_count "${FEED_ID}")" + popular_count="$(popular_feed_count "${FEED_ID}")" + + python3 "${SCRIPT_DIR}/summarize.py" round \ + --summary "${summary_json}" \ + --like-count "${like_count}" \ + --popular-count "${popular_count}" \ + --expected-likes "${VUS}" >> "${CSV}" + + tail -n 1 "${CSV}" +done + +echo +python3 "${SCRIPT_DIR}/summarize.py" total \ + --csv "${CSV}" \ + --raw-glob "${OUT_DIR}/round-*-raw.csv" \ + --expected-likes "${VUS}" \ + --json-out "${OUT_DIR}/summary.json" diff --git a/scripts/load/popular-feed-like-race/seed-fixture.sh b/scripts/load/popular-feed-like-race/seed-fixture.sh new file mode 100755 index 000000000..67207cd4b --- /dev/null +++ b/scripts/load/popular-feed-like-race/seed-fixture.sh @@ -0,0 +1,111 @@ +#!/usr/bin/env bash +# 이슈 #620 재현용 로컬 픽스처를 만든다. +# +# 만드는 것 +# - 아바타/아바타 프로필 1건 (사용자 생성 제약 충족용) +# - 알림 타입 3건 (좋아요 / 댓글 / 지금뜨는글). 없으면 좋아요 알림 저장이 실패한다. +# - 소설 1건 (인기 피드 판정은 novelId가 있는 피드만 대상으로 한다) +# - 작성자 1명 + 좋아요를 누를 사용자 N명 (기본 6명) +# - 대상 피드 1건 +# +# 이미 만들어 둔 픽스처가 있으면 다시 만들지 않고 기존 ID를 그대로 출력한다. +# 로컬 전용이다. 원격/공유 DB에서는 실행을 거부한다. +# +# 사용법 +# DB_DOCKER_CONTAINER=websoso-mysql DB_PASSWORD=... ./seed-fixture.sh +# LIKER_COUNT=6 ./seed-fixture.sh + +set -euo pipefail +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +# shellcheck source=lib.sh +source "${SCRIPT_DIR}/lib.sh" + +LIKER_COUNT="${LIKER_COUNT:-6}" +FIXTURE_TAG="${FIXTURE_TAG:-race620}" + +# FIXTURE_TAG는 아래 INSERT의 SQL 문자열 리터럴에 그대로 들어간다. +# 영숫자와 밑줄만 허용하고, nickname 컬럼이 varchar(10)이라 태그는 7자 이하로 제한한다. +require_sql_safe_tag "FIXTURE_TAG" "${FIXTURE_TAG}" 7 +require_positive_int "LIKER_COUNT" "${LIKER_COUNT}" + +assert_local_target +assert_db_reachable + +echo "[seed] 대상 DB: ${DB_DOCKER_CONTAINER:-${DB_HOST}:${DB_PORT}}/${DB_NAME}" + +# --- 공통 마스터 데이터 ----------------------------------------------------- +printf '%s\n' " + INSERT INTO avatar (avatar_id, avatar_image, avatar_name) + SELECT 1, 'seed', 'seed' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM avatar WHERE avatar_id = 1); + + INSERT INTO avatar_profile (avatar_profile_id, avatar_character_image, avatar_profile_image, avatar_profile_name, avatar_id) + SELECT 1, 'seed', 'seed', 'seed', 1 + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM avatar_profile WHERE avatar_profile_id = 1); + + INSERT INTO notification_type (notification_type_image, notification_type_name) + SELECT 'seed', '좋아요' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM notification_type WHERE notification_type_name = '좋아요'); + INSERT INTO notification_type (notification_type_image, notification_type_name) + SELECT 'seed', '댓글' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM notification_type WHERE notification_type_name = '댓글'); + INSERT INTO notification_type (notification_type_image, notification_type_name) + SELECT 'seed', '지금뜨는글' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM notification_type WHERE notification_type_name = '지금뜨는글'); + + INSERT INTO novel (author, is_completed, novel_description, novel_image, title) + SELECT '${FIXTURE_TAG}', 0, '${FIXTURE_TAG} 재현용', 'seed', '${FIXTURE_TAG}-novel' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM novel WHERE title = '${FIXTURE_TAG}-novel'); +" | mysql_exec + +NOVEL_ID="$(mysql_scalar "SELECT novel_id FROM novel WHERE title = '${FIXTURE_TAG}-novel' LIMIT 1;")" + +# --- 사용자 ----------------------------------------------------------------- +create_user() { + local nickname="$1" + printf '%s\n' " + INSERT INTO user (created_date, modified_date, avatar_id, avatar_profile_id, birth, email, + gender, intro, is_profile_public, is_push_enabled, marketing_agreed, + nickname, privacy_agreed, role, service_agreed, social_id) + SELECT NOW(6), NOW(6), 1, 1, 2000, NULL, + 'M', '${FIXTURE_TAG}', 1, 1, 0, + '${nickname}', 1, 'USER', 1, '${FIXTURE_TAG}-${nickname}' + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM user WHERE nickname = '${nickname}'); + " | mysql_exec + mysql_scalar "SELECT user_id FROM user WHERE nickname = '${nickname}' LIMIT 1;" +} + +WRITER_NICKNAME="${FIXTURE_TAG}w" +WRITER_ID="$(create_user "${WRITER_NICKNAME}")" + +LIKER_IDS=() +for ((i = 1; i <= LIKER_COUNT; i++)); do + LIKER_IDS+=("$(create_user "${FIXTURE_TAG}l${i}")") +done +USER_IDS="$(IFS=,; echo "${LIKER_IDS[*]}")" + +# --- 대상 피드 --------------------------------------------------------------- +FEED_CONTENT="${FIXTURE_TAG}-target-feed" +printf '%s\n' " + INSERT INTO feed (created_date, feed_content, is_hidden, is_public, is_spoiler, modified_date, novel_id, user_id) + SELECT NOW(6), '${FEED_CONTENT}', 0, 1, b'0', NOW(6), ${NOVEL_ID}, ${WRITER_ID} + FROM DUAL WHERE NOT EXISTS (SELECT 1 FROM feed WHERE feed_content = '${FEED_CONTENT}'); +" | mysql_exec + +FEED_ID="$(mysql_scalar "SELECT feed_id FROM feed WHERE feed_content = '${FEED_CONTENT}' LIMIT 1;")" + +cat < 0: + flags.append(REQUEST_HTTP_4XX) + if status_5xx > 0: + flags.append(REQUEST_HTTP_5XX) + if transport_error > 0: + flags.append(REQUEST_TRANSPORT_ERROR) + if like_count != expected_likes: + flags.append(REQUEST_LIKE_COUNT_MISMATCH) + return "+".join(flags) if flags else REQUEST_CLEAN + + +def percentile(sorted_values, ratio): + """선형 보간 백분위수. k6의 p(95)와 같은 방식이다.""" + if not sorted_values: + return None + if len(sorted_values) == 1: + return sorted_values[0] + position = ratio * (len(sorted_values) - 1) + lower = int(position) + upper = min(lower + 1, len(sorted_values) - 1) + weight = position - lower + return sorted_values[lower] * (1 - weight) + sorted_values[upper] * weight + + +def cmd_round(args): + with open(args.summary, encoding="utf-8") as f: + summary = json.load(f) + + status_4xx = int(summary.get("status4xx", 0)) + status_5xx = int(summary.get("status5xx", 0)) + transport_error = int(summary.get("transportError", 0)) + + popular_state = classify_popular_state(int(args.popular_count)) + request_state = classify_request_state( + status_4xx, + status_5xx, + transport_error, + int(args.like_count), + int(args.expected_likes), + ) + + duration = summary.get("durationMs") or {} + skew = summary.get("fireSkewMs") or {} + + row = [ + summary.get("round", ""), + summary.get("staggerMs", 0), + args.like_count, + args.popular_count, + summary.get("status2xx", 0), + status_4xx, + status_5xx, + transport_error, + summary.get("httpReqFailedRate"), + duration.get("p95"), + duration.get("max"), + skew.get("max"), + popular_state, + request_state, + ] + writer = csv.writer(sys.stdout, lineterminator="\n") + writer.writerow(["" if v is None else v for v in row]) + + +def load_raw_durations(pattern): + """k6 --out csv 결과에서 http_req_duration 값(ms)만 모은다.""" + durations = [] + for path in sorted(glob.glob(pattern)): + with open(path, encoding="utf-8") as f: + for record in csv.DictReader(f): + if record.get("metric_name") == "http_req_duration": + try: + durations.append(float(record["metric_value"])) + except (KeyError, TypeError, ValueError): + continue + return durations + + +def cmd_total(args): + popular_states = Counter() + request_states = Counter() + rounds = 0 + total_requests = 0 + failed_requests = 0 + dirty_rounds = [] + + with open(args.csv, encoding="utf-8") as f: + for record in csv.DictReader(f): + rounds += 1 + popular_states[record["popular_state"]] += 1 + request_state = record["request_state"] + request_states[request_state] += 1 + if request_state != REQUEST_CLEAN: + dirty_rounds.append("{}({})".format(record["round"], request_state)) + ok = int(record["status_2xx"] or 0) + bad = (int(record["status_4xx"] or 0) + + int(record["status_5xx"] or 0) + + int(record["transport_error"] or 0)) + total_requests += ok + bad + failed_requests += bad + + durations = sorted(load_raw_durations(args.raw_glob)) + + result = { + "rounds": rounds, + "expectedLikesPerRound": int(args.expected_likes), + "popularState": {state: popular_states[state] for state in POPULAR_STATES}, + "requestState": dict(sorted(request_states.items())), + "roundsNeedingManualReview": dirty_rounds, + "http": { + "requests": total_requests, + "failed": failed_requests, + "failedRate": round(failed_requests / total_requests, 6) if total_requests else None, + }, + "durationMs": { + "samples": len(durations), + "min": round(durations[0], 3) if durations else None, + "med": round(percentile(durations, 0.50), 3) if durations else None, + "p95": round(percentile(durations, 0.95), 3) if durations else None, + "p99": round(percentile(durations, 0.99), 3) if durations else None, + "max": round(durations[-1], 3) if durations else None, + }, + } + + if args.json_out: + with open(args.json_out, "w", encoding="utf-8") as f: + json.dump(result, f, ensure_ascii=False, indent=2) + f.write("\n") + + not_registered = result["popularState"][POPULAR_NOT_REGISTERED] + print("[total] 라운드 {}회".format(rounds)) + print("[total] popular_feed 행 상태 미등록 {} / 1건 {} / 2건 이상 {}".format( + not_registered, + result["popularState"][POPULAR_REGISTERED], + result["popularState"][POPULAR_DUPLICATE_ROWS], + )) + print("[total] 미등록 라운드 비율 {:.1%} (관측값이다. 원인은 서버 로그와 타임라인으로 확인한다)".format( + not_registered / rounds if rounds else 0)) + print("[total] 요청 상태 {}".format( + " / ".join("{} {}".format(k, v) for k, v in result["requestState"].items()) or "없음")) + print("[total] HTTP 실패율 {} ({}/{})".format( + result["http"]["failedRate"], failed_requests, total_requests)) + print("[total] 좋아요 API duration med {} / p95 {} / p99 {} / max {} (ms, n={})".format( + result["durationMs"]["med"], result["durationMs"]["p95"], + result["durationMs"]["p99"], result["durationMs"]["max"], + result["durationMs"]["samples"])) + if dirty_rounds: + print("[total] 요청 오류가 있어 수동 확인이 필요한 라운드: {}".format(", ".join(dirty_rounds))) + if result["popularState"][POPULAR_DUPLICATE_ROWS]: + print("[total] popular_feed 행이 2건 이상인 라운드가 있다. 서버 로그에서 저장 경로를 확인한다.") + if args.json_out: + print("[total] 요약 JSON {}".format(args.json_out)) + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + sub = parser.add_subparsers(dest="command", required=True) + + p_round = sub.add_parser("round") + p_round.add_argument("--summary", required=True) + p_round.add_argument("--like-count", required=True) + p_round.add_argument("--popular-count", required=True) + p_round.add_argument("--expected-likes", required=True) + p_round.set_defaults(func=cmd_round) + + p_total = sub.add_parser("total") + p_total.add_argument("--csv", required=True) + p_total.add_argument("--raw-glob", required=True) + p_total.add_argument("--expected-likes", required=True) + p_total.add_argument("--json-out") + p_total.set_defaults(func=cmd_total) + + args = parser.parse_args() + args.func(args) + + +if __name__ == "__main__": + main() diff --git a/src/test/java/org/websoso/WSSServer/feed/feed/PopularFeedLikeRaceScriptTest.java b/src/test/java/org/websoso/WSSServer/feed/feed/PopularFeedLikeRaceScriptTest.java new file mode 100644 index 000000000..ec8bc465f --- /dev/null +++ b/src/test/java/org/websoso/WSSServer/feed/feed/PopularFeedLikeRaceScriptTest.java @@ -0,0 +1,224 @@ +package org.websoso.WSSServer.feed.feed; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.io.IOException; +import java.lang.reflect.Field; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.List; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.springframework.web.bind.annotation.PostMapping; +import org.websoso.WSSServer.feed.feed.application.PopularFeedApplication; +import org.websoso.WSSServer.feed.feed.controller.FeedController; + +/** + * 이슈 #620 동시 좋아요 재현 자산이 프로덕션 계약과 어긋나지 않는지 정적으로 검증한다. + *

+ * 재현 스크립트는 실행에 서버/DB/k6가 필요해 자동 테스트로 돌릴 수 없다. 대신 스크립트가 참조하는 + * 엔드포인트 경로와 임계값이 실제 코드와 같은지, 자격 증명이 섞여 들어가지 않았는지를 여기서 막는다. + */ +class PopularFeedLikeRaceScriptTest { + + private static final Path SCRIPT_DIR = Path.of("scripts", "load", "popular-feed-like-race"); + private static final Path K6_SCRIPT = SCRIPT_DIR.resolve("like-race.js"); + private static final Path RUNNER = SCRIPT_DIR.resolve("run-race.sh"); + private static final Path LIB = SCRIPT_DIR.resolve("lib.sh"); + private static final Path SEED = SCRIPT_DIR.resolve("seed-fixture.sh"); + private static final Path SUMMARIZER = SCRIPT_DIR.resolve("summarize.py"); + private static final Path TIMELINE = SCRIPT_DIR.resolve("observe-timeline.sh"); + + @Test + @DisplayName("재현 자산 파일이 모두 존재한다") + void reproductionAssetsExist() { + assertThat(List.of(K6_SCRIPT, RUNNER, LIB, SEED, SUMMARIZER, TIMELINE)) + .allSatisfy(path -> assertThat(Files.isRegularFile(path)) + .as("%s 가 있어야 한다", path) + .isTrue()); + } + + @Test + @DisplayName("k6 시나리오가 호출하는 경로가 좋아요 API 매핑과 같다") + void k6ScriptTargetsTheRealLikeEndpoint() throws Exception { + String mapping = FeedController.class + .getDeclaredMethod("likeFeed", org.websoso.WSSServer.user.domain.User.class, Long.class) + .getAnnotation(PostMapping.class) + .value()[0]; + + // "/feeds/{feedId}/likes" -> k6 템플릿 리터럴 "/feeds/${FEED_ID}/likes" + String expected = mapping.replace("{feedId}", "${FEED_ID}"); + + assertThat(read(K6_SCRIPT)) + .as("k6 시나리오가 실제 매핑 경로 %s 를 호출해야 한다", mapping) + .contains(expected); + } + + @Test + @DisplayName("기본 동시 사용자 수가 인기 피드 임계값보다 하나 많다") + void defaultVusIsOneMoreThanPopularFeedThreshold() throws Exception { + Field field = PopularFeedApplication.class.getDeclaredField("POPULAR_FEED_LIKE_THRESHOLD"); + field.setAccessible(true); + int threshold = field.getInt(null); + + assertThat(defaultVus()) + .as("임계값(%d)을 넘어서는 마지막 한 명이 있어야 count == %d 판정 경쟁이 생긴다", threshold, threshold) + .isEqualTo(threshold + 1); + } + + @Test + @DisplayName("반복 횟수와 동시 시작 방식을 조절할 수 있다") + void runnerExposesRepeatAndSynchronizationKnobs() throws IOException { + String runner = read(RUNNER); + + assertThat(runner).as("반복 횟수 옵션").contains("--rounds"); + assertThat(runner).as("동시 사용자 수 옵션").contains("--vus"); + assertThat(runner).as("동시 시작 리드타임 옵션").contains("--start-delay-ms"); + assertThat(read(K6_SCRIPT)).as("공통 시작 시각 동기화").contains("startAtMs"); + } + + @Test + @DisplayName("라운드 초기화는 대상 피드에만 한정된다") + void resetIsScopedToTheTargetFeed() throws IOException { + String lib = read(LIB); + + Matcher deletes = Pattern.compile("DELETE\\s+(?:\\w+\\s+)?FROM\\s+[^;]+;").matcher(lib); + int count = 0; + while (deletes.find()) { + count++; + assertThat(deletes.group()) + .as("초기화 DELETE는 feed_id로 범위를 좁혀야 한다") + .contains("feed_id"); + } + assertThat(count).as("초기화 DELETE 문이 있어야 한다").isPositive(); + } + + @Test + @DisplayName("운영·공유 환경을 대상으로 실행할 수 없도록 로컬 호스트만 허용한다") + void runnerRefusesNonLocalTargets() throws IOException { + String lib = read(LIB); + + assertThat(lib).contains("LOCAL_HOSTS_REGEX"); + assertThat(lib).contains("assert_local_target"); + assertThat(read(RUNNER)).as("실행 전 로컬 여부를 확인해야 한다").contains("assert_local_target"); + assertThat(read(SEED)).as("픽스처 생성 전에도 로컬 여부를 확인해야 한다").contains("assert_local_target"); + assertThat(read(TIMELINE)).as("타임라인 관찰도 로컬에서만 해야 한다").contains("assert_local_target"); + } + + @Test + @DisplayName("SQL에 들어가는 입력은 조회·삭제보다 먼저 형식을 검증한다") + void sqlInputsAreValidatedBeforeAnyQuery() throws IOException { + String lib = read(LIB); + + assertThat(lib).as("양의 정수 검증").contains("require_positive_int"); + assertThat(lib).as("음이 아닌 정수 검증").contains("require_non_negative_int"); + assertThat(lib).as("SQL 문자열에 들어가는 태그 검증").contains("require_sql_safe_tag"); + assertThat(lib).as("FEED_ID 전용 검증").contains("require_feed_id"); + + // 피드를 건드리는 함수는 각자 실행 직전에 FEED_ID를 다시 확인해야 한다. + for (String function : List.of("feed_like_count", "popular_feed_count", "feed_exists", + "reset_feed_state")) { + assertThat(bodyOf(lib, function)) + .as("%s 는 조회·삭제 전에 require_feed_id를 호출해야 한다", function) + .contains("require_feed_id"); + } + + String runner = read(RUNNER); + assertThat(runner).as("실행기가 FEED_ID를 검증해야 한다").contains("require_feed_id"); + for (String name : List.of("ROUNDS", "VUS")) { + assertThat(runner).as("%s 는 양의 정수여야 한다", name) + .contains("require_positive_int \"" + name + "\""); + } + for (String name : List.of("START_DELAY_MS", "SPIN_MS", "STAGGER_MS", "SETTLE_MS")) { + assertThat(runner).as("%s 는 0 이상의 정수여야 한다", name) + .contains("require_non_negative_int \"" + name + "\""); + } + + String seed = read(SEED); + assertThat(seed).as("FIXTURE_TAG는 SQL 리터럴에 들어가므로 문자 집합을 검증해야 한다") + .contains("require_sql_safe_tag \"FIXTURE_TAG\""); + assertThat(seed).as("LIKER_COUNT는 양의 정수여야 한다") + .contains("require_positive_int \"LIKER_COUNT\""); + } + + @Test + @DisplayName("타임라인 관찰이 기존 general log 행을 지우지 않는다") + void timelineObserverPreservesExistingGeneralLog() throws IOException { + String timeline = read(TIMELINE); + + assertThat(timeline) + .as("mysql.general_log를 TRUNCATE하면 로컬에 쌓인 로그가 사라진다") + .doesNotContainPattern("(?i)TRUNCATE\\s+TABLE\\s+mysql\\.general_log"); + assertThat(timeline).as("구간을 자를 marker가 있어야 한다").contains("MARKER"); + assertThat(timeline).as("marker 시각 이후만 읽어야 한다").contains("event_time >= @marker_at"); + assertThat(timeline).as("타임라인 관찰도 숫자 입력을 검증해야 한다").contains("require_feed_id"); + } + + @Test + @DisplayName("집계기는 관측값만 분류하고 원인을 단정하지 않는다") + void summarizerClassifiesObservationsOnly() throws IOException { + String summarizer = read(SUMMARIZER); + + assertThat(summarizer) + .as("popular_feed 행 상태와 요청 오류를 분리해야 한다") + .contains("classify_popular_state") + .contains("classify_request_state"); + assertThat(summarizer) + .as("popular_feed 행 개수에서 바로 나오는 상태만 쓴다") + .contains("not_registered") + .contains("duplicate_rows"); + assertThat(summarizer) + .as("5xx만으로 유니크 충돌이라고 단정하던 상태값은 남아 있으면 안 된다") + .doesNotContain("duplicate_conflict"); + assertThat(summarizer) + .as("요청 오류는 별도 상태로 기록해야 한다") + .contains("like_count_mismatch") + .contains("transport_error"); + + assertThat(read(RUNNER)) + .as("CSV가 두 상태를 각각 컬럼으로 가져야 한다") + .contains("popular_state,request_state"); + } + + @Test + @DisplayName("재현 자산에 토큰이나 시크릿 리터럴이 들어 있지 않다") + void reproductionAssetsCarryNoSecrets() { + assertThat(List.of(K6_SCRIPT, RUNNER, LIB, SEED, SUMMARIZER, TIMELINE)) + .allSatisfy(path -> { + String content = read(path); + assertThat(content) + .as("%s 에 JWT 리터럴이 있으면 안 된다", path) + .doesNotContain("eyJhbGciOi"); + assertThat(content) + .as("%s 는 시크릿을 환경 변수로만 받아야 한다", path) + .doesNotContainPattern("JWT_SECRET\\s*=\\s*[\"']?[A-Za-z0-9]"); + }); + } + + /** 셸 함수 하나의 본문을 잘라낸다. `name() {` 부터 열의 맨 앞 `}` 까지. */ + private String bodyOf(String script, String functionName) { + Matcher matcher = Pattern + .compile("^" + Pattern.quote(functionName) + "\\(\\)\\s*\\{$(.*?)^\\}$", + Pattern.DOTALL | Pattern.MULTILINE) + .matcher(script); + assertThat(matcher.find()).as("%s 함수를 찾지 못했다", functionName).isTrue(); + return matcher.group(1); + } + + private int defaultVus() throws IOException { + Matcher matcher = Pattern.compile("intEnv\\('VUS',\\s*(\\d+)\\)").matcher(read(K6_SCRIPT)); + assertThat(matcher.find()).as("like-race.js에 VUS 기본값이 있어야 한다").isTrue(); + return Integer.parseInt(matcher.group(1)); + } + + private static String read(Path path) { + try { + return Files.readString(path, StandardCharsets.UTF_8); + } catch (IOException e) { + throw new IllegalStateException(path + " 를 읽을 수 없다", e); + } + } +}