ピクスタ開発部の星直史です。
メリークリスマス！！！これは現実です！クリスマスは今年も開催します！！！
本日、私はケンタッキー、パック寿司、コージーコーナーのショートケーキとシャンメリーを買い込み、ネットしながら一人クリスマス会をしようと思います！！

この記事はPIXTA Advent Calendar 2017 25日目の記事です。

さて、先日てくすたでfotowaの開発環境構築にDockerを導入した話を紹介しました。
PIXTAをメインに開発するチームの開発環境でもDockerを導入をしているのですが、PIXTAのTOPページを表示するのに60秒近くかかっていました(！)
この記事では、開発環境高速化の取り組みについて紹介をします。

開発環境の概要

ピクスタ開発部メンバーの多くはMacOSで開発をしています。*1 また、Docker for Macとdocker-syncをインストールし、Docker Composeでコンテナを立ち上げることで、コマンド一発で開発環境を立ち上げています。

高速化するまでのステップは基本に忠実に行いました。

問題を再現する
対策の検討と実施
対策の検証
ボトルネックを探し1に戻る

問題解決を迅速に行うためには、事実をベースにして仮説検証をすることが重要です。
そのためには、問題となっている事象を再現し、何が原因で問題が引き起こされているのか的確に把握することが重要です。問題の原因特定が仮説検証の精度を左右するといっても過言ではないと思います。

問題を再現する

問題を再現するにはまず、問題がどこにあるかを確認するためRailsアプリケーションのlog/development.logを確認します。

...略
Started GET "/" for 172.21.0.1 at 2017-12-25 03:32:36 +0000
  ActiveRecord::SchemaMigration Load (23.0ms)  SELECT `schema_migrations`.* FROM `schema_migrations`
  ActiveRecord::SchemaMigration Load (22.6ms)  SELECT `schema_migrations`.* FROM `schema_migrations`
  Currency Load (10.1ms)  SELECT `currencies`.* FROM `samples`
  Currency Load (9.8ms)  SELECT `currencies`.* FROM `samples`
Processing by SampleController#index as HTML
#<ActionDispatch::Request::Session:0x0056081879bca8>
{:analysis=>{}, :_csrf_token=>"2mE6LEmIjbJ/GuU9SvsN5PUu7qiivU4fKX2/pifFOQk="}
Dalli::Server#connect cache.pixta.jp:11211
hogehoge.pixta.jp:11211 failed (count: 0) SocketError: getaddrinfo: Name or service not known
Session::DalliStore#get: No server available

...略

Started GET "/assets/i18n.self.js?body=1" for 172.21.0.1 at 2017-12-25 03:35:14 +0000
Started GET "/assets/i18n/shims.self.js?body=1" for 172.21.0.1 at 2017-12-25 03:35:15 +0000
Started GET "/assets/sample1.js?body=1" for 172.21.0.1 at 2017-12-25 03:35:16 +0000
Started GET "/assets/sample2.js?body=1" for 172.21.0.1 at 2017-12-25 03:36:21 +0000
Started GET "/assets/sample3.js?body=1" for 172.21.0.1 at 2017-12-25 03:37:53 +0000
Started GET "/assets/sample4.js?body=1" for 172.21.0.1 at 2017-12-25 03:38:24 +0000

...略

このログを見て2点問題があることに気づきました。

Assetsをライブコンパイルしている
キャッシュを使用していない

ログを確認すると、レンダリングが完了するまでに、Assetsを動的なSprocketsコンパイルしているため配信に時間がかかっていることと、キャッシュが効いていないため、都度DBアクセスする重い処理が走っていることがわかりました。

対策の検討と実施

Railsアプリケーションにおける問題は前述の通りなので、対策としては設定ファイルを変更が考えられます。
具体的には、config/enviroments/development.rbの修正です。

Assetsを事前にコンパイルする

config/enviroments/配下の設定の詳細はRailsガイドを参考にしました。
compile周りの設定は下記の設定で変更しました。

# コンパイル済みアセットを圧縮するかどうかを指定。圧縮することで、データ容量を減らし、高速化をする
config.assets.compress = true

# JavaScriptの圧縮に使用するプログラムを定義。:uglifierが最も圧縮率が高い
config.assets.js_compressor = :uglifier

# CSSの圧縮に使用するプログラムを定義
config.assets.css_compressor = :scss

# 動的なSprocketsコンパイルをするかどうかを指定
config.assets.compile = false

# デバッグ用にアセットの連結と圧縮をやめるかどうかを指定
config.assets.debug = false

precompileした場合の懸念点はいくつかありました。

JSやCSSに修正した場合に再度rake assets:precompileコマンドを実行しなくてはならない。
config.assets.debug = falseとconfig.assets.compress = trueとしているため、エラー時のデバッグがしにくい

上記について、既にwebpackを導入していたため、--progress --watchオプションで起動することで、修正反映直後に再ビルドが走り、かつ、エラーが発見できるため、問題ありませんでした。*2

キャッシュ使用する

