서비스 응답속도 저하시 php-fpm 로그로 원인분석하기

php-fpm 기반의 웹 서비스에서 알 수 없는 문제로 응답속도가 저하되는 현상이 발생 할 경우가 종종 있다.

원인은 여러가지일 수 있다. 몇 가지를 꼽자면,

  1. DBMS의 SQL 응답속도 저하 (Slow Query)
  2. 네트워크 지연
  3. 서버 리소스 점유율 (CPU, RAM 등)
  4. Disk 입출력 문제

등이 있다.

하지만, 서버 리소스나 네트워크에 별 다른 문제가 없고, Slow Query 로그에도 별다른 이상징후가 없다면,
원인분석을 해야 하는데, 이 경우 Web Application에서 어느 로직에서 문제가 발생하는지 원인을 찾아야 한다.

개발환경이라면 Xdebug를 활용 수 있겠지만, 실 서비스 중인 서버에는 적용할 수 없는 방법이다.

이 때는 php-fpm의 slowlog를 찍어서 확인하는 방법이 있다.

php-fpm.conf 파일을 열어보면 아래와 같은 설정을 확인할 수 있다.

......
request_slowlog_timeout = 30s
slowlog = /var/log/php-fpm/slow.log
......

여기서 request_slowlog_timeout을 3~5s 정도로 낮추고, php-fpm 서비스를 재시작한다.

그 후 tail 명령으로 /var/log/php-fpm/slow.log 를 확인 후 응답속도가 느린 페이지에 접속을 계속 시도해보면 다음과 같은 로그가 찍힌다.

[10-Nov-2018 11:30:22]  [pool www] pid 8260
script_filename = ******************
[0x00007f1a47de79a8] fopen() ****.php:422
[0x00007f1a47de6500] +++ dump failed

이 로그에는 응답속도 저하의 원인이 되는 파일과 해당 function까지 추적해주기 때문에 원인을 금방 파악할 수 있다.

DevOps 장애조치 PHP php-fpm Linux