performance - 旧版 Rails 应用程序升级到 6.0.4 导致响应速度大幅下降

问题描述

我正在努力将我们的旧 Rails 应用程序升级到 6.0.4，我们的运行状况检查端点以 1-2 秒的实时响应响应（目前为 20-30 MS），但我们的 Rails 日志显示响应2-3 毫秒。卷曲我们的健康检查端点的本地结果：

➜  git:(rails/upgrade-to-6) ✗ time curl app.local/health_check
{"version":"release-30-241-g9dc39fcc2f::20210617174031"}curl app.local/health_check  0.01s user 0.00s system 0% cpu 3.798 total
➜  git:(rails/upgrade-to-6) ✗ time curl app.local/health_check
{"version":"release-30-241-g9dc39fcc2f::20210617174031"}curl app.local/health_check  0.01s user 0.00s system 1% cpu 0.931 total
➜  git:(rails/upgrade-to-6) ✗ time curl app.local/health_check
{"version":"release-30-241-g9dc39fcc2f::20210617174031"}curl app.local/health_check  0.00s user 0.00s system 1% cpu 0.969 total

由于开发加载代码，第一个请求很慢，但后续请求仍然是大约 1 秒实时。

这些请求的 rails 日志：

Started GET "/health_check" for 127.0.0.1 at 2021-07-27 14:43:49 -0400
Creating scope :closed. Overwriting existing method ServiceRequest.closed.
DEPRECATION WARNING: Controller-level `force_ssl` is deprecated and will be removed from Rails 6.1. Please enable `config.force_ssl` in your environment configuration to enable the ActionDispatch::SSL middleware to more fully enforce that your application communicate over HTTPS. If needed, you can use `config.ssl_options` to exempt matching endpoints from being redirected to HTTPS. (called from <class:ApplicationController> at /home/jimmy/Work/project/app/controllers/application_controller.rb:6)
Processing by HealthCheckController#index as */*
Completed 200 OK in 2ms (Views: 0.2ms | ActiveRecord: 0.0ms | Allocations: 1562)


Started GET "/health_check" for 127.0.0.1 at 2021-07-27 14:43:54 -0400
Processing by HealthCheckController#index as */*
Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 0.0ms | Allocations: 3649)


Started GET "/health_check" for 127.0.0.1 at 2021-07-27 14:43:56 -0400
Processing by HealthCheckController#index as */*
Completed 200 OK in 3ms (Views: 0.1ms | ActiveRecord: 0.0ms | Allocations: 3649)

有问题的控制器非常简单，因为它可以作为我们负载均衡器的健康检查

class HealthCheckController < ActionController::Base
  def index
    app_version = App::VERSION
    db_version = ActiveRecord::Migrator.current_version
    render json: { version: "#{app_version}::#{db_version}" }
  end
end

即使用硬编码的整数替换app_version和db_version代码块，我仍然看到相同程度的缓慢。

在使用中间件运行 stackprof 一段时间后，结果并不疯狂（至少我可以说）

==================================
  Mode: cpu(1000)
  Samples: 1404 (0.99% miss rate)
  GC: 134 (9.54%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
        99   (7.1%)          99   (7.1%)     (marking)
        73   (5.2%)          73   (5.2%)     ActiveModel::AttributeMethods#respond_to?
       108   (7.7%)          64   (4.6%)     Hash#deep_dup
       400  (28.5%)          60   (4.3%)     ActiveRecord::Base#perform_attribute_assignment
       869  (61.9%)          55   (3.9%)     ActiveRecord::Core#initialize
       152  (10.8%)          55   (3.9%)     ActiveRecord::AttributeMethods::Read#_read_attribute
        53   (3.8%)          53   (3.8%)     ActiveModel::AttributeSet#[]
        42   (3.0%)          42   (3.0%)     ActiveSupport::PerThreadRegistry#instance
        39   (2.8%)          39   (2.8%)     Grape::Router#compile!
        82   (5.8%)          37   (2.6%)     ActiveRecord::DynamicMatchers#respond_to_missing?
        36   (2.6%)          36   (2.6%)     ActiveModel::Attribute#initialize
        35   (2.5%)          35   (2.5%)     (sweeping)
       278  (19.8%)          35   (2.5%)     ActiveRecord::AttributeAssignment#_assign_attributes
        33   (2.4%)          33   (2.4%)     ActiveModel::Attribute#initialize_dup
        29   (2.1%)          29   (2.1%)     ActiveRecord::Core#initialize_internals_callback
        52   (3.7%)          28   (2.0%)     ActionDispatch::Journey::GTG::Builder#transition_table
       240  (17.1%)          27   (1.9%)     ActiveModel::AttributeAssignment#_assign_attribute
       117   (8.3%)          27   (1.9%)     ActiveRecord::AttributeMethods::Write#_write_attribute
        27   (1.9%)          27   (1.9%)     ActiveRecord::DynamicMatchers::Method.pattern
        26   (1.9%)          26   (1.9%)     Hash#stringify_keys
        25   (1.8%)          25   (1.8%)     ActiveModel::Type::Value#assert_valid_value
        36   (2.6%)          24   (1.7%)     ActiveRecord::Core#init_internals
        24   (1.7%)          24   (1.7%)     ActiveModel::Type::String#cast_value
        40   (2.8%)          22   (1.6%)     ActiveRecord::Scoping::ScopeRegistry#value_for
        24   (1.7%)          18   (1.3%)     block (2 levels) in class_attribute
        45   (3.2%)          18   (1.3%)     ActiveRecord::DynamicMatchers::Method.match
        42   (3.0%)          18   (1.3%)     ActiveModel::Type::Value#cast
        16   (1.1%)          16   (1.1%)     ActiveRecord::ModelSchema::ClassMethods#schema_loaded?
        16   (1.1%)          16   (1.1%)     AttrEncrypted#encrypted_attributes
        59   (4.2%)          16   (1.1%)     ActiveModel::Attribute#value

我注意到的一件事是，与我们的非升级环境相比，我们使用 rails 6.0.4 版本的预生产环境看到 CPU 利用率出现峰值。

就应用程序的正常使用而言，一切似乎都运行良好，只是速度很慢，以至于我们的负载均衡器正在从轮换中删除应用程序服务器。

我们在生产和本地开发中使用独角兽，独角兽的 procfile 条目：

web: bundle exec unicorn -p $PORT -c ./config/unicorn.rb

和配置文件：

worker_processes Integer(ENV["WEB_CONCURRENCY"] || 4)
timeout 60
preload_app true

before_fork do |server, worker|
  Signal.trap 'TERM' do
    puts 'Unicorn master intercepting TERM and sending myself QUIT instead'
    Process.kill 'QUIT', Process.pid
  end

  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.connection.disconnect!
  end

  if defined?($nats_client)
    $nats_client.close
  end
end

after_fork do |server, worker|
  Signal.trap 'TERM' do
    puts 'Unicorn worker intercepting TERM and doing nothing. Wait for master to send QUIT'
  end

  if defined?(ActiveRecord::Base)
    config = Rails.application.config.database_configuration[Rails.env]
    config['adapter'] = 'postgis'
    ActiveRecord::Base.establish_connection(config)
  end
end

我想知道是否有人见过类似的东西或有任何我应该调查的线索。

谢谢！

标签： performanceruby-on-rails-6

performance - 旧版 Rails 应用程序升级到 6.0.4 导致响应速度大幅下降

问题描述

解决方案

推荐阅读