SNS 뉴스피드 구현과 쿼리 튜닝


소셜 네트워킹 서비스를 개발하면서 SNS의 뉴스피드 기능을 만들게 되었다. 그런데 사람이 점점 늘어나면서 뉴스피드를 로딩하는 시간이 점점 길어지더니 한 페이지 로딩하는데 5초 정도 걸리기 시작했다. 데이터베이스 쿼리로 인한 속도 저하는 처음 겪어보는 일이라서 어떻게 해야할지 막막했지만 가만히 손 놓고 있을 수는 없었기 때문에 처음으로 쿼리 튜닝이라는 것을 해봤다.

먼저 디비 구조는 다음과 같다. 필요 없는 컬럼은 생략했다.


User
+----------------------------+--------------+------+-----+---------+----------------+
| Field                      | Type         | Null | Key | Default | Extra          |
+----------------------------+--------------+------+-----+---------+----------------+
| id                         | int(11)      | NO   | PRI | NULL    | auto_increment |
+----------------------------+--------------+------+-----+---------+----------------+
Index: id


Follow
+-------------+----------+------+-----+---------+----------------+
| Field       | Type     | Null | Key | Default | Extra          |
+-------------+----------+------+-----+---------+----------------+
| id          | int(11)  | NO   | PRI | NULL    | auto_increment |
| follower_id | int(11)  | YES  |     | NULL    |                |
| followed_id | int(11)  | YES  |     | NULL    |                |
+-------------+----------+------+-----+---------+----------------+
Index: id

Post
+----------------+--------------+------+-----+---------+----------------+
| Field          | Type         | Null | Key | Default | Extra          |
+----------------+--------------+------+-----+---------+----------------+
| id             | int(11)      | NO   | PRI | NULL    | auto_increment |
| user_id        | int(11)      | YES  | MUL | NULL    |                |
| content        | longtext     | YES  |     | NULL    |                |
| created_at     | datetime     | NO   |     | NULL    |                |
+----------------+--------------+------+-----+---------+----------------+
Index: id, user_id

그리고 기존의 뉴스피드 포스트 목록을 불러오기 위한 쿼리는 다음과 같았다.

SELECT `posts`.*
FROM `posts`
WHERE
    `posts`.`user_id` IN (
      SELECT `users`.`id`
      FROM `users`
      INNER JOIN `follows`
      ON `users`.`id` = `follows`.`followed_id`
      WHERE `follows`.`follower_id` = 1
    )
  OR
    `posts`.`user_id` = 1

이 쿼리는 초반에 잘 동작했지만 포스트와 팔로우의 레코드가 각각 1000단위로 쌓이자 점점 느려지기 시작했다. 그리로 현재 프로덕션 환경의 디비에는 포스트, 팔로우 각각 7000개씩 저장되어 있다.

서비스에 영향을 주면 안되기 때문에 테스트는 동일한 환경에 포스트 6000, 팔로우 4000개로 셋팅한 다른 데이터베이스에서 진행했다. 그리고 쿼리의 분석과 소요 시간을 확인하기 위해 MySQL 내장 기능인 EXPLAINSHOW PROFILES를 사용했다.

테스트 환경에서 위의 쿼리는 3.7초가 소요되는 것을 SHOW PROFILES 명령어를 통해 볼 수 있다.

+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                   |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 3.78938800 | SELECT `posts`.* FROM `posts` WHERE (`posts`.`user_id` IN (SELECT `users`.`id` FROM `users` INNER JOIN `follows` ON `users`.`id` = `follows`.`followed_id` WHERE `follows`.`follower_id` = 1) OR `posts`.`user_id` = 1) |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

다음엔 EXPLAIN으로 쿼리를 분석 해서 포스트와 팔로우 테이블을 풀스캔하는 것을 발견할 수 있었다.