キャッシュの設定についても、Railsガイドを参考に設定していきます。
memcachedをコンテナ化しているので、それを指定します。

# Railsでのキャッシュ処理に使用されるキャッシュストアを設定します
config.cache_store = :dalli_store, "memcached.pixta.jp", { compress: true }

# Sprocketsで使用するキャッシュストアを定義します
config.assets.cache_store = :dalli_store, "memcached.pixta.jp", { compress: true }

対策の検証

設定ファイルを変更したのちに下記コマンドを実行し、TOPページにアクセスすると、10秒前後に高速化されました。

rake assets:precompile
yarn webpack --config config/webpack.config.babel.js --progress --watch

高速化されたとはいえ、ソースコードを修正し、更新するごと10秒待たされるのは苦痛です。
ログを見るとRailsアプリケーションに到達してからは高速化されたのですが、一番最初の処理が開始されるまでに待ち時間がありました。

このことから、Webサーバー(Apache HTTP Server、Passenger)の処理に問題がありそうなので、Webサーバー側のログを見ます。*3
具体的にはaccess.logとerror.logです。

172.21.0.5 - - [25/Dec/2017:03:39:33 +0000] "GET /sample HTTP/1.1" 200 315 "-" "Typhoeus - https://github.com/typhoeus/typhoeus"
172.21.0.1 - - [25/Dec/2017:03:39:32 +0000] "GET / HTTP/1.1" 200 17108 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
172.21.0.1 - - [25/Dec/2017:03:40:55 +0000] "GET /assets/frontend/vendor.js HTTP/1.1" 304 - "http://dev.pixta.jp/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"

確認しても、特に疑わしい箇所はなかったのですが、access.logに書き込まれるまでに数秒待たされていました。
これは何度アクセスしても同じでした。

問題を再現する(2サイクル目)

さすがにこれ以上ログから追うことはできなそうでしたので、Apache HTTP Serverの設定ファイルを確認することにしました。

...略
<IfModule mpm_prefork_module>
    StartServers          16  
    MinSpareServers       16  
    MaxSpareServers       32  
    ServerLimit           400 
    MaxClients            400 
    MaxRequestsPerChild   10000
</IfModule>

<IfModule mpm_worker_module>
    StartServers          4   
    MaxClients            1024
    MinSpareThreads       64  
    MaxSpareThreads       192 
    ThreadsPerChild       64  
    MaxRequestsPerChild   10000
</IfModule>

...略

LoadModule alias_module modules/mod_alias.so
LoadModule auth_basic_module modules/mod_auth_basic.so
LoadModule authn_file_module modules/mod_authn_file.so
LoadModule authz_default_module modules/mod_authz_default.so
LoadModule authz_groupfile_module modules/mod_authz_groupfile.so
LoadModule authz_host_module modules/mod_authz_host.so
LoadModule authz_user_module modules/mod_authz_user.so
LoadModule autoindex_module modules/mod_autoindex.so
LoadModule deflate_module modules/mod_deflate.so
LoadModule dir_module modules/mod_dir.so
LoadModule env_module modules/mod_env.so
LoadModule expires_module modules/mod_expires.so
LoadModule headers_module modules/mod_headers.so
LoadModule log_config_module modules/mod_log_config.so
LoadModule mime_module modules/mod_mime.so
LoadModule negotiation_module modules/mod_negotiation.so
LoadModule proxy_module modules/mod_proxy.so
LoadModule rewrite_module modules/mod_rewrite.so
LoadModule setenvif_module modules/mod_setenvif.so
LoadModule status_module modules/mod_status.so

...略

設定ファイルで挙動に影響がありそうな箇所は2箇所のみでした。

MPM(Multi Processing Module)の設定
不要なLoadModuleのInclude

ここの2箇所以外はミニマムな設定だったので、ここに狙いをつけることにしました。

対策の検討と実施(2サイクル目)

MPMの設定

Apache HTTP ServerにはMPM(Multi Processing Module)といわれるリクエストを受けた際の処理の方法の違いがあるモジュールが用意されています。
現在の設定を確認するために、下記コマンドで確認します。

$ /usr/sbin/apachectl -V
Server version: Apache/2.2.15 (Unix)
Server built:   Mar 22 2017 06:52:55
Server's Module Magic Number: 20051115:25
Server loaded:  APR 1.3.9, APR-Util 1.3.9
Compiled using: APR 1.3.9, APR-Util 1.3.9
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)

コマンドを確認すると、設定がPreforkが設定されていることがわかります。
Apache HTTP ServerのMPMは数種類用意されています。代表的なものは下記の通りです。

prefork
worker
event

それぞれの違いについては、公式のドキュメントに詳細が載っていますので、解説はそちらに譲ります。
マルチプロセッシングモジュール (MPM)

preforkはリクエストを受けたらプロセスが処理します。workerはリクエストをスレッドが処理することになるので、プロセスを立ち上げる分のオーバーヘッドが少なくなるため、workerの方が高速になります。

