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 和瘦 Web 服务器（禁用 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 以深入了解所有这些分配的来源和来源。

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