+----+--------------------+---------+--------+------------------------+---------+---------+------+------+--------------------------------+
| id | select_type        | table   | type   | possible_keys          | key     | key_len | ref  | rows | Extra                          |
+----+--------------------+---------+--------+------------------------+---------+---------+------+------+--------------------------------+
|  1 | PRIMARY            | posts   | ALL    | index_posts_on_user_id | NULL    | NULL    | NULL | 6301 | Using where                    |
|  2 | DEPENDENT SUBQUERY | users   | eq_ref | PRIMARY                | PRIMARY | 4       | func |    1 | Using index                    |
|  2 | DEPENDENT SUBQUERY | follows | ALL    | NULL                   | NULL    | NULL    | NULL | 4801 | Using where; Using join buffer |
+----+--------------------+---------+--------+------------------------+---------+---------+------+------+--------------------------------+

먼저 팔로우의 풀스캔부터 없애보기로 했다. 팔로우 테이블이 조인되는 과정에서 발생하는 풀스캔을 없애기 위해 follows.follower_idfollows.followed_id컬럼에 인덱스를 추가해봤다.

+----+--------------------+---------+--------+-----------------------------------------------------------+------------------------------+---------+-------+------+--------------------------+
| id | select_type        | table   | type   | possible_keys                                             | key                          | key_len | ref   | rows | Extra                    |
+----+--------------------+---------+--------+-----------------------------------------------------------+------------------------------+---------+-------+------+--------------------------+
|  1 | PRIMARY            | posts   | ALL    | index_posts_on_user_id                                    | NULL                         | NULL    | NULL  | 6301 | Using where              |
|  2 | DEPENDENT SUBQUERY | follows | ref    | index_follows_on_follower_id,index_follows_on_followed_id | index_follows_on_follower_id | 5       | const |    1 | Using where              |
|  2 | DEPENDENT SUBQUERY | users   | eq_ref | PRIMARY                                                   | PRIMARY                      | 4       | func  |    1 | Using where; Using index |
+----+--------------------+---------+--------+-----------------------------------------------------------+------------------------------+---------+-------+------+--------------------------+

“ALL” 타입에서 “ref”타입으로 변경된 것을 볼 수 있다. 이것은 정상적으로 인덱스를 탄다는 것을 뜻한다. 이렇게 2개의 풀스캔 중 1개를 없애니 실행 속도가 3.7초에서 0.03초로 엄청나게 줄어들었다.

+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                   |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.02776975 | SELECT `posts`.* FROM `posts` WHERE (`posts`.`user_id` IN (SELECT `users`.`id` FROM `users` INNER JOIN `follows` ON `users`.`id` = `follows`.`followed_id` WHERE `follows`.`follower_id` = 1) OR `posts`.`user_id` = 1) |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

다음으로 포스트의 풀스캔을 없애기 위해 포스트와 팔로우를 직접 JOIN하도록 했다.

이 과정에서 애를 좀 먹었는데 처음에 구상한 쿼리는 다음과 같았다.

SELECT posts.*
FROM posts
INNER JOIN follows
ON posts.user_id = follows.followed_id
WHERE follows.follower_id = 1 OR posts.user_id = 1

쿼리 안에서 유저 테이블에 대한 참조를 없애고 포스트와 팔로우 테이블로만 표현했다. 이것으로 인해 포스트 테이블도 “ref” 타입으로 변경되었고, 팔로우 테이블은 “index_merge” 타입으로 변경되었다.

+----+-------------+---------+-------------+-----------------------------------------------------------+-----------------------------------------------------------+---------+---------------------------+------+-------------------------------------------------------------------------------------+
| id | select_type | table   | type        | possible_keys                                             | key                                                       | key_len | ref                       | rows | Extra                                                                               |
+----+-------------+---------+-------------+-----------------------------------------------------------+-----------------------------------------------------------+---------+---------------------------+------+-------------------------------------------------------------------------------------+
|  1 | SIMPLE      | follows | index_merge | index_follows_on_follower_id,index_follows_on_followed_id | index_follows_on_follower_id,index_follows_on_followed_id | 5,5     | NULL                      |    2 | Using union(index_follows_on_follower_id,index_follows_on_followed_id); Using where |
|  1 | SIMPLE      | posts   | ref         | index_posts_on_user_id                                    | index_posts_on_user_id                                    | 5       | vinup.follows.followed_id |   50 | Using where                                                                         |
+----+-------------+---------+-------------+-----------------------------------------------------------+-----------------------------------------------------------+---------+---------------------------+------+-------------------------------------------------------------------------------------+

