パフォーマンスの測り方 — ボトルネックを見つける

# パーセンタイルの意味
# もし1000リクエストのレスポンスタイムが:
# P50 = 100ms  → 500番目に遅いリクエストが100ms
# P95 = 500ms  → 950番目に遅いリクエストが500ms
# P99 = 2000ms → 990番目に遅いリクエストが2秒
# P99.9 = 10000ms → 999番目が10秒（99.9パーセンタイル）
 
# 平均 = 150ms でも、P99 = 10秒 なら
# 1000ユーザーに1人は10秒待たされている

# Gemfile
group :development do
  gem 'rack-mini-profiler', require: false
  gem 'flamegraph'   # フレームグラフ（どのメソッドが遅いか）
  gem 'stackprof'    # Ruby プロファイラ
  gem 'memory_profiler'  # メモリ使用量プロファイラ
end

bundle install

# config/initializers/rack_profiler.rb
if Rails.env.development?
  require 'rack-mini-profiler'
 
  Rack::MiniProfiler.config.tap do |config|
    config.storage = Rack::MiniProfiler::MemoryStore
    config.enabled = true
    config.show_sensitive_sql_warnings = true
    config.backtrace_includes = [/app\//]  # アプリコードのスタックトレースのみ
  end
end

# app/controllers/timeline_controller.rb
def index
  @users = User.limit(50)  # 1クエリ: SELECT * FROM users LIMIT 50
end

<%# app/views/timeline/index.html.erb %>
<% @users.each do |user| %>
  <div class="user-card">
    <%= user.username %>
    <% user.posts.each do |post| %>  <%# N クエリ: ユーザーごとにSELECT %>
      <div class="post"><%= post.content %></div>
    <% end %>
    <% user.followers.count %>人のフォロワー  <%# さらに N クエリ！ %>
  </div>
<% end %>

-- 発行されるSQL（50ユーザーの場合）
SELECT * FROM users LIMIT 50;              -- 1クエリ
SELECT * FROM posts WHERE user_id = 1;    -- +1クエリ
SELECT COUNT(*) FROM follows WHERE followee_id = 1;  -- +1クエリ
SELECT * FROM posts WHERE user_id = 2;    -- +1クエリ
SELECT COUNT(*) FROM follows WHERE followee_id = 2;  -- +1クエリ
-- ... 合計101クエリ（1 + N×2）
-- 50ユーザー × 2種類のクエリ = 100 + 1 = 101クエリ！

# app/controllers/timeline_controller.rb
def index
  @users = User.includes(:posts, :followers).limit(50)
  # includes は N+1 を解消する魔法ではなく、
  # 必要なデータを先読み（eager load）する
end

-- 発行されるSQL（修正後）
SELECT * FROM users LIMIT 50;
-- users id: (1, 2, 3, ..., 50) を覚えておく
 
SELECT * FROM posts WHERE user_id IN (1, 2, 3, ..., 50);
-- 1クエリで全ユーザーの投稿を取得
 
SELECT follows.*, users.*
FROM follows
INNER JOIN users ON follows.follower_id = users.id
WHERE follows.followee_id IN (1, 2, 3, ..., 50);
-- 1クエリで全ユーザーのフォロワーを取得
 
-- 合計3クエリ！（101 → 3）

# includes の使い分け
 
# includes（preload相当）: レコードをRubyオブジェクトとして読み込む
User.includes(:posts)
# SELECT * FROM users
# SELECT * FROM posts WHERE user_id IN (...)
# → posts にアクセスするとき、既にメモリ上にある
 
# joins: SQLのJOINを発行する（WHERE条件やORDERに使う）
User.joins(:posts).where(posts: { published: true })
# SELECT users.* FROM users
# INNER JOIN posts ON posts.user_id = users.id
# WHERE posts.published = true
# → Rubyオブジェクトとして posts は読み込まない
 
# eager_load: LEFT OUTER JOIN + includes の挙動
User.eager_load(:posts)
# SELECT users.*, posts.*
# FROM users LEFT OUTER JOIN posts ON posts.user_id = users.id
# → 1回のSQLで全部取得（N+1解消 + WHERE句でfilterも可能）

# Gemfile
group :development do
  gem 'bullet'
end

# config/environments/development.rb
Rails.application.configure do
  config.after_initialize do
    Bullet.enable = true
    Bullet.alert = true           # ブラウザアラートで通知
    Bullet.rails_logger = true    # Railsログに出力
    Bullet.add_footer = true      # ページ下部に表示
    Bullet.counter_cache_enable = true  # カウンターキャッシュの提案
 
    # Slack通知（チーム全員に周知）
    Bullet.slack = {
      webhook_url: ENV['SLACK_WEBHOOK_URL'],
      channel: '#performance-alerts',
      username: 'Bullet Bot'
    }
  end
end

-- postgresql.conf または AWS RDS パラメータグループ
log_min_duration_statement = 100   -- 100ms以上のクエリをログ
log_statement = 'none'             -- 全クエリはログしない（重い）
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h '

# AWS RDS のパラメータグループ設定（AWS CLI）
aws rds modify-db-parameter-group \
  --db-parameter-group-name buzz-pg-params \
  --parameters "ParameterName=log_min_duration_statement,ParameterValue=100,ApplyMethod=immediate"

# Railsコンソールで実行（問題クエリの調査）
result = ActiveRecord::Base.connection.execute(
  "EXPLAIN ANALYZE
   SELECT * FROM posts
   WHERE content LIKE '%Ruby%'
   ORDER BY created_at DESC
   LIMIT 20"
)
puts result.map { |row| row['QUERY PLAN'] }.join("\n")

-- 出力例（問題のあるクエリ）
Seq Scan on posts  (cost=0.00..45234.00 rows=150 width=1024)
                   (actual time=0.045..8934.233 rows=150 loops=1)
  Filter: ((content)::text ~~ '%Ruby%'::text)
  Rows Removed by Filter: 2250000
Planning Time: 1.2 ms
Execution Time: 8934.8 ms  ← 8秒！
 
-- Seq Scan = 225万行を全件スキャン
-- これがインデックスを使えない LIKE '%keyword%' の問題

# より便利な方法: Active Record でEXPLAIN
Post.where("content LIKE ?", "%Ruby%").order(created_at: :desc).limit(20).explain
# => ActiveRecord::Explain オブジェクト
 
# もっと詳しく（ANALYZE付き）
Post.where("content LIKE ?", "%Ruby%").explain(analyze: true)

-- 良いEXPLAIN出力の例
Index Scan using idx_posts_user_created on posts
  (cost=0.43..8.45 rows=1 width=512)
  (actual time=0.082..0.089 rows=1 loops=1)
  Index Cond: ((user_id = 123) AND (created_at > '2024-01-01'))
Heap Fetches: 1
Planning Time: 0.234 ms
Execution Time: 0.123 ms  ← 速い！
 
-- 悪いEXPLAIN出力の例（ボトルネックのサイン）
Seq Scan on posts
  (actual time=0.012..8901.234 rows=18234 loops=1)
  Rows Removed by Filter: 2250000  ← 225万行スキャン
Execution Time: 8934.8 ms  ← 遅い！

# Rails の queryスタック調査ヘルパー
# config/initializers/query_logger.rb
if Rails.env.development?
  ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
    event = ActiveSupport::Notifications::Event.new(*args)
    if event.duration > 100  # 100ms以上
      puts "  [SLOW] #{event.duration.round}ms: #{event.payload[:sql]}"
      puts "  Caller: #{caller.grep(/app\//).first(3).join(', ')}"
    end
  end
end

# Gemfile
gem 'newrelic_rpm'
# または
gem 'ddtrace', require: 'datadog/auto_instrument'

# config/newrelic.yml
production:
  license_key: <%= ENV['NEW_RELIC_LICENSE_KEY'] %>
  app_name: Buzz Production
 
  transaction_tracer:
    enabled: true
    transaction_threshold: 0.5  # 0.5秒以上のリクエストを記録
    record_sql: obfuscated       # SQLをログに残す（マスキングあり）
    stack_trace_threshold: 0.5
 
  error_collector:
    enabled: true
    capture_params: false  # プライバシー保護のためパラメータは記録しない
 
  # スロートランザクションのトレース
  slow_sql:
    enabled: true
    explain_threshold: 0.5  # 0.5秒以上のSQLを EXPLAIN で記録
    explain_enabled: true
    record_sql: obfuscated

# CloudWatch アラーム設定（Terraform）
resource "aws_cloudwatch_metric_alarm" "response_time_p99" {
  alarm_name          = "buzz-p99-response-time"
  comparison_operator = "GreaterThanThreshold"
  evaluation_periods  = "5"
  metric_name         = "TargetResponseTime"
  namespace           = "AWS/ApplicationELB"
  period              = "60"
  statistic           = "p99"
  threshold           = "1"  # 1秒
  alarm_description   = "P99レスポンスタイムが1秒を超えました"
  alarm_actions       = [aws_sns_topic.alerts.arn]
 
  dimensions = {
    LoadBalancer = aws_alb.buzz.arn_suffix
  }
}
 
resource "aws_cloudwatch_metric_alarm" "error_rate" {
  alarm_name          = "buzz-5xx-error-rate"
  comparison_operator = "GreaterThanThreshold"
  evaluation_periods  = "3"
  metric_name         = "HTTPCode_Target_5XX_Count"
  namespace           = "AWS/ApplicationELB"
  period              = "60"
  statistic           = "Sum"
  threshold           = "10"  # 1分間に10件以上の5xxエラー
  alarm_actions       = [aws_sns_topic.alerts.arn]
}

# k6 のインストール
brew install k6

// buzz_load_test.js
import http from 'k6/http';
import { check, sleep, group } from 'k6';
import { Counter, Rate, Trend } from 'k6/metrics';
 
// カスタムメトリクス
const timelineErrors = new Counter('timeline_errors');
const timelineLatency = new Trend('timeline_latency');
const successRate = new Rate('success_rate');
 
export let options = {
  stages: [
    { duration: '1m',  target: 100  },  // 1分でユーザー100人まで増加（ウォームアップ）
    { duration: '3m',  target: 500  },  // 3分でユーザー500人まで増加
    { duration: '5m',  target: 1000 },  // 5分でユーザー1000人まで増加（ピーク）
    { duration: '2m',  target: 500  },  // 2分で縮小
    { duration: '1m',  target: 0    },  // 1分でゼロに
  ],
  thresholds: {
    http_req_duration: ['p(95)<2000', 'p(99)<5000'],  // SLO
    http_req_failed: ['rate<0.01'],  // エラー率1%未満
    success_rate: ['rate>0.99'],
  },
};
 
// テストシナリオ
export default function() {
  group('タイムライン', function() {
    const response = http.get('https://staging.buzz-app.com/timeline', {
      headers: { 'Authorization': `Bearer ${__ENV.TEST_TOKEN}` }
    });
 
    const success = check(response, {
      'ステータス200': (r) => r.status === 200,
      'レスポンス2秒以内': (r) => r.timings.duration < 2000,
      'Content-Type確認': (r) => r.headers['Content-Type'].includes('application/json'),
    });
 
    timelineLatency.add(response.timings.duration);
    successRate.add(success);
    if (!success) timelineErrors.add(1);
  });
 
  sleep(1);
}

k6 run buzz_load_test.js

# 開発環境でフレームグラフを生成
# ブラウザで /timeline?pp=flamegraph にアクセス
 
# または stackprof で直接プロファイリング
# config/initializers/profiling.rb（開発環境のみ）
if Rails.env.development?
  require 'stackprof'
end
 
# app/controllers/application_controller.rb
around_action :profile_action, if: -> { params[:pp] == 'stackprof' && Rails.env.development? }
 
def profile_action
  result = StackProf.run(mode: :wall, interval: 1000) { yield }
  report = StackProf::Report.new(result)
  report.print_text(false, 30)  # 上位30メソッドを出力
end

# メモリリークの調査
require 'memory_profiler'
 
report = MemoryProfiler.report do
  # 問題のあるコードを実行
  100.times { User.includes(:posts).limit(10).to_a }
end
 
report.pretty_print(
  to_file: '/tmp/memory_report.txt',
  scale_bytes: true,
  normalize_paths: true
)

# 今後のパフォーマンス監視を自動化する
# config/initializers/performance_monitoring.rb
if Rails.env.production?
  ActiveSupport::Notifications.subscribe('process_action.action_controller') do |*args|
    event = ActiveSupport::Notifications::Event.new(*args)
    payload = event.payload
 
    # 1秒以上かかったリクエストをログ
    if event.duration > 1000
      Rails.logger.warn({
        type: 'slow_request',
        controller: payload[:controller],
        action: payload[:action],
        duration_ms: event.duration.round,
        db_ms: payload[:db_runtime]&.round,
        view_ms: payload[:view_runtime]&.round,
        status: payload[:status]
      }.to_json)
    end
  end
end

# config/initializers/performance_budget.rb
PERFORMANCE_BUDGETS = {
  'timeline#index'   => 500,   # 500ms
  'posts#show'       => 200,   # 200ms
  'users#profile'    => 300,   # 300ms
  'search#index'     => 800,   # 800ms（検索は少し緩め）
}.freeze
 
if Rails.env.production?
  ActiveSupport::Notifications.subscribe('process_action.action_controller') do |*args|
    event = ActiveSupport::Notifications::Event.new(*args)
    payload = event.payload
    key = "#{payload[:controller]}##{payload[:action]}"
    budget = PERFORMANCE_BUDGETS[key]
 
    if budget && event.duration > budget
      ratio = (event.duration / budget).round(1)
      Rails.logger.error "[BUDGET EXCEEDED] #{key}: #{event.duration.round}ms (budget: #{budget}ms, #{ratio}x over)"
      # Datadog / New Relic にカスタムイベントを送る
    end
  end
end