APIの時間占有率を簡単に調べてみた

この記事はアピリッツの技術ブログ「DoRuby」から移行した記事です。情報が古い可能性がありますのでご注意ください。

ツールやgemを入れずに調べてみた。

　なるほど、ボトルネックは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で可視化とかをするとより分かり易くなったり。