ども。いよいよWEBアプリ作成も終盤、終盤と言いながらまったく完成していません（笑
一通り重要な機能は完成しているのですが、周辺機能をいじりたくなっちゃうんですよね。検索機能の強化や詳細化もやりたいし。
パンくずリストを実装したのと、それからslickの画像スライダーは現実には使いにくいので止めてサムネイル画像を出すように改変したりしています。
今日はテックアカデミーの講師とのビデオ通話を行いました。自分が気にしていた「WEBアプリのパフォーマンス」について聞くことができました。
WEBアプリを開発したらパフォーマンスを測定しよう
WEBサイト全般に言えますがレスポンスが遅いのはユーザーのために良くない事です。サイトにアクセスして3秒かかればちょっと遅いなと感じます。5秒もかかればもうほとんどの人がバックボタンで離脱してしまうのではないでしょうか。
どんなに良いコンテンツを持ったサイトであっても速度が遅いだけで見られない、使われないサイトになってしまい勿体無いです。自分のサイトが世のため人のためのサイトだと思えばこそ速度アップの改善を測るべきですよね。
さて、WEBアプリの場合はユーザーがアクセスして、サーバーで処理をして、データを返すという一連の処理があるのでどこかに遅い処理が潜んでいるかもしれません。そんな遅い処理を特定して改善しましょう。
今作っているWEBサイトはheroku上に公開していますので、herokuのログを吐き出して見ていきます。
heroku logsを見る方法
herokuのログを見るには以下のコマンドで行います。
$heroku logs
またリアルタイムでログが流れていくのを見るには
$heroku logs -t/span>
とtオプションを付けます。
それからherokuではデフォルトで1500行しかログに出ないようで、それ以前のログから消えていくそうです。
今回はログの内容をファイルに吐き出そうと思い、以下のコマンドを打ち込みました。
$heroku logs -t > mylog.txt/span>
これでmylog.txtというファイルが生成されログが記述されていきます。ログは1分後に書き込まれていくので少し待たないといけないです。
heroku logsの見かた
以下ログのサンプルです。
2018-05-03T12:43:32.688868+00:00 app[web.1]: => Booting Puma
2018-05-03T12:43:32.688897+00:00 app[web.1]: => Rails 5.0.6 application starting in production on http://0.0.0.0:20704
2018-05-03T12:43:32.688900+00:00 app[web.1]: => Run `rails server -h` for more startup options
2018-05-03T12:43:32.688901+00:00 app[web.1]: Puma starting in single mode…
2018-05-03T12:43:32.688909+00:00 app[web.1]: * Version 3.11.3 (ruby 2.3.7-p456), codename: Love Song
2018-05-03T12:43:32.688911+00:00 app[web.1]: * Min threads: 5, max threads: 5
2018-05-03T12:43:32.688913+00:00 app[web.1]: * Environment: production
2018-05-03T12:43:32.689097+00:00 app[web.1]: * Listening on tcp://0.0.0.0:20704
2018-05-03T12:43:32.699153+00:00 app[web.1]: Use Ctrl-C to stop
このあたりでWEBサーバー（Puma）が起動したよ、と書いてあるのがわかります。一番左から日付、日時、マイクロ秒です。アメリカ時刻です。
次の事例がこちら。
2018-05-03T12:43:33.591468+00:00 app[web.1]: I, [2018-05-03T12:43:33.591355 #4] INFO — : [2f14b374-e71a-4312-b3ad-e97abff9e620] Started GET “/” for 124.142.4.252 at 2018-05-03 12:43:33 +0000
2018-05-03T12:43:33.604790+00:00 app[web.1]: I, [2018-05-03T12:43:33.604674 #4] INFO — : [2f14b374-e71a-4312-b3ad-e97abff9e620] Processing by ToppagesController#index as HTML
2018-05-03T12:43:33.621364+00:00 app[web.1]: I, [2018-05-03T12:43:33.621218 #4] INFO — : [2f14b374-e71a-4312-b3ad-e97abff9e620] Rendering toppages/index.html.erb
2018-05-03T12:43:33.699599+00:00 app[web.1]: I, [2018-05-03T12:43:33.699530 #4] INFO — : [2f14b374-e71a-4312-b3ad-e97abff9e620] Completed 200 OK in 95ms (Views: 81.0ms | ActiveRecord: 17.5ms)
こちら、1行目がStarted GET “/” と書いてあります。これは “/” ←ルートなのでドメイントップへのGETアクセスが来たよと書いてあります。
それによって2行目のToppagesController#index（このメソッドは自分が書いたもの）で処理をしてます。
3行目でトップページのメイン部分を表示させています。
4行目でCompleted 200と書いてあり、ユーザーへの画面の戻しが完了したことがわかります。 in 95ms ←これがリクエストが来てから完了するまでの秒数です。95マイクロ秒なので早いと思います。後半のViewsで81.0msがビューの表示にかかった秒数で、ActiveRecord: 17.5msはActiveRecordの処理にかかった時間です。
また各行の真ん中らへんに以下の文字列があります。
[2f14b374-e71a-4312-b3ad-e97abff9e620]
テックアカデミーの先生によると、これはUUIDと言うそうです。各ユーザーの1リクエスト毎にふられるユニークなIDです。1回のリクエスト内のすべての処理がこの同一のUUIDが付与されます。UUIDでグルーピングすれば1回のリクエスト内のすべての処理を特定することができます。またこのIDで検索してCompletedの行を見つければ全体で何秒かかったのかわかります。
時間がかかっている箇所を特定し改善する
ある処理を行った時にやたら時間がかかっているページがありました。
INFO — : [7b958650-f327-4d0e-806a-311a0f9029d3]
Started GET “/shops?utf8=%E2%9C%93&area=%E6%9F%8F%E9%A7%85&tenpo_genre=&commit=%E6%A4%9C%E7%B4%A2&option=1”
中略
2018-05-03T12:43:42.172944+00:00 app[web.1]: I, [2018-05-03T12:43:42.172849 #4]
INFO — : [7b958650-f327-4d0e-806a-311a0f9029d3]
Completed 200 OK in 1983ms (Views: 115.6ms | ActiveRecord: 104.4ms)
Completed 200 OK in 1983msですので、約2秒です。この処理は僕が作ってるWEBアプリの中で1番時間がかかっている処理でした。行の後半でViewsは115.6msで、ActiveRecordは104.4msですのでViewとActiveRecordはそこまで悪くは無いと思います。
こうなってくるとどこで時間がかかっているか場所の特定をしなくてはいけません。今回のWEBアプリでは幸いなことにスグ特定することができました。なぜなら僕はプログラムの中でしょっちゅうputsで処理の内容を標準出力に出していたからです。たとえば「ここで●●インスタンス生成」とか「●●メソッド通過」とか書いてあるわけです。
ログを見てたら以下のような箇所を発見。
2018-05-03T12:43:40.194498+00:00 app[web.1]: ◆クエリは
2018-05-03T12:43:41.707777+00:00 app[web.1]: ◆JSONは
2行目～3行目の間で秒数を見てみると41.707777 – 40.194498 = 1.513279秒もかかってることがわかりました。この処理の一番時間がかかってるのはココで特定できました。
ここで何をしてるかというと、私が作ってるWEBアプリは店舗検索機能がついていて、YahooのAPI検索を行います。そのときの検索クエリとAPIから取得してきたJSONデータを受け取るまでの時間が約1.5秒かかってるわけです。
herokuがあるサーバーがアメリカで、Yahoo APIがあるのはたぶん日本なので、米国から日本に取りに行く物理的なネットワーク上の時間がかかっているんだろうなと思います。
herokuサーバーが日本に来てくれない限りこの処理は早くなりませんのでお手上げです。ここは仕方がないと諦めです。つまり改善できず。
3秒ルール以内なので判断としてこれで継続することにしました。
取り敢えずテストを行って一番遅い箇所がココだけで、ほかの画面は問題なかったのでヨシということにしました。
テックアカデミーの講師の方からのアドバイスとして、ほかには次の2つのアドオンを紹介いただきました。
https://qiita.com/y_uuki/items/dd4fce78b1bc32b64600
これは処理上のどこが遅いかを特定するのに役立つツールです。見た目がグラフで出るのでネットワークが遅いのか、RailsなのかDBなのか特定するのに役立つようです。
・Papertrail
http://vdeep.net/heroku-papertrail
https://blog.leko.jp/post/research-of-log-collection-and-monitoring-in-heroku/
こちらはログを保管するためのものです。先程も書いたようにherokuのログは1500行しか出ないらしく、このツールを入れれば1週間はログを保持できるようになります。（無料版なら）もしWEBアプリを公開して維持していく中で何か問題が起こった時にログを保持していなければ場所の特定が出来ないので、このツールを使っていくのはやらないといけない気がしますね。
しかし紹介していただいたものの、新しいことを取り入れたり覚えたり、操作に慣れるのに時間がかかるのは必至です。さぁてどうしようか‥
