ruby-on-rails - Ruby on Rails - 加载缓慢并在垃圾收集器中花费大量时间

Question

我有一个大型 Rails 应用程序，我希望提高(糟糕的)性能。

使用 ruby​​-prof 运行对我帮助不大，我得到了类似这样的输出(在瘦生产模式下运行):

Thread ID: 9322800
Total: 1.607768
Sort by: self_time

 %self     total     self     wait    child    calls   name
 26.03      0.42     0.42     0.00     0.00     1657   Module#define_method 
  8.03      0.13     0.13     0.00     0.00      267   Set#initialize 
  4.41      0.07     0.07     0.00     0.00       44   PG::Result#values 
  4.28      0.07     0.07     0.00     0.00     1926   ActiveSupport::Callbacks::Callback#start 
  4.21      0.07     0.07     0.00     0.00    14835   Kernel#hash 
  4.13      0.08     0.07     0.00     0.01      469   Module#redefine_method 
  4.11      0.07     0.07     0.00     0.00       63  *<Class::ActiveRecord::Base>#with_scope 
  4.02      0.07     0.06     0.00     0.00      774   ActiveSupport::Callbacks::Callback#_compile_options 
  3.24      0.05     0.05     0.00     0.00       30   PG::Connection#async_exec 
  2.31      0.40     0.04     0.00     0.37     2130  *Module#class_eval 
  1.47      0.02     0.02     0.00     0.00        6   PG::Connection#unescape_bytea 
  1.03      0.05     0.02     0.00     0.03      390  *Array#select 

* indicates recursively called methods

我猜它可能在垃圾收集器上花费了很多时间，所以因为我在 REE 上运行我决定尝试使用 GC.enable_stats 来获取更多信息。我将以下内容添加到我的应用程序 Controller 中:

around_filter :enable_gc_stats

private

def enable_gc_stats
  GC.enable_stats

  begin
    yield
  ensure
    GC.disable_stats
    GC.clear_stats
  end
end

在我的机器上以生产模式运行的相对较大的页面上，使用 REE 和瘦网络服务器(ruby-prof 被禁用，因为它使它有点慢)我得到:

Completed 200 OK in 1093ms (Views: 743.1ms | ActiveRecord: 139.2ms)

GC.collections: 11
GC.time: 666299 us 666.299 ms
GC.growth: 461 KB

GC.allocated_size: 152 MB
GC.num_allocations: 1,924,773
ObjectSpace.live_objects: 1,015,195
ObjectSpace.allocated_objects: 12,393,644

因此对于一个耗时 1093 毫秒的页面，垃圾收集器似乎花费了将近 700 毫秒。以前有人遇到过这种问题吗？我知道你无法帮助我的应用程序(它非常大，有很多 gem 和东西) - 但是否有技术或工具可以更好地了解为什么会产生这么多垃圾？

任何想法将不胜感激!

Answer 1

您的 Rails 日志显示大部分时间 (75%) 花在查看代码上。

您的配置文件报告显示了三个明显的热点:Module#define_method 用于自身时间，Module#class_eval 用于总时间，以及 Set#initialize .

define_method 和 class_eval 表明可能有很多动态代码执行，这对我来说似乎过分了——通常你想尽早生成代码并重用它而不是重复使用重新生成它。这几乎可以肯定是您过多的对象分配问题的一部分。生成图表报告而不是平面报告应该可以帮助您找到落入这些昂贵路径的父方法，并且可以为您指明可以优化的地方。

Set#initialize 可能是您的代码需要执行的操作的真实产物，或者它可能表明存在一些重要的 Set[...] 或Set::new 设置内联创建调用，这可以完成一次并分配给常量或实例/类 var 以供重用。

ruby-prof 没问题，但您可能还想试试 perftools.rb使用 rack-perftools_profiler 很容易连接到机架 rails . perftools 有一些增强的可视化工具，可以更容易地理解热执行路径。

由于您正在运行 REE 并且广泛的对象分配(以及垃圾收集)是一个问题，您可以尝试 memprof深入了解所有这些分配的来源和来源。

如果找不到减少分配对象数量的方法，可以通过 tuning the GC 以更大的进程内存大小为代价来减轻 GC 负担。预分配一个足够大的堆来满足典型请求的分配需求。 Unicorn 为 out of band GC 提供机架模块.您可能能够调整此模块的方法来处理精简并将所有 GC 时间移至请求之间——您仍将支付 CPU 成本，但至少您不会延迟对垃圾收集的响应。