하지만 위의 쿼리에는 한 가지 문제가 있었다.

뉴스피드에서는 팔로우한 유저들의 포스트 뿐만 아니라 자신의 포스트도 보여줘야 하기 때문에 WHERE 절에 posts.user_id = 1을 추가했지만, INNER JOIN의 ON 조건에 의해 자신의 포스트가 제외되어 버렸다.

그리고 이 문제는 UNION을 사용해서 WHERE 절을 2개의 쿼리로 나누는 것으로 해결했다.

SELECT posts.*
FROM posts
INNER JOIN follows
ON posts.user_id = follows.followed_id
WHERE follows.follower_id = 1
UNION
SELECT posts.*
FROM posts
WHERE posts.user_id = 1;

UNION으로 작성하니 포스트까지 “ref” 타입으로 변경되었고 실행 시간은 0.0006초로 더욱 더 빨라졌다.

EXPLAIN
+----+--------------+------------+------+-----------------------------------------------------------+------------------------------+---------+---------------------------+------+-------------+
| id | select_type  | table      | type | possible_keys                                             | key                          | key_len | ref                       | rows | Extra       |
+----+--------------+------------+------+-----------------------------------------------------------+------------------------------+---------+---------------------------+------+-------------+
|  1 | PRIMARY      | follows    | ref  | index_follows_on_follower_id,index_follows_on_followed_id | index_follows_on_follower_id | 5       | const                     |    1 | Using where |
|  1 | PRIMARY      | posts      | ref  | index_posts_on_user_id                                    | index_posts_on_user_id       | 5       | vinup.follows.followed_id |   61 | Using where |
|  2 | UNION        | posts      | ref  | index_posts_on_user_id                                    | index_posts_on_user_id       | 5       | const                     |    5 | Using where |
| NULL | UNION RESULT | <union1,2> | ALL  | NULL                                                      | NULL                         | NULL    | NULL                      | NULL |           |
+----+--------------+------------+------+-----------------------------------------------------------+------------------------------+---------+---------------------------+------+-------------+

Profile
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                                                                                                   |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|        1 | 0.00066025 | SELECT posts.* FROM posts INNER JOIN follows ON posts.user_id = follows.followed_id WHERE follows.follower_id = 1 UNION SELECT posts.* FROM posts WHERE posts.user_id = 1                                               |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

5초 => 0.0006초, 아주 만족스러운 작업이었다 ^ㅇ^

참고 링크


[Rails] 배포 환경에서 발생하는 Auto loading 문제


레일즈는 소스 코드 파일을 로드하기 위해서 실제로 사용될 때 그제서야 파일을 로드하는 Auto loading1과 서버가 실행될 때 한 번에 모든 파일을 로드하는 Eager loading 두 가지 방식을 사용한다.

며칠 전 까지만 해도 나는 Auto loading 방식만 대충 알고 있었고 Eager loading 방식에 대해서는 모르고 있었는데, 정말 우연한 계기로 두 방식을 상황에 맞게 적절히 사용하지 않으면 개발이나 테스트 환경이 아닌 배포 환경에서 문제가 될 수 있다는 것을 알게 되었다. 이 문제를 통해 레일즈의 Auto loading 방식과 Eager loading 방식에 대해서 좀 더 자세히 알아보자.

1. 어떤 문제가 있었는지?

