9월 24일 16시 5분부터 16시 16분까지 11분 동안 페미위키가 느렸습니다. 응답의 95%가 30초에서 54초 걸렸고, 502가 27건 나갔습니다. 읽기는 대체로 성공해서 같은 10분 동안 200 응답이 4,364건 나갔고, 페미위키:대문 상태 검사는 실패하지 않았습니다. 16시 19분에 사이트 전체 상한을 10분에 3,000건에서 2,000건으로 내렸습니다.
| 시각 | 일어난 일 |
|---|---|
| 12:06 | 비 로그인 검색, 차이, 역사 요청의 사이트 전체 상한을 10분에 1,500건에서 3,000건으로 올림.[1] 같은 배포에 /24별로 10분에 100건인 제한을 더함
|
| 12:19 | 워커를 10개에서 16개로 늘림.[2] |
| 16:05 | 응답의 95%가 30초를 넘기기 시작 |
| 16:08 | Grafana의 워커 대기열 경보가 디스코드로 알림 |
| 16:10 | Route 53의 특수:빈문서 검사가 경보로 바뀌어 알림. 응답의 95%가 54초, 502가 나오기 시작 |
| 16:16 | 상한이 차서 429를 내기 시작. 응답의 95%가 1.2초로 돌아옴 |
| 16:19 | 상한을 2,000건으로 내린 배포가 끝남.[3] |
원인
16시 무렵 크롤러가 몰려 비 로그인 검색, 차이, 옛 판, 역사 요청이 10분에 2,790건까지 늘었습니다. 가장 많이 보낸 쪽은 15.177.0.0/16, 154.197.0.0/16, 57.141.0.0/16이었고 나머지는 여러 /16에 퍼져 있었습니다.
이 요청들은 상한 안에 있었으므로 그대로 PHP까지 갔으나[4] 그만큼을 처리하기에 CPU가 모자랐습니다. 2코어 가운데 사용자 73%, 커널 16%가 차고 부하는 9.87이었으며, 남은 유휴는 7.8%였습니다. 워커는 16개까지 떠 있었지만 CPU가 병목이라 도움이 되지 않았습니다.
상한을 3,000건으로 올린 것은 같은 날 낮의 조치였습니다. 그 전에는 1,500건이 평소 수요보다 낮아 로그인하지 않은 사람이 크롤러 때문에 429를 받고 있었고,[5] 그것을 없애려고 올렸습니다.
이날 잰 값으로는 5분에 1,019건일 때 95% 응답이 1.19초, 1,336건일 때 29.6초, 1,941건일 때 53.8초였습니다. 10분에 2,000건과 2,700건 사이가 이 서버의 한계입니다.
알림
Grafana에 전날 넣은 워커 대기열 경보가 16시 8분 40초에 울렸습니다.[6] 요청이 5분 넘게 php-fpm 앞에 줄 서 있으면 알리는 경보로, Route 53 경보보다 1분 20초 빨랐고 무엇이 막혔는지도 함께 알려 주었습니다. 사이트 다운 경보는 울리지 않았습니다. 읽기가 계속 성공했으므로 맞는 동작입니다.
고친 것
남은 문제
상한은 서버가 감당하는 양에 맞춰 두었으므로, 크롤러가 그보다 많이 보내면 그 뒤에 검색이나 역사를 누른 사람이 다시 429를 받습니다. 수요와 용량 가운데 하나를 고르는 상태는 그대로입니다. 워커를 늘리는 것으로는 풀리지 않고, CPU를 늘리거나 이 요청들을 캐시에서 답하게 해야 합니다.
출처
- ↑ https://github.com/femiwiki/infra/pull/627
- ↑ https://github.com/femiwiki/infra/pull/628
- ↑ https://github.com/femiwiki/infra/pull/648
- ↑ https://github.com/femiwiki/docker-mediawiki/blob/d3e2eeb4084f5b28733fd4012d6b748c2433126e/dockers/femiwiki/Caddyfile#L60-L68
- ↑ https://github.com/femiwiki/infra/issues/626
- ↑ https://github.com/femiwiki/infra/pull/623
- ↑ https://github.com/femiwiki/infra/blob/ec38a0d7973bc91c498c1ff1e71f62a71c2fae23/docker/container.tf#L33