なるほど、ボトルネックはAPIに掛かる時間だけではなく、APIが呼び出される回数にも依存するのか、といつしか知ってから数ヶ月。
RailsのAPIのどれが一番時間を占有しているのか取り敢えず簡単に調べたいなー、と思って特に何のgemとかも入れずに調べてみました。
準備
取り敢えず、そのAPIの時間占有率を調べる為のデータ型を作ってしまおう。
コンソール上で
bundle exec rails g model ApiOccupancyData
マイグレーションを書き込み。最低限必要なのは、コントローラ名、アクション名、それからAPIの消費秒数と総呼び出し回数でしょう。
class CreateApiOccupancyData < ActiveRecord::Migration def change create_table :api_occupancy_datas do |t| t.string :controller_name, comment: "コントローラ名" t.string :action_name, comment: "アクション名" t.integer :average_time, default: 0, comment: "API消費秒数(ms)" t.integer :total_call_count, default: 0, comment: "API総呼び出し回数" t.timestamps end add_index :api_time_occupied_datas, [:controller_name, :action_name], unique: true, name: "api_name_index" end end
それで、最後にrake db:migrateしてモデル作成。
計測
取り敢えず、ログを弄る、ログデータから取ってくるとかするのは、モンキーパッチをする必要がありそうだし、深く調べなきゃいけないし、色々時間が掛かりそう。
というわけで、簡単にコントローラ全体にbefore_action, after_actionを掛けてしまって、時間を取ってしまうことにしました。
class ApplicationController < ActionController::Base before_action :set_time after_action :recognize_time def set_time @start_time = Time.now end def recognize_time #ms単位で差を計測 time_cost = ((Time.now - @start_time) * 1000).to_i #パラメータにコントローラ名とアクション名は入っている controller_name = params[:controller] action_name = params[:action] record = ApiOccupancyData.find_or_create_by(controller_name: controller_name, action_name: action_name) #平均時間を上書き record.average_time = ((record.average_time * record.total_call_count) + time_cost) / (record.total_call_count + 1) #総呼び出し回数を更新 record.total_call_count += 1 record.save end end
後はRailsを色々動かしてみて、データが貯まるのを待ちましょう。
出力
Railsコンソール上であとは、
ApiOccupancyData.order("average_time * total_call_count DESC")
とでも打てば時間占有率が高い順にデータが列挙されていきます。
そこから、API単位で詳しく見ていって、どこで時間が掛かっているか等、調べていけます。
後、chart.jsで可視化とかをするとより分かり易くなったり。