lib 디렉토리에 존재하는 파일을 읽지 못하는 문제였다. lib 디렉토리에 선언된 클래스를 불러오지 못해서 클래스를 사용하려고 하면 NameError: uninitialized constant 에러가 발생했다.

그런데 이상했던 점은 개발, 테스트 환경에서는 정상적으로 불러오다가 스테이징, 프로덕션 환경에 배포하기만 하면 불러오지 못한다는 것이었다. 테스트도 모두 성공하고 콘솔로 테스트해봐도 제대로 불러오는데 배포환경만 되면 에러를 뿜어대니 돌아버릴 지경이었다.

2. 문제의 원인

오랜 삽질과 검색 끝에 결국 원인을 찾아냈는데, 레일즈 4.2 버전에서 5.0으로 버전 업 될 때 production 환경에서 auto loading 기능을 비활성화 시키는 기능이 추가되었다.2 이게 왜 문제가 되냐면 이전에는 개발 환경이든 배포 환경이든 auto loading을 사용했기 때문에 app 디렉토리 이외의 디렉토리를 로드할 땐 다음과 같이 설정하는게 일반적이었다.

# config/application.rb

...
  config.autoload_paths << Rails.root.join('lib')
...

그런데 배포 환경에서 auto loading이 비활성화 되어버리니 위의 설정 코드가 무용지물이 되어버리고 lib 디렉토리를 참조할 수 없게 된 것이다.

3. 문제의 해결 방법은?

해결 방법은 간단하다. 배포 환경에서는 Eager loading 방식을 사용하므로 배포 환경일 땐 config.eagerload_paths에 경로를 추가하면 된다.

# config/application

...
  if Rails.env.development? || Rails.env.test?
    config.autoload_paths << Rails.root.join('lib')
  else
    config.eager_load_paths << Rails.root.join('lib')
  end
...

그런데 실제로 오토 로딩되는 경로는 autoload_paths + eager_load_paths이기 때문에3 설정 코드를 더 간단히 하기 위해 config.eager_load_paths만 작성해도 된다.

# config/application

...
  config.eager_load_paths << Rails.root.join('lib')
...

참고

  1. https://collectiveidea.com/blog/archives/2016/07/22/solutions-to-potential-upgrade-problems-in-rails-5
  2. http://blog.arkency.com/2014/11/dont-forget-about-eager-load-when-extending-autoload/
  1. Lazy loading이라는 용어가 있지만 레일즈에선 auto loading이라고 부른다. Ruby 언어에서 소스 파일을 lazy하게 불러올 때 사용되는 autoload 키워드에서 따온 것 같은데, Ruby의 autoload는 3.0 버전 이후 deprecated 될 수 있다고 한다. 

  2. 업그레이드 가이드 문서 참조 

  3. Rails Engine 코드 참조 


[Rails] 타임 헬퍼로 시간 테스트하기


테스트 코드를 실행할 때 현재 시간을 변경하고 싶을 때가 있다. 예를 들어 모임 시간을 가지는 모임(Meeting) 클래스가 있고 모임 시간이 지났을 때 종료 상태를 반환하는 메서드를 테스트한다고 해보자. 먼저 모임 클래스는 다음과 같다.

class Meeting
  attr_accessor :time

  def initialize(time)
    @time = time
  end

  def finished?
    time < Time.now
  end
end

모임의 시간은 임의로 정할 수 있지만 Time.now가 반환하는 시간은 변경하기 까다롭다. 이럴 때 레일즈에서 제공하는 타임 헬퍼 모듈 (ActiveSupport::Testing::TimeHelpers)을 사용하면 좋다.

# spec/unit/meeting_spec.rb
require 'rails_helper'

