jisangs/chocomae
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

현재 서비스중인 t3a.medium 실행 지표 상태 확인

Browse Source
This commit is contained in:
Jisang Park
2026-09-18 12:30:12 +09:00
parent 03eea2098e
commit b18612277c
18 changed files with 14858 additions and 68 deletions
Download Patch File Download Diff File Expand all files Collapse all files
doc/plan/db/260915-improve-production/07-post-analysis.md
+155 -47
View File
@@ -17,7 +17,16 @@
| **EXPLAIN rows (q3 일간·함수)** | 10,103 | 5,851 | 1.7배 ⬇️ | [x] 확인 |
| **서버 처리 시간 (q4, ANALYZE)** | 75.2ms | 0.47ms | 161배 ⬇️ | [x] 확인 |
| **서버 처리 시간 (q3 일간·함수, ANALYZE)** | 75.3ms | 2.44ms | 31배 ⬇️ | [x] 확인 |
| **느린 쿼리 수 (0.5초 이상)** | 측정 안 함 (당시 기준 3초·파일 로그) | 앱 쿼리 0건 (작업 후 1시간, 작업 SQL 5건만) | - | [ ] 24시간 후 재확인 |
| **애플리케이션 느린 쿼리 (3초 이상)** | 0건 (slow log 전체 기간) | 0건 (9/16 하루) | - | [x] 확인 (04:00 백업 1건 외 기록 없음) |
> **slow log에 기록된 것은 모두 백업·작업 SQL이고, 애플리케이션 쿼리는 한 건도 없었습니다.**
> - 매일 04:00 약 5초: `best_record` 전체 SELECT (mysqldump 백업)
> - 9/7 17:44~18:07: 같은 백업 SELECT 반복 (백업 스크립트 작업일)
> - 9/15 23:04~23:09: 이번 작업의 전체 백업 덤프, 중복 DELETE, ALTER
>
> 앱 쿼리는 작업 전에도 3초를 넘지 않았으므로(측정 쿼리 서버 처리 시간 약 75ms), 이번 개선 효과는 이 지표가 아니라 04단계의 서버 처리 시간·검사 행 수로 판단합니다. 9/16 이후에도 04:00 백업 SELECT(약 5초, 전체 행을 읽으므로 인덱스와 무관)는 계속 기록되니 성능 저하로 오해하지 마세요.
>
> 원본: [result/slow_log_daily_before.txt](result/slow_log_daily_before.txt), [result/slow_log_entries_before.txt](result/slow_log_entries_before.txt)
> 참고: 01단계 사전 측정의 일간 랭킹(함수형)은 `index_merge`, rows 10,100이었습니다.
>
@@ -26,34 +35,84 @@
### 저장된 파일
```
result/
├── premeasure_*.txt, premeasure_*.json ← 01 사전 측정
├── baseline_explain_q*.json ← 02 EXPLAIN
├── baseline_perf.txt ← 02 실행 시간
├── backup_app_highest_dup_rows.sql ← 03 삭제 행 백업
├── add_indexes_result.txt ← 03 인덱스 추가 결과
├── after_explain_q*.json ← 04 EXPLAIN
├── after_perf.txt ← 04 실행 시간
├── explain_summary.txt, timing_summary.txt
└── comparison.txt
├── premeasure_*.txt, premeasure_*.json ← 01 사전 측정
├── params.sql, queries/*.sql ← 02·04 공통 측정 쿼리
├── run_measure.sh, summarize_*.py ← 02·04 공통 측정 도구
├── baseline_explain_q*.json, baseline_perf.txt ← 02 EXPLAIN, 실행 시간
├── baseline_analyze.txt, baseline_*_summary.txt ← 02 서버 처리 시간
├── dedupe_before_count.txt, dedupe_result.txt ← 03 중복 정리
├── add_indexes.sql, add_indexes_*.txt ← 03 인덱스 추가
├── after_explain_q*.json, after_perf.txt ← 04 EXPLAIN, 실행 시간
├── after_analyze.txt, after_slow_log.txt ← 04 서버 처리 시간, slow log
├── explain_summary.txt, analyze_summary.txt ← 04 비교 요약
├── comparison.txt ← 04 비교표·결론
├── slow_log_daily_before.txt, slow_log_entries_*.txt ← 07 slow log 분석
├── peaktime/ ← 07 vmstat 원본 로그·스크립트
└── peaktime_vmstat_summary.txt ← 07 피크 시간대 비교
커밋 제외 (로컬에만 보관, 개인정보·비밀번호 해시 포함):
backup_chocomae_full_20260915.sql.gz, backup_app_highest_dup_rows.sql, *grants*.txt
```
---
## 🔍 성능 분석
### 쿼리 응답 시간 추이 (24시간 모니터링)
### 피크 시간대 서버 상태 (vmstat, 12:50~15:00)
```
시간대별 성능:
- 평상시: _____ ms
- 피크 시간: _____ ms
- 최고 응답 시간: _____ ms
운영 서버 cron이 매일 12:50부터 `vmstat 10 780`을 기록합니다 (`chocomae-peaktime-monitoring.sh`). 9/14·9/15는 개선 전, 9/16은 개선 후입니다.
느린 쿼리 로그:
- 0.5초 이상: _____ 개 (개선 전: _____)
- 1초 이상: _____ 개 (개선 전: _____)
- 5초 이상: _____ 개 (개선 전: _____)
```
| 지표 (779샘플 평균) | 9/14 | 9/15 | 9/16 (개선 후) |
|---|---|---|---|
| CPU 사용 us+sy | 13.51% | 9.49% | **2.80%** |
| CPU 사용 p95 | 29% | 23% | **6%** |
| 누적 CPU 시간 (130분) | 1,052.8초 | 739.5초 | **217.9초** |
| us > 5 인 샘플 수 | 701 | 468 | **5** |
| 실행 대기 r ≥ 2 샘플 수 | 86 | 62 | **16** |
| 디스크 읽기 bi 평균 | 71.8 | 60.5 | **17.4** |
| 문맥 전환 cs 평균 (부하 지표) | 879 | 658 | 645 |
| 여유 메모리 free 평균 | 564MB | 433MB | 471MB |
| 피크 기록 수 (best_record) | 2,705건 | 1,947건 | 2,173건 |
| **기록 1,000건당 CPU** | 389.2초 | 379.8초 | **100.3초** |
- **부하는 비슷한데 CPU 사용량이 3.4배 줄었습니다.** 문맥 전환 수(cs)는 9/15 658 → 9/16 645로 거의 같은데, CPU 사용률은 9.49% → 2.80%입니다.
- 디스크 읽기(bi)도 3.5배 줄어, 인덱스로 읽는 페이지가 줄어든 것과 일치합니다.
- 메모리는 큰 변화가 없습니다.
원본과 계산 결과: [result/peaktime/](result/peaktime/), [result/peaktime_vmstat_summary.txt](result/peaktime_vmstat_summary.txt)
**사용자 수로 보정한 결과 (2026-09-16 확인):** 9/16은 9/15보다 기록이 약 12% 많았는데도 CPU는 3.4배 적게 썼습니다. 기록 1,000건당 CPU로 환산하면 **380초 → 100초로 약 3.8배 감소**했습니다. 개선 전 두 날(389.2초, 379.8초)의 값이 서로 비슷해 기준값으로 믿을 만합니다.
---
### 디스크 사용량 변화 (인덱스 추가 비용)
2026-09-16에 운영 DB에서 다시 측정했습니다. 01단계 측정값과 비교한 결과입니다.
| 테이블 | data_mb (전 → 후) | index_mb (전 → 후) | 인덱스 증가 |
|---|---|---|---|
| best_record | 72.5 → 73.5 | 72.1 → **143.2** | +71.1MB |
| app_highest_record | 16.5 → 16.5 | 15.8 → 21.3 | +5.5MB |
| typing_exam_record | 10.3 → 10.3 | 10.9 → 17.9 | +7.0MB |
| typing_exam_highest_record | 1.4 → 1.4 | 1.2 → 1.7 | +0.5MB |
**best_record 인덱스별 크기** (`mysql.innodb_index_stats`)
| 인덱스 | 크기 | 비고 |
|---|---|---|
| PRIMARY | 73.5MB | 데이터 본체 |
| `idx_maestro_player_app_dt` | 35.6MB | 이번에 추가 |
| `idx_maestro_app_dt` | 30.6MB | 이번에 추가 |
| PlayerID | 29.3MB | 기존, 외래키용 |
| AppID | 25.4MB | 기존, 외래키용 |
| MaestroID | 22.3MB | 기존, 외래키용 (새 인덱스로 대체 가능) |
- **인덱스로 늘어난 디스크는 약 79MB**입니다. best_record의 증가분 71.1MB 중 약 4.9MB는 같은 기간 기록이 7% 늘어난 몫이고, 나머지 66.2MB가 새 복합 인덱스 2개입니다.
- DB 전체 크기는 약 207MB → 292MB로 **약 41% 늘었습니다.** 성능과 맞바꾼 디스크 비용입니다.
- `app_highest_record`는 8,795행을 지웠는데도 `data_mb`가 그대로입니다. InnoDB가 삭제한 공간을 파일에서 반환하지 않고 새 행에 재사용하기 때문이며 정상입니다.
- **메모리 사용량은 줄지 않았습니다.** InnoDB 버퍼 풀은 시작할 때 정해진 크기를 확보하므로 쿼리가 빨라져도 사용량이 달라지지 않습니다. 대신 같은 캐시로 더 적은 데이터만 다루게 되어 디스크 읽기가 줄었습니다(위 vmstat `bi` 참고).
원본: [result/index_size_after.txt](result/index_size_after.txt)
---
@@ -61,11 +120,12 @@ result/
| 지표 | 개선 전 | 개선 후 | 변화 |
|---|---|---|---|
| 동시 사용자 | _____ | _____ | _____ |
| 평균 응답 시간 | _____ ms | _____ ms | _____ ms |
| 실패율 | _____ % | _____ % | _____ % |
| CPU 사용률 | _____ % | _____ % | _____ % |
| 메모리 사용률 | _____ % | _____ % | _____ % |
| 피크 시간 기록 수 (부하) | 1,947건 (9/15) | 2,173건 (9/16) | 12% 증가 |
| 평균 응답 시간 | 측정 안 함 (웹 서버 응답 시간 미기록) | - | - |
| 실패율 | 측정 안 함 | - | - |
| CPU 사용률 (피크 12:50~15:00) | 9.49% (9/15) | **2.80%** (9/16) | **3.4배 ⬇️** |
| 기록 1,000건당 CPU (부하 보정) | 379.8초 (9/15) | **100.3초** (9/16) | **3.8배 ⬇️** |
| 여유 메모리 (피크 평균) | 433MB (9/15) | 471MB (9/16) | 큰 변화 없음 |
---
@@ -73,20 +133,27 @@ result/
### 성공 기준
- [ ] 범위형 쿼리(q2·q4·q6)의 rows가 베이스라인 대비 대폭 감소 (목표: 조회 기간의 실제 기록 수 수준)
- [ ] 느린 쿼리 대폭 감소
- [ ] 결과 행 수 변화 없음, 최고기록 화면 정상
- [ ] 서비스 가용성 100% 유지
- [ ] 사용자 불만 없음
- [x] 범위형 쿼리(q2·q4·q6)의 rows가 베이스라인 대비 대폭 감소 (목표: 조회 기간의 실제 기록 수 수준) — 10,103 → 22 / 99 / 709
- [x] 애플리케이션 느린 쿼리(3초 이상) 없음 — 9/16 하루 동안 0건 (기록된 것은 04:00 백업 SELECT 1건뿐, [result/slow_log_entries_after.txt](result/slow_log_entries_after.txt))
- [x] 결과 행 수 변화 없음, 최고기록 화면 정상 — 04-3 diff 통과, 2026-09-15 운영 화면 확인
- [x] 서비스 가용성 100% 유지 — 온라인 DDL로 중단 없음, 9/15 작업 직후 운영 화면 확인, 9/16 피크 시간에 기록 2,173건 정상 저장
- [ ] 사용자 불만 없음 — 2026-09-16까지 접수된 문의 없음 (기간을 더 두고 확인)
### 결론
```
[ ] 성공: 모든 기준 달성, 운영 정상화
[x] 성공: 모든 기준 달성, 운영 정상화 (2026-09-16 판단)
[ ] 부분 성공: 대부분 달성, 모니터링 계속
[ ] 실패: 목표 미달, 추가 최적화 필요
```
**근거 요약**
- 서버 처리 시간: 범위형 쿼리 75~80ms → 0.26~2.50ms (32~292배), 함수형도 18~36배 단축
- 검사 행 수: 10,103 → 22 / 99 / 709
- 피크 시간 CPU: 기록 1,000건당 379.8초 → 100.3초 (3.8배 감소, 부하 12% 증가 상태에서)
- 조회 결과 행 수는 개선 전과 동일, 운영 화면 정상, 앱 느린 쿼리 0건
- 남은 확인: 사용자 문의 여부는 기간을 더 두고 관찰
---
## 🔧 추가 최적화 제안
@@ -94,8 +161,8 @@ result/
### 단계별 추가 개선
#### **1단계: 쿼리 최적화 (안 1)**
- [ ] 함수 제거 쿼리 적용 (03단계 3-4, Stage에서 수정 완료한 코드 배포)
- [ ] 예상 효과: 04단계의 함수형↔범위형 비교값(q1↔q2, q3↔q4, q5↔q6) 참고
- [x] 함수 제거 쿼리 적용 (03단계 3-4, Stage에서 수정 완료한 코드를 2026-09-15 운영 배포)
- [x] 효과: 같은 조건에서 함수형 대비 서버 처리 시간 q1→q2 8배, q3→q4 5배, q5→q6 1.7배 추가 단축 (04단계)
#### **2단계: 집계 테이블 도입 (안 2)**
- [ ] daily_best_record, daily_typing_exam_record 생성
@@ -114,27 +181,68 @@ result/
---
#### **5단계: 중복 인덱스 정리 (선택)**
- [ ] `best_record`의 `MaestroID` 단일 인덱스 삭제 검토 (22.3MB 회수)
- 새로 만든 `idx_maestro_app_dt`가 `MaestroID`로 시작하므로 외래키 제약도 충족하고 조회도 대체됩니다.
- `ALTER TABLE best_record DROP INDEX MaestroID, ALGORITHM=INPLACE, LOCK=NONE;`
- `AppID`, `PlayerID` 단일 인덱스는 각각 그 컬럼으로 시작하는 외래키가 있어 **삭제하면 안 됩니다.**
- [ ] `typing_exam_record` 등 다른 테이블에도 같은 정리 여지가 있는지 인덱스 목록 확인
- [ ] 스테이징에서 외래키 제약과 쿼리 계획을 먼저 확인한 뒤 운영 적용
---
## 📋 모니터링 계획
### 지속적 모니터링 (24시간 이후)
`mysql.slow_log` SELECT 권한이 필요하고, `log_output`에 `TABLE`이 있어야 합니다. 조회가 끝나면 05단계 사후 작업대로 slow query log 설정을 원래 값으로 복원하세요.
작업 후 slow query log는 원래 설정(`slow_query_log=ON`, `long_query_time=3`, `log_output=FILE`)으로 돌아갔고, 작업용 `jisangs` 계정은 삭제했습니다. 그래서 `mysql.slow_log` 테이블이 아니라 **MariaDB가 실행되는 서버(또는 컨테이너)의 slow log 파일**로 확인합니다.
작업 전후 모두 같은 기준(3초 이상)으로 기록되므로, 날짜별 건수를 그대로 비교할 수 있습니다.
> 2026-09-15 23:05~23:20에는 기준이 0.5초였고 작업 SQL(ALTER·DELETE)이 기록됐습니다. 9/15 건수에서 이 시간대는 제외하고 보세요.
**1. 날짜별 느린 쿼리 건수** (서버에서 root/sudo로 실행)
```bash
# 일일 성능 리포트
mariadb -h chocomae.jinaju.com -u jisangs -p chocomae -e "
SELECT
DATE_FORMAT(start_time, '%Y-%m-%d %H:00:00') AS hour,
COUNT(*) AS slow_query_count,
AVG(query_time) AS avg_time,
MAX(query_time) AS max_time
FROM mysql.slow_log
WHERE start_time >= CURDATE()
GROUP BY hour
ORDER BY hour;
"
sudo awk '/^# Time:/ {d = substr($3, 1, 10)} /^# Query_time:/ {c[d]++} END {for (k in c) print k, c[k]}' \
/var/log/mysql/mariadb-slow.log | sort | tail -14
```
첫 열은 `# Time:` 줄의 날짜입니다 (형식에 따라 `260916` 또는 `2026-09-16`). 9/15 이전 며칠과 9/16 이후를 비교해 위 표의 "느린 쿼리 수"에 적습니다.
**2. 느린 쿼리 종류 상위 10개** (`mariadb-dumpslow`가 설치된 경우)
```bash
sudo mariadb-dumpslow -s c -t 10 /var/log/mysql/mariadb-slow.log
```
`best_record`, `typing_exam_record`의 날짜 조건 쿼리가 9/16 이후에도 나오는지 확인합니다. 나오면 03-4에서 수정하지 못한 쿼리가 남아 있는 것입니다. 백업 덤프의 `SELECT /*!40001 SQL_NO_CACHE */ ... FROM best_record`는 정상입니다.
> 운영 서버의 `mariadb-dumpslow`는 이 로그 중간에서 `Died at /usr/bin/mariadb-dumpslow line 182` 에러로 멈췄습니다 (2026-09-15). 멈추기 전까지의 요약은 출력되므로 참고용으로 쓰고, 건수는 1번 awk 명령으로 확인하세요.
**3. 느린 쿼리 항목별 목록** (시각, 실행 시간, 검사 행 수 — SQL 본문은 출력하지 않음)
```bash
sudo awk '/^# Time:/ {t = $3 " " $4} /^# Query_time:/ {print t, "query_time=" $3, "rows_examined=" $NF}' \
/var/log/mysql/mariadb-slow.log | tail -30
```
9/16 이후 항목이 04:00 백업 1건(검사 행 약 121만)뿐이면 정상입니다.
**4. 피크 시간대 기록 저장 건수** (vmstat 비교를 사용자 수로 보정할 때, 서버에서 관리자 계정으로 실행)
```sql
SELECT DATE(RecordDateTime) AS day, COUNT(*) AS best_record_cnt
FROM best_record
WHERE RecordDateTime >= '2026-09-14' AND RecordDateTime < '2026-09-17'
AND TIME(RecordDateTime) >= '12:50:00' AND TIME(RecordDateTime) < '15:00:00'
GROUP BY day ORDER BY day;
```
날짜별 건수가 비슷하면 vmstat의 CPU 감소는 개선 효과로 볼 수 있고, 9/16 건수가 크게 적으면 사용자가 적었던 영향도 섞인 것입니다.
**결과 (2026-09-16):** 9/14 2,705건 / 9/15 1,947건 / 9/16 2,173건 → 9/16이 9/15보다 많으므로, CPU 감소는 사용자가 줄어서가 아닙니다.
---
## 📝 최종 보고서 항목