안녕하세요!
어제 확인했을 때는 사이트가 정상적으로 작동했는데, 오늘 아침에 일어나 보니 502 Bad Gateway 오류로 사이트가 다운되어 있습니다. monitor.log 파일을 첨부합니다. monitor.txt (9.4 MB)
와… 왜 자바가 이렇게 많지? 제 제티(Jitsi) 서버가 한때 그랬던 것 같아 
또 호스트를 메일 서버로 쓰고 있는 것 같네. 나는 결국 앱을 분리해서 메일 서버를 따로 뗐어. 이렇게 하면 나중에 복구하기가 훨씬 쉽고, 표준 프로덕션 설치 환경에 최대한 가깝게 깔끔하게 유지할 수 있어서 좋아. 메일용 아주 작은 인스턴스에 플로팅 IP를 할당하면 평판 모니터링도 좀 더 쉬울 거고, 비용도 아주 약간만 더 들 것 같아.
자, 한번 살펴볼게요… 먼저 average를 grep으로 검색해 보겠습니다:
06:24:13 up 3 days, 8:13, 0 users, load average: 0.01, 0.05, 0.08
06:34:33 up 3 days, 8:23, 0 users, load average: 12.89, 11.68, 6.35
즉, 실행 가능한 프로세스 수가 06:34 직전에 급증한 것으로 보입니다.
조금 더 넓게 grep을 해 보면 메모리 사용량이 크게 변하지 않았음을 알 수 있습니다:
06:24:13 up 3 days, 8:13, 0 users, load average: 0.01, 0.05, 0.08
total used free shared buff/cache available
Mem: 8167548 3513172 3241404 371940 1412972 4512016
Swap: 10485756 0 10485756
--
06:34:33 up 3 days, 8:23, 0 users, load average: 12.89, 11.68, 6.35
total used free shared buff/cache available
Mem: 8167548 3110612 1351844 373268 3705092 4812672
Swap: 10485756 0 10485756
사실 오히려 메모리 사용량이 감소했으므로, 아마도 어떤 프로세스가 종료된 것 같습니다:
06:13:53 up 3 days, 8:02, 0 users, load average: 0.04, 0.16, 0.15
total used free shared buff/cache available
Mem: 8167548 3505540 3259744 371932 1402264 4519680
06:24:13 up 3 days, 8:13, 0 users, load average: 0.01, 0.05, 0.08
total used free shared buff/cache available
Mem: 8167548 3513172 3241404 371940 1412972 4512016
06:34:33 up 3 days, 8:23, 0 users, load average: 12.89, 11.68, 6.35
total used free shared buff/cache available
Mem: 8167548 3110612 1351844 373268 3705092 4812672
06:44:53 up 3 days, 8:33, 0 users, load average: 13.64, 13.25, 9.89
total used free shared buff/cache available
Mem: 8167548 3093212 3618984 373276 1455352 4840140
06:55:13 up 3 days, 8:44, 0 users, load average: 11.62, 12.70, 11.42
total used free shared buff/cache available
Mem: 8167548 3140580 3366628 373352 1660340 4792440
Unicorn이 재시작된 것으로 보입니다:
Thu Aug 5 06:24:13 CEST 2021
06:24:13 up 3 days, 8:13, 0 users, load average: 0.01, 0.05, 0.08
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 30389 0.0 0.0 2160 1148 ? Ss Aug03 0:00 \_ runsv unicorn
x 13329 0.0 0.0 15132 3712 ? S Aug04 0:26 \_ /bin/bash config/unicorn_launcher -E production -c config/unicorn.conf.rb
x 13365 0.0 3.0 542036 251584 ? Sl Aug04 0:23 \_ unicorn master -E production -c config/unicorn.conf.rb
x 13846 0.6 4.5 9129356 371852 ? SNl Aug04 4:19 | \_ sidekiq 6.2.1 discourse [0 of 5 busy]
x 13858 0.0 3.9 8971616 323264 ? Sl Aug04 0:18 | \_ unicorn worker[0] -E production -c config/unicorn.conf.rb
x 13870 0.0 4.0 8975712 330660 ? Sl Aug04 0:20 | \_ unicorn worker[1] -E production -c config/unicorn.conf.rb
x 13889 0.0 4.1 8979808 337180 ? Sl Aug04 0:20 | \_ unicorn worker[2] -E production -c config/unicorn.conf.rb
x 29760 0.0 0.0 13708 2220 ? S 06:24 0:00 \_ sleep 1
Thu Aug 5 06:34:33 CEST 2021
06:34:33 up 3 days, 8:23, 0 users, load average: 12.89, 11.68, 6.35
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 30389 0.0 0.0 2160 1148 ? Ss Aug03 0:00 \_ runsv unicorn
x 4638 0.4 0.0 15132 3784 ? S 06:32 0:00 \_ /bin/bash config/unicorn_launcher -E production -c config/unicorn.conf.rb
x 4642 11.1 2.8 439636 233240 ? Sl 06:32 0:11 \_ unicorn master -E production -c config/unicorn.conf.rb
x 4822 13.1 3.7 8877408 309844 ? Sl 06:33 0:10 | \_ unicorn worker[1] -E production -c config/unicorn.conf.rb
x 5025 15.6 3.7 8873312 310264 ? Sl 06:33 0:10 | \_ unicorn worker[0] -E production -c config/unicorn.conf.rb
x 5065 20.6 3.9 8922504 320740 ? SNl 06:33 0:11 | \_ sidekiq 6.2.1 discourse [0 of 5 busy]
x 5639 0.0 0.0 13708 2264 ? S 06:34 0:00 \_ sleep 1
그리고 Apache가 시작하는 데 문제가 있는 것으로 보입니다:
Thu Aug 5 06:24:13 CEST 2021
06:24:13 up 3 days, 8:13, 0 users, load average: 0.01, 0.05, 0.08
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 13730 0.0 0.1 225016 15840 ? Ss Aug02 0:17 /usr/sbin/apache2 -k start
www-data 10232 0.0 0.1 1352372 10972 ? Sl Aug03 0:00 \_ /usr/sbin/apache2 -k start
www-data 27998 0.0 0.1 228880 9608 ? S Aug04 0:01 \_ /usr/sbin/apache2 -k start
www-data 28000 0.0 0.3 3036536 27796 ? Sl Aug04 0:53 \_ /usr/sbin/apache2 -k start
www-data 28002 0.0 0.3 2904772 26524 ? Sl Aug04 0:50 \_ /usr/sbin/apache2 -k start
www-data 28185 0.0 0.1 762472 10952 ? Sl Aug04 0:00 \_ /usr/sbin/apache2 -k start
Thu Aug 5 06:34:33 CEST 2021
06:34:33 up 3 days, 8:23, 0 users, load average: 12.89, 11.68, 6.35
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 13730 0.0 0.1 225024 15856 ? Ss Aug02 0:17 /usr/sbin/apache2 -k start
www-data 10232 0.0 0.1 1352372 10972 ? Sl Aug03 0:00 \_ /usr/sbin/apache2 -k start
www-data 28185 0.0 0.1 762472 10952 ? Sl Aug04 0:00 \_ /usr/sbin/apache2 -k start
www-data 30794 0.0 0.1 228888 9620 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 31490 0.0 0.1 344564 10852 ? Sl 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32095 0.0 0.1 500228 10888 ? Sl 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32215 83.2 0.1 369152 10876 ? Sl 06:25 7:26 \_ /usr/sbin/apache2 -k start
www-data 32284 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32382 187 0.1 410136 10916 ? Sl 06:25 16:31 \_ /usr/sbin/apache2 -k start
www-data 32410 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32545 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 2106 0.0 0.1 3032348 11396 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
www-data 2240 0.0 0.1 2901012 11416 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
www-data 2241 0.0 0.1 2901184 14220 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
Thu Aug 5 06:44:53 CEST 2021
06:44:53 up 3 days, 8:33, 0 users, load average: 13.64, 13.25, 9.89
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 13730 0.0 0.1 225024 15856 ? Ss Aug02 0:17 /usr/sbin/apache2 -k start
www-data 10232 0.0 0.1 1352372 10972 ? Sl Aug03 0:00 \_ /usr/sbin/apache2 -k start
www-data 28185 0.0 0.1 762472 10952 ? Sl Aug04 0:00 \_ /usr/sbin/apache2 -k start
www-data 30794 0.0 0.1 228888 9620 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 31490 0.0 0.1 344564 10852 ? Sl 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32095 0.0 0.1 500228 10888 ? Sl 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32215 82.1 0.1 369152 10876 ? Sl 06:25 15:50 \_ /usr/sbin/apache2 -k start
www-data 32284 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32382 188 0.1 410136 10916 ? Sl 06:25 36:10 \_ /usr/sbin/apache2 -k start
www-data 32410 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 32545 0.0 0.1 229400 9936 ? S 06:25 0:00 \_ /usr/sbin/apache2 -k start
www-data 2106 0.0 0.1 3032348 11396 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
www-data 2240 0.0 0.1 2901012 11416 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
www-data 2241 0.0 0.1 2901184 14432 ? Sl 06:27 0:00 \_ /usr/sbin/apache2 -k start
포크된 Apache 프로세스가 많고, 그중 하나가 CPU 83%를, 또 다른 하나는 188%를 소모하고 있는 것을 주목해 주세요. 거기에 뭔가 문제가 있는 것 같습니다.
하지만 이 발견에 대해 어떻게 해야 할지 확신이 서지 않습니다.
최근 커널이 프로세스를 종료한 이유가 있는지 확인하는 것도 도움이 될 수 있습니다:
dmesg -T | egrep -i kille
그 명령어를 실행해도 아무 결과가 없습니다.
친구가 MPM prefork에서 MPM Event로 바꿔준 것이 원인인 것 같아요. 그 이후로 Apache의 사용량이 많이 늘었지만, discourse를 제외하고는 사이트가 충돌하거나 문제가 생긴 적은 없었어요. 결국 MPM prefork로 다시 변경했는데, 이게 도움이 될까요?
자바가 사실은 Varnish 캐치라는 걸 알게 됐어요. 프로세스의 트리를 열어보니 기본이 Varnish이었거든요. 자바라고 하기엔 Varnish이 훨씬 더 말이 돼요 
MPM Event는 Apache가 멀티 스레드로 실행되도록 하여 더 많은 방문자를 처리할 수 있게 합니다. 이는 이제 일반적으로 PHP-FPM으로 알려진 별도의 PHP 서비스와 함께 사용해야 합니다. 서버가 바쁠 때 Prefork는 Apache와 PHP의 성능을 제한합니다. Event가 과도한 리소스를 사용한다면, 이는 대부분 Event 대비 잘못 구성된 FPM 때문일 가능성이 높지만, 최적화되지 않은 MPM Event 자체도 문제가 될 수 있습니다.
Prefork는 동시 트래픽이 많지 않은 서버에는 잘 작동하지만, 현재 Apache의 표준은 Event/FPM입니다.
그건 좋은 일인 것 같네요…
네, 도움 주셔서 감사합니다 
MPM prefork로 다시 변경했고, 아파치가 3일 동안 크래시가 없었습니다. 이제야 모든 문제가 해결된 것 같아 희망을 가져봅니다. 도움 주셔서 감사합니다