레일스 로그를 활용한 성능 분석

지난 글 몽그렐 클러스터가 필요한 이유에서 설명한 것처럼 레일스 애플리케이션(특히나 몽그렐을 사용할 때는)은 거의 모든 경우에 대해서 빠른 응답 시간을 보장해야 안정적인 서비스를 할 수 있다. 그러나 이는 쉽지만은 않은 목표이기 때문에, 꾸준한 모니터링과 개선이 수반되야한다. 이제 어떤 액션이 애플리케이션 전체의 건강을 해치는 '병목 지점'인지를 알아낼 수 있는 방법이 필요하다. 다행히 레일스 로그를 보면 매 액션에 대한 자세한 정보가 담겨 있기 때문에 이 로그를 분석해보면 어렵지 않게 원하는 내용을 찾을 수 있다.

1. Processing PluginsController#index (for 127.0.0.1 at 2007-07-11 13:22:49) [GET]

   Session ID: 1

   Parameters: {"action"=>"index", "controller"=>"plugins"}
2. Completed in  0.01590 (62 reqs/sec) | Rendering: 0.00351 (22%) |  Memcache: 0.00725 | DB:  0.00687 (43%) | 200 OK [http://localhost/plugins]

이런 분석을 해주는 툴은 직접 만들어도 되겠지만, Rails Analyzer 프로젝트에서 제공하는 Production Log Analyzer를 사용해도 된다. 이 툴을 실행하면 아래와 같은 정보를 얻을 수 있다.

• 응답 속도 통계
• DB 통신에 사용한 시간 통계
• 화면 렌더링에 사용한 시간 통계

위 값들의 액션별 통계도 제공하지만, 보다 유용한 것은 가장 오랜 시간을 소요한 액션들에 대한 정보이다. 이 액션이 우리가 개선해야할 목록이기도 하다. 위 프로젝트 사이트에 레포트 예제도 있으니, 이를 보고 사용할지를 판단해보기 바란다. 스프링노트팀에서는 매일 새벽 배치 작업을 통해 전날 로그를 분석해서 메일로 받아보고 있다. 그리고 아침마다 아직 할 일이 많다는 사실을 깨우친다. :)

Production Log Analyzer를 사용하기 위해서는 한가지 설정이 필요하다. 레일스 로그 파일을 유심히 보면 알겠지만 한가지 문제점이 있다. 여러 몽그렐 프로세스의 로그들이 모두 섞여서 어느 줄이 어느 요청에서 온 것인지 구분이 되지 않는다는 것이다. 이 문제를 해결하기 위해서는 이 프로그램의 저자는 레일스의 기본 설정 로거 대신에 SyslogLogger를 사용하도록 권장하고 있다. 이는 유닉스 시스템의 syslogd를 이용해 로그를 남기는 것이다. 여러 머신의 로그를 하나로 모으는데도 유용하고, 파일 기반 로거보다 성능 향상도 조금 있을 것으로 기대된다.

하지만 이런 설정의 여의치 않다면 레일스 로그 형식을 살짝 바꿔서 Production Log Analyzer가 처리할 수 있는 형식으로 바꿔줘도 된다. 이 파일을 lib 디렉터리에 만들고 환경 파일(config/environments/production.rb)에 다음과 같이 추가해주면 된다. 자세한 내용은 이 포스트를 참조하기 바란다.

1. require 'hodel_3000_compliant_logger'
   config.logger = Hodel3000CompliantLogger.new(config.log_path)
   config.logger.level = Logger::INFO

이렇게 해서 성능 병목지점을 찾았다면 이를 해소하기 위해 어떤 작업을 할 수 있을까? 프로파일링을 해볼 수도 있고, 수정과 벤치마크를 반복하는 방법도 있다. 이도 저도 안되면 백그라운드 작업으로 돌리는 방법도 있다. 여기에 관련 내용은 다음 기회에 다루기로 하겠다.

이 글은 스프링노트에서 작성되었습니다.