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 来获取更多信息。我将以下内容添加到我的应用程序控制器中：

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 毫秒。以前有人遇到过这种问题吗？我意识到你无法帮助我的应用程序（它非常大，有很多宝石和东西） - 但是有没有技术或工具可以更好地了解为什么会产生这么多垃圾？

任何想法将不胜感激！

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连接到机架导轨。perftools 有一些增强的可视化工具，可以更容易地理解热执行路径。

由于您正在运行 REE 并且大量对象分配（因此垃圾收集）是一个问题，您可以尝试使用memprof来深入了解所有这些分配的来源和来源。

如果您找不到减少分配对象数量的方法，您可以通过调整 GC以预分配一个足够大的堆来容纳典型请求的分配需求，从而以更大的进程内存大小为代价来减轻 GC 负担。Unicorn 为带外 GC提供了一个机架模块。您可能能够调整此模块的方法来使用 Thin 并将所有 GC 时间移到请求之间——您仍然需要支付 CPU 成本，但至少您不会延迟对垃圾收集的响应。