问题描述

发现于一个专门提供 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 邮件：[email protected] 地址：杭州天目山路西溪印象城附近