Ruby 分享一次排查问题的过程

besfan · 2016年03月25日 · 最后由 ssybb1988 回复于 2016年03月27日 · 3253 次阅读

问题描述

发现于一个专门提供API的服务:优惠券服务,请求量比较低,吞吐量大概几十cpm,通过监控查看到会有极少量请求比较慢,响应时间在两三秒的样子,出现频率也不固定,间隔几分钟到几十分钟不等。这个API是返回用户所拥有优惠券的数量,就是一个简单的SQL count。监控上看到该API的一般响应时间大约几十毫秒,只是个别请求的响应时间比较长。

服务器概况

Nginx, Puma, Rails 4.2, Grape, PostgreSQL, Sidekiq, Redis

服务器、PostgreSQL和redis都用阿里云的服务。

定位问题的过程

1. 看监控
  • 问题代码定位

我们使用的是OneAPM作为监控的(OneAPM是不是应该给点广告费,哈哈哈)。 第一张图片可以看出数据库查询的时间是可以接受的,时间都耗在了Rack上。

详情中也没有显示具体的慢的位置,没有说明是哪个Rack,范围太大,没什么实际帮助。

当时有过怀疑,是不是OneAPM的监控不准呢?在Nginx日志中是可以显示出响应的处理时间,这个时间相对OneAPM来说要更准确。

经过确认,Nginx日志中响应时间在1-3秒的请求每天都会有几十个。(在Nginx的配置中为log_format增加$upstream_response_time或者$request_time,默认是没有这2个值的。)

  • 服务器负载分析

查看OneAPM以及阿里云上的资源监控,没有发现任何异常。请求响应迟钝的那段时间前后,也没有耗时较长或者有可能造成堵塞的其他异常请求。

2. 分析代码

接口的实现中只有3行代码,逻辑很简单, 生成ActiveRecord::Relation,单表count查询,grape中也没有去渲染其他数据,仅仅返回一个数量。

简单来说就执行了这2行,数据库索引也加了,即使不加索引也是没问题的,因为数据一开始是很少的。

coupons = Coupon.where(user_id: params[:user_id]) 
coupons.count

Puma的问题? Grape的问题? Rails? 数据库? 锁?…………

3. 是否慢在业务代码的范围内?

用了最笨的办法,在每一行前后打上日志,缩小范围。

结果:Rails默认的请求日志和手动添加的第一条日志,这2个日志的间隔时间比较长。 可以确认的是,已经执行到了Rails的代码中,和Puma的关系不大了。同样,也不是业务代码的原因。