MPMをpreforkからworkerへの切り替えは、etc/sysconfig/httpdにHTTPD=/usr/sbin/httpd.workerを追加し、再起動するだけで変更できます。

# The default processing model (MPM) is the process-based
# 'prefork' model.  A thread-based model, 'worker', is also
# available, but does not work with some modules (such as PHP).
# The service must be stopped before changing this variable.
#
HTTPD=/usr/sbin/httpd.worker

変更結果は下記の通りです。

$ /usr/sbin/apachectl -V
Server version: Apache/2.2.15 (Unix)
Server built:   Mar 22 2017 06:53:18
Server's Module Magic Number: 20051115:25
Server loaded:  APR 1.3.9, APR-Util 1.3.9
Compiled using: APR 1.3.9, APR-Util 1.3.9
Architecture:   64-bit
Server MPM:     Worker
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)

不要なLoadModuleのInclude

httpd.confのLoadModulesを確認すると、開発環境においては不要なModuleが読み込まれていました。

こちらについては、あまり特別なことはしておらず、公式のドキュメントを参照し、読み込まれているModuleを一つずつ、どんな用途で使用するのかを確認しながら、消していき、必要最低限のModuleだけをIncludeすることにしました。

対策の検証(2サイクル目)

MPMをworkerに設定し、LoadModuleを必要最低限に絞りアクセスすると、10秒前後かかっていたのが3秒弱にまで縮まりました。

しかし、Railsアプリケーションの最初の処理が動き出すまでに、1秒前後かかっていました。
前述の通り、ピクスタの開発部は大多数がMacOSを使用しています。そのため、docker-syncでホストとコンテナ間でファイルの同期をする必要がありました。マウント時の同期オプションの変更PRなどで速度改善がなされましたが、そもそもファイル同期が遅いというissueがあることや、中でもMacOSとDockerの同期速度が遅いので、そこがボトルネックになっていると仮説を立てました。

問題を再現する(3サイクル目)

試しに、素のEC2インスタンスにDockerとDocker Composeをインストールし、開発環境を立ち上げた後にアクセスしたところ、3秒だった処理が1.5秒前後にまで縮まりました。
このことから、ホストOSの相性が悪かったことがわかりました。

対策の検討と実施(3サイクル目)

ピクスタ開発部はベトナムにも開発拠点があり、ベトナムメンバーが主に使用しているOSはUbuntuです。
そのため、Dockerにより開発環境構築の標準化を進めていましたが、Dockerをインストールする手順がUbuntuとMacで微妙に異なってしまうため、ドキュメントが2つ存在していました。

そこで、MacOSとDockerの同期速度の改善と、開発環境の標準化をもう一歩進めるために、Vagrantを導入することにしました。

元々、Ubuntu用のドキュメントや、docker-composeの資産があったので、単純にVagrantで仮想環境を立ち上げ、Vagrantfileのprovisioningブロックの中でドキュメントに書かれていた処理内容を転記するだけでしたので、楽に導入することができました。

対策の検証

前述の通り、仮装環境を立ち上げ、その上にDockerを起動させることで、3秒から1.5秒にすることができました。狙い通りですね。

また、仮装環境内でコンテナを立ち上げたことで、bundle installやrake assets:precompileなど、ファイルI/Oが発生する処理も高速化されました。当初240秒かかっていた処理が60秒(！)に高速化されました

まとめ

Railsの設定ファイルを変更することで速くなることは予想していましたが、ミドルウェアの設定や、Dockerとそれを動作させるOSとの相性まで考え抜けたのは、計測を基にして対応したからだと思います。

60秒かかっていた処理を1.5秒にできたので、快適な開発を手に入れることができたのは直接的な成果ではありますが、開発部全体のパフォーマンスが向上することで、間接的にサービスへの貢献できたのではないかと思います。

また、記事上ではｻｸｻｸ解決しているように見えますが、詳細な設定ファイルの調整や挙動をしっかり調べて変更を行ったので、スキルの向上も図れたと思います。派手なことはしていませんが、こういう泥臭い作業の蓄積がスキルの蓄積になるものだと、個人的には思います。

ピクスタでは常に改善を繰り返し、サービスに貢献していきたいエンジニアを募集しています！！

recruit.pixta.co.jp

*1:Mac以外のOSでも希望があれば使うことができます

*2:逆にここがクリアできなければ、今回の修正は入れることができなかったと思います。

*3:LogLevelをdebugにすると、詳細な情報が見ることができます

てくすた

ピクスタ株式会社のエンジニア・デザイナーがつづるよもやまテクニカルブログです

開発環境のレスポンスを60秒から1.5秒に高速化した3つのポイント

開発環境の概要

問題を再現する

対策の検討と実施

Assetsを事前にコンパイルする

キャッシュ使用する

対策の検証

問題を再現する(2サイクル目)

対策の検討と実施(2サイクル目)

MPMの設定

不要なLoadModuleのInclude

対策の検証(2サイクル目)

問題を再現する(3サイクル目)

対策の検討と実施(3サイクル目)

対策の検証

まとめ