describe Meeting do
  include ActiveSupport::Testing::TimeHelpers

  describe "#finished?" do
    let(:meeting_time) { Time.now }
    let(:meeting) { Meeting.new(meeting_time) }

    context "모임 시간이 지났을 때" do
      before do
        # 현재 시간을 하루 뒤로 설정한다.
        travel(1.day)
      end

      it { expect(meeting.finished?).to eq(true) }
    end

    context "모임 시간이 지나지 않았을 때" do
      before do
        # 현재 시간을 모임 시간 하루 전으로 설정한다.
        travel_to(meeting_time - 1.day)
      end

      it { expect(meeting.finished?).to eq(false) }
    end
  end
end

나는 타임 헬퍼를 시간으로 정렬되는 것을 테스트할 때 사용하고 있다. 데이터베이스에 2개의 레코드를 생성한 뒤 정렬 결과를 확인하는 방식인데, 테스트 코드가 너무 빨리 실행되서인지 레코드의 created_at이 같아지는 바람에 정렬 테스트의 결과가 실행할 때 마다 달라지는 문제가 있었다.

it "최신순으로 정렬되어야 함" do
  old_meeting = create(:meeting)
  new_meeting = create(:meeting)

  # old_meeting과 new_meeting의 created_at이 같음!
  expect(sorting code).to eq([new_meeting, old_meeting])
end

이 때 현재 시간을 1초 정도 딜레이 시켜주면 정상적으로 테스트할 수 있다. 물론 created_at 값을 직접 설정해도 되지만 코드를 읽을 때 타임 헬퍼를 사용하는 것이 좀 더 직관적으로 보인다.


# created_at 변경
it "최신순으로 정렬되어야 함" do
  old_meeting = create(:meeting, created_at: Time.now)
  new_meeting = create(:meeting, created_at: Time.now + 1.second)

  # old_meeting과 new_meeting의 created_at이 1초 차이남
  expect(sorting code).to eq([new_meeting, old_meeting])
end

# 타임 헬퍼 사용
it "최신순으로 정렬되어야 함" do
  old_meeting = create(:meeting)
  travel 1.second
  new_meeting = create(:meeting)

  # old_meeting과 new_meeting의 created_at이 1초 차이남
  expect(sorting code).to eq([new_meeting, old_meeting])
end

이 때 주의할 점은 테스트가 끝나도 현재 시간이 초기화되지 않는다는 것이다. 전체 테스트에서 travel 1.second 코드를 300번 사용하면 현재 시간이 5분이 밀리게 된다. 이것 때문에 뜻밖의 오류가 발생할 수 있으니 반드시 테스트 종료 후에 travel 메서드로 변경한 시간을 초기화 시키는 travel_back 메서드를 실행시켜 주어야 한다. 이것은 rails_helper.rb 설정 파일에 작성할 수 있다. (RSpec 기준)

# spec/rails_helper.rb

...

RSpec.configure do |config|
  ...
  config.include ActiveSupport::Testing::TimeHelpers
  ...

  config.after(:each) do
    travel_back
  end
end

rails_helper.rb 파일에서 타임 헬퍼를 include 하면 모든 테스트 코드에서 사용할 수 있기 때문에 이제 meeting_spec.rb에서 include 코드를 작성할 필요는 없다.

# spec/unit/meeting_spec.rb
require 'rails_helper'

describe Meeting do
  # include ActiveSupport::Testing::TimeHelpers

  describe "#finished?" do
    ...
  end
end

logrotate로 리눅스 로그 관리


웹 서비스를 운영할 때 쉽게 놓칠 수 있는 것 중 하나가 로그 관리다. 로그를 관리하지 않아도 운영하는데는 문제가 없으며 운영 초반에는 로그를 관리해야할 정도로 트래픽이 발생하는 경우가 드물기 때문이다.

하지만 시간이 점점 지나고 트래픽이 늘어나면 로그는 고스란히 디스크에 쌓이게 되고, 이를 그대로 방치해두면 엄청난 디스크 용량을 낭비하게 된다.

