由于 Ruby China 的代码起得比较老,最早应该是 4 年前了,所以 Gemfile 里面有一些 Gem 的版本都很老。
今天新改了一个功能,大概是用 Rails.cache.read_multi
方法批量获得用户对一批 Topic 的阅读状态。
这个功能之前是循环的时候依此调用 topic_read? 方法来检测状态的。
后面我改成了这样,也就是利用 Memcached get multi 的方法一次获取,减少网络连接次数。
def filter_readed_topics(topics)
t1 = Time.now
key_hashs = {}
return [] if topics.blank?
cache_keys = topics.map { |t| "user:#{self.id}:topic_read:#{t.id}" }
results = Rails.cache.read_multi(*cache_keys)
ids = []
topics.each do |topic|
val = results["user:#{self.id}:topic_read:#{topic.id}"]
if (val == (topic.last_reply_id || -1))
ids << topic.id
end
end
t2 = Time.now
logger.error "filter_readed_topics (#{(t2 - t1) * 1000}ms)"
ids
end
理论上来说,这样的修改是有助于提升效率的,同时在开发环境下面看 Rails log 的时间比较正常,于是我就发布了。
然后,到了线上,我发现我登录状态下,话题列表的响应时间要 200ms 以上(之前是 150ms 左右,并且这次我还有改进 View 的 Partial 缓存的,理论上来说应该在 100ms 左右的)
于是我又在开发环境给 filter_readed_topics
方法加上时间统计,结果 1ms 看起来还是没问题,而线上统计出来是 40ms。
好奇怪...数据库也导到本地测试,还是依然很快的...
又尝试在线上把时间统计缩短到 Rails.cache.read_multi
这段,结果打印出来一看,我靠,就是这里的问题。
难道是 read_multi 的 Bug?
搜索了一下 Dalli read_multi slow 第一条结果指向 Dalli Issue 里面,3 年前的东西,再看我们的 Gemfile,额 gem 'dalli', '1.1.1'
,看来就是你的问题啦!
于是升级到最新版本,发布重启(这里顺便发现,改了 Gemfile 里 Gem 的版本,Puma 得 stop 再 start 才能生效)
再看日志里面 filter_readed_topics
的统计时间,降到了 4ms 这回正常了!