rack-lineprof導入

[J-ogawa]

ソースコードベースで処理時間が可視化できる。
基本的にコメントアウトしておいて、ローカルで見るときだけONにする
https://github.com/J-ogawa/isucon/commit/bd3d7220239c4eed693d59b58176e0b591f2519f

出力例

[Rack::Lineprof] ===============================================================
app.rb
               |  22
               |  23        def db
   5.4ms  8310 |  24          Thread.current[:isu4_db] ||= Mysql2::Client.new(
               |  25            host: ENV['ISU4_DB_HOST'] || 'localhost',
               |  26            port: ENV['ISU4_DB_PORT'] ? ENV['ISU4_DB_PORT'].to_i : nil,
              .......
               |  104          threshold = config[:ip_ban_threshold]
               |  105
 221.0ms     2 |  106          not_succeeded = db.xquery('SELECT ip FROM (SELECT ip, MAX(succeeded) as max_succeeded, COUNT(1) as cnt FROM login_log GROUP BY ip) AS t0 WHERE t0.max_succeeded = 0 AND t0.cnt >= ?', threshold)
               |  107
               |  108          ips.concat not_succeeded.each.map { |r| r['ip'] }
               |  109
  76.3ms     2 |  110          last_succeeds = db.xquery('SELECT ip, MAX(id) AS last_login_id FROM login_log WHERE succeeded = 1 GROUP by ip')
               |  111
  68.3ms     1 |  112          last_succeeds.each do |row|
  66.7ms  1020 |  113            count = db.xquery('SELECT COUNT(1) AS cnt FROM login_log WHERE ip = ? AND ? < id', row['ip'], row['last_login_id']).first['cnt']
               |  114            if threshold <= count
               |  115              ips << row['ip']
              .......
               |  124          threshold = config[:user_lock_threshold]
               |  125
  61.7ms     2 |  126          not_succeeded = db.xquery('SELECT user_id, login FROM (SELECT user_id, login, MAX(succeeded) as max_succeeded, COUNT(1) as cnt FROM login_log GROUP BY user_id) AS t0 WHERE t0.user_id IS NOT NULL AND t0.max_succeeded = 0 AND t0.cnt >= ?', threshold)
               |  127
   1.6ms     3 |  128          user_ids.concat not_succeeded.each.map { |r| r['login'] }
               |  129
  54.6ms     2 |  130          last_succeeds = db.xquery('SELECT user_id, login, MAX(id) AS last_login_id FROM login_log WHERE user_id IS NOT NULL AND succeeded = 1 GROUP BY user_id')
               |  131
 19978.9ms     1 |  132          last_succeeds.each do |row|
 19935.9ms 15584 |  133            count = db.xquery('SELECT COUNT(1) AS cnt FROM login_log WHERE user_id = ? AND ? < id', row['user_id'], row['last_login_id']).first['cnt']
               |  134            if threshold <= count
               |  135              user_ids << row['login']
              .......
               |  174        content_type :json
               |  175        {
 365.7ms     1 |  176          banned_ips: banned_ips,
 20096.7ms     1 |  177          locked_users: locked_users,
   3.8ms  2509 |  178        }.to_json
               |  179      end
               |  180    end
127.0.0.1 - - [15/Oct/2017 17:28:55] "GET /report HTTP/1.1" 200 31449 20.4711