끝도 없이 늘어나는 로그 파일을 관리하기 위해 리눅스에서는 logrotate라는 프로그램을 사용하면 좋다. logrotate는 정해진 시간마다 로그 파일을 백업시켜주는데, 로그 파일이 무작정 늘어나는 것을 방지하기 위해 로그 파일의 최대 개수를 정해놓으면 최대 개수를 초과했을 때 가장 오래된 로그 파일을 삭제하고 새로운 로그 파일을 생성하면서 rotating 해주는 툴이다.

시스템에 설치되어있지 않다면 설치해준다.

sudo yum install -y logrotate

/etc/logrotate.conf 파일에 어떤 로그를 로테이팅할지 작성할 수 있다. 파일을 열어보면 기본으로 작성된 코드가 있을 것이다.

# see "man logrotate" for details
# rotate log files weekly
weekly

# keep 4 weeks worth of backlogs
rotate 4

# create new (empty) log files after rotating old ones
create

# use date as a suffix of the rotated file
dateext

# uncomment this if you want your log files compressed
#compress

# RPM packages drop log rotation information into this directory
include /etc/logrotate.d

# no packages own wtmp and btmp -- we'll rotate them here
/var/log/wtmp {
    monthly
    create 0664 root utmp
        minsize 1M
    rotate 1
}

/var/log/btmp {
    missingok
    monthly
    create 0600 root utmp
    rotate 1
}

# system-specific logs may be also be configured here.

중간에 include /etc/logrotate.d를 보면 /etc/logrotate.d 디렉토리의 파일들을 전부 불러오는 것을 알 수 있다. 그럼 이제 /etc/logrotate.d 디렉토리에 새로운 설정 파일을 생성하고 레일즈 프로젝트의 로그를 관리하도록 작성해보자.

# /etc/logrotate.d/myproject

/home/ec2-user/myproject/log/production.log {
  weekly
  rotate 4
  missingok
  dateext
  postrotate
    touch /home/ec2-user/myproject/tmp/restart.txt
  endscript
}

이렇게 설정한 뒤에 한 번 실행해보자.

sudo /usr/sbin/logrotate /etc/logrotate.d/myproject

처음 실행했을 때는 아무 일도 일어나지 않는다. 왜냐면 logrotate는 실행될 때 /var/lib/logrotate.status 파일을 통해 정해진 기간이 지났는지 확인하는데 방금은 아무 정보가 없었기 때문이다. /var/lib/logrotate.status 파일에 현재 날짜만 기록하고 로테이팅이 실행되지는 않았다.

# /var/lib/logrotate.status

logrotate state -- version 2
"/var/log/yum.log" 2016-1-1
"/home/ec2-user/myproject/log/production.log" 2016-12-10
"/var/log/dracut.log" 2016-1-1
"/var/log/wtmp" 2015-12-1
"/var/log/spooler" 2016-12-4
"/var/log/btmp" 2016-12-1
"/var/log/maillog" 2016-12-4
"/var/log/secure" 2016-12-4
"/var/log/messages" 2016-12-4
"/var/account/pacct" 2015-12-1
"/var/log/cron" 2016-12-4

production.log 파일이 오늘 날짜(2016-12-10)로 실행되었다는 것이 저장되었다. 이제 12월 17일이 되어야 1주일이 지났다는 것을 인식하고 로테이팅이 실행될 것이다.

지금 당장 확인해보려면 2016-12-10을 일주일 전인 2016-12-03으로 바꾼 뒤 sudo /usr/sbin/logrotate /etc/logrotate.d/myproject를 한번 더 실행해보면 된다.


블로그 주소 저장


전에 작성한 “mvc 웹 프레임워크의 문제점” 포스트에서 밥 아저씨의 Clean Architecture 강의 영상으로 다음 포스트를 쓴다고 했는데, 내가 쓰려는 포스트와 거의 비슷한 블로그 포스트를 찾음

읽어보고 도움도 많이 되었고 좋은 글이라 공유해둠

https://medium.com/@fbzga/clean-architecture-in-ruby-7eb3cd0fc145


Pagination