I, [2016-01-29T15:51:50.013946 #17676]  INFO -- : Started GET "problem/api" for 100.97.90.88 at 2016-01-29 15:51:50 +0800
---------------这里耗时较长-----这一行是我手动写上去的--------------
I, [2016-01-29T15:51:51.129605 #17676]  INFO -- : params: #<Hashie::Mash user_id="123456">
4. 是否慢在了某个Middleware内?

已经打印了请求日志,但是还没有进入到接口代码中,是否因为某个middleware处理慢了导致的?只是猜测,来验证一下。middleware的相关介绍查看这里。在config/application.rb添加下面的代码:

config.after_initialize do
  Rails.configuration.middleware.middlewares.each do |middleware|
    middleware_klass = middleware.klass
    if middleware_klass.class === Class && middleware_klass.method_defined?(:call)
      middleware_klass.class_eval do
        alias :old_call :call

        def call env
          Rails.logger.info "-------#{self.class.name}"
          old_call(env)
        end
      end
    end
  end

在每一个middleware的call之前打印一行日志。日志是这样的:

I, [2016-01-29T15:51:50.013946 #17676]  INFO -- : Started GET "problem/api" for 100.97.90.88 at 2016-01-29 15:51:50 +0800
I, [2016-01-29T15:51:50.014022 #17676]  INFO -- : middleware call time at: 15:51:50.014001 -------ActionDispatch::ShowExceptions
I, [2016-01-29T15:51:50.014091 #17676]  INFO -- : middleware call time at: 15:51:50.014072 -------ActionDispatch::DebugExceptions
I, [2016-01-29T15:51:50.014139 #17676]  INFO -- : middleware call time at: 15:51:50.014122 -------ActionDispatch::RemoteIp
I, [2016-01-29T15:51:50.014192 #17676]  INFO -- : middleware call time at: 15:51:50.014174 -------ActionDispatch::Callbacks
I, [2016-01-29T15:51:50.014261 #17676]  INFO -- : middleware call time at: 15:51:50.014242 -------ActiveRecord::ConnectionAdapters::ConnectionManagement
I, [2016-01-29T15:51:50.014324 #17676]  INFO -- : middleware call time at: 15:51:50.014305 -------ActiveRecord::QueryCache
---------------这里耗时较长-----这一行是我手动写上去的--------------
I, [2016-01-29T15:51:51.127367 #17676]  INFO -- : middleware call time at: 15:51:51.127277 -------ActionDispatch::Cookies
I, [2016-01-29T15:51:51.127480 #17676]  INFO -- : middleware call time at: 15:51:51.127459 -------ActionDispatch::Session::CookieStore
I, [2016-01-29T15:51:51.127573 #17676]  INFO -- : middleware call time at: 15:51:51.127547 -------ActionDispatch::Flash
I, [2016-01-29T15:51:51.127624 #17676]  INFO -- : middleware call time at: 15:51:51.127606 -------ActionDispatch::ParamsParser
I, [2016-01-29T15:51:51.127688 #17676]  INFO -- : middleware call time at: 15:51:51.127669 -------Rack::Head
I, [2016-01-29T15:51:51.127740 #17676]  INFO -- : middleware call time at: 15:51:51.127719 -------Rack::ConditionalGet
I, [2016-01-29T15:51:51.127797 #17676]  INFO -- : middleware call time at: 15:51:51.127778 -------Rack::ETag
I, [2016-01-29T15:51:51.127865 #17676]  INFO -- : middleware call time at: 15:51:51.127827 -------OneApm::Rack::BrowserMonitoring
I, [2016-01-29T15:51:51.127994 #17676]  INFO -- : middleware call time at: 15:51:51.127975 -------OneApm::Rack::MiddlewareHooks
I, [2016-01-29T15:51:51.128953 #17676]  INFO -- : middleware call time at: 15:51:51.128891 -------Rack::Head
I, [2016-01-29T15:51:51.129605 #17676]  INFO -- : params: #<Hashie::Mash user_id="123456">

这样就可以计算出是每个middleware的处理时间。可以看出是ActiveRecord::QueryCache和ActionDispatch::Cookies之间的间隔时间有1秒多,而我是在每个middleware的开始打印的日志,因此可以确认问题是出在了 ActiveRecord::QueryCache 中。 ActiveRecord::QueryCache的作用是启用 Active Record 查询缓存,把每次查询的结果缓存起来,如果在同一次请求中遇到相同的查询,直接从缓存中读取结果,不用再次查询数据库。 因为服务器的负载很低,移除这个middleware的副作用比较小。

5. 移除 ActiveRecord::QueryCache

加入下面的代码:

# config/application.rb
config.middleware.delete "ActiveRecord::QueryCache"

接着去观察日志,然并卵,依然会有慢请求存在,数量也没有明显减少。好在相比之前有了变化,问题定位到了接口的代码中,慢在得到ActiveRecord::Relation,但还没执行count的时候。

coupons = Coupon.where(user_id: params[:user_id]) 

看一下ActiveRecord::QueryCache的实现

module ActiveRecord
  class QueryCache

    def call(env)
      connection    = ActiveRecord::Base.connection
      enabled       = connection.query_cache_enabled
      connection_id = ActiveRecord::Base.connection_id
      connection.enable_query_cache!

      response = @app.call(env)
      response[2] = Rack::BodyProxy.new(response[2]) do
        restore_query_cache_settings(connection_id, enabled)
      end

      response
    rescue Exception => e
      restore_query_cache_settings(connection_id, enabled)
      raise e
    end

  end
end

ActiveRecord::QueryCache和生成一个ActiveRecord::Relation共同点是什么? 应该是获取数据库连接。

6. 确认ActiveRecord::ConnectionAdapters::ConnectionPool#checkout的执行时间。

Check-out a database connection from the pool, indicating that you want to use it. You should call checkin when you no longer need this.

This is done by either returning and leasing existing connection, or by creating a new connection and leasing it.

在config/application.rb添加下面的代码:

config.after_initialize do
  module CheckoutLog
    def checkout
      Rails.logger.info '-------checkout start'
      super.tap do |_|
        Rails.logger.info '-------checkout end'
      end
    end
  end
  ActiveRecord::ConnectionAdapters::ConnectionPool.prepend(CheckoutLog)
end

在checkout执行前后打印日志,对于prepend的用法,参见理解 Ruby 中的 include 和 prepend 结果确实慢在了checkout中。 通过类似的方法,一步一步追踪过去,最终定位到了 @connection.query 'SELECT 1',通过执行一个最简单的SQL来确认数据库连接是否活跃。 下面是涉及到的方法,分布在多个类中。

def checkout
  synchronize do
    conn = acquire_connection
    conn.lease
    checkout_and_verify(conn)
  end
end

def checkout_and_verify(c)
  c._run_checkout_callbacks do
    c.verify!
  end
  c
rescue
  remove c
  c.disconnect!
  raise
end

def verify!(*ignored)
  reconnect! unless active?
end

# Is this connection alive and ready for queries?
def active?
  @connection.query 'SELECT 1'
  true
rescue PGError
  false
end
7. 脱离Rails框架,确认是否是数据库的原因

直接用pg的gem单独执行select 1

require 'pg'
conn = PG.connect( dbname: 'your_db_name',
                   host: 'your_db_host',
                   port: 5432,
                   user:'user_name',
                   password: 'your_password')
1000000.times.each_with_index do |a,index|
  start_t = Time.now
  conn.exec('select 1')
  end_t = Time.now
  tt = end_t-start_t
  puts("#{index}:  #{tt}") if tt>0.05
end

经过多次验证,100万次执行,会有几十次超过50毫秒,多次超过1秒。 结论已经很明显了,阿里云的PostgreSQL服务有问题。

8. 给阿里云提工单

经过漫长的问题排查及定位,给出的回复是:数据库中间件的任务调度模块有些不高效的地方,导致工作负荷高的时候产生较大延迟,正在解决中。

总结

出现问题不可怕,可怕的是不知道问题在哪里。 定位问题的基本思路就是不断 缩小排查范围。 每天都会出现几十次响应很慢的请求,对整个系统来说影响也不算很大,在生产服务器上打日志是一种笨办法,只能晚上发布,第二天观察结果,然后接着打日志,晚上发布……整个过程历时比较长。

🙏 招人 🙏

[杭州]大搜车诚招一名ruby工程师 详情见之前的招聘贴 这是新的办公环境

有意向的小伙伴可以联系我 微信: besfan 邮件: fanxiaopeng@souche.com 地址: 杭州天目山路西溪印象城附近

共收到 6 条回复

自顶向下, 逐步锁定的思路很赞~

不过回想起来, 如果在最开始就花十五分钟尝试一遍潜在的常见问题, 会省不少时间. 或许可以做个小工具, 依次检查:

  • DNS 解析
  • 简单数据查询: 包括 db, redis, memcache
  • 其他

大赞,感觉很有收获

其实这种时候还是很难受的。自己的代码查了好多天,结果发现是别人的锅……

#3楼 @msg7086 我觉得这个过程是值得的,收获颇多。

楼主思路很清楚啊,我看了也很有收获。

赞。 另外,#1楼 @42thcoder 这种偶发的问题即使做一个工具也很难定位到,可以优化的一些地方:

  1. OneAPM 的同学可以做的更好一些,这个既然是数据库上的问题,直接就应该显示出来数据库有问题。
  2. 我们自己的链路跟踪系统开发还是挺有必要的,一些需求 OneAPM 估计做到他们的通用系统里,例如单次请求的跟踪,资源视角的视图,与我们监控系统的集成等。 链路跟踪系统实现后,调试这种问题会很轻松。 3.@besfan 在解决这个问题中花了不少时间在打日志和取消日志上,日志做的规范一些的话可能会让这个问题好解决一些,例如外部请求,数据库长请求,缓存长请求等等。
需要 登录 后方可回复, 如果你还没有账号请点击这里 注册