最近在琢磨上点手段来对 Rails 的日志进行处理，之前一直是 tail/grep 直接去服务端看 production.log，但是当请求密集的时候各个请求的记录混杂在一起，根本分不清。于是开始调研日志处理方案。

着重看了下 fluentd 的方案，我想开始就简单点（我也不想部署额外的视图应用）直接把日志打到 Postgres 里得了，反正用 hotwired 撸几个视图查看日志也是分分钟的事儿。

Fluentd 的方案是 tail 读取日志，然后通过正则处理，转化为 json , 然后批量写入 postgres。emm..... 之所以性能比常规好一些，主要就是批量写入 PG 的这块特别优化了下。那我直接把 Rails 日志以 JSON (hash) 直接批量写入 PG 性能不更好？于是开始实操，直接上干货。

# 拿到请求的详细信息
module RailsCom::ActionController
  class EventSubscriber < ActiveSupport::StructuredEventSubscriber
    attach_to :action_controller

    def start_processing(event)
    end

    def process_action(event)
      payload = event.payload
      request = payload[:request]
      raw_headers = payload.fetch(:headers, {})
      real_headers = Com::Err.request_headers(raw_headers)

      emit_event(
        'controller.process_action',
        path: request.fullpath,
        controller_name: payload[:controller],
        action_name: payload[:action],
        params: payload[:params].to_json,
        headers: real_headers.to_json,
        session: request.session.to_h.to_json,
        format: payload[:format].to_s,
        ip: request.remote_ip,
        session_id: request.session.id,
        created_at: Time.now.iso8601(6),
        uuid: request.request_id
      )
    end

  end
end

# 收集日志，每5秒钟批量写入 PG 
class EventJsonSubscriber
  COLUMNS = [
    :uuid, :path, :controller_name, :action_name, :params, :headers, :session, :ip, :format, :session_id, :created_at
  ]

  def initialize
    @queue = Concurrent::Array.new
    @coder = PG::TextEncoder::CopyRow.new
    Concurrent::TimerTask.execute(execution_interval: 5) { flush! }
  end

  def emit(event)
    payload = event[:payload]

    @queue << payload.values_at(*COLUMNS)
  end

  private
  def flush!
    return if @queue.empty?
    buf = @queue.shift(@queue.size)
    uuid = SecureRandom.uuid

    conn = ActiveRecord::Base.connection.raw_connection
    conn.copy_data "COPY com_logs(#{COLUMNS.join(', ')}, commit_uuid) FROM STDIN" do
      buf.each do |item|
        conn.put_copy_data item << uuid, @coder
      end
    end
  end
end

# 在 puma.rb 中注册下订阅
before_worker_boot do
  subscriber = EventJsonSubscriber.new
  Rails.event.subscribe(subscriber) do |event|
    event[:name].start_with?('controller.')
  end
end

可以工作了，看着 com_logs 表里源源不断涌入的完整日志，惊喜又激动！接下来看看对性能的损耗，直接上压测：

关闭日志入库

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.73s   273.31ms   2.00s    93.32%
    Req/Sec    25.73     20.11   180.00     74.08%
  6389 requests in 30.05s, 39.92MB read
  Socket errors: connect 0, read 0, write 0, timeout 1228
Requests/sec:    212.60
Transfer/sec:      1.33MB

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.72s   280.64ms   2.00s    93.03%
    Req/Sec    26.61     23.25   230.00     74.67%
  6343 requests in 30.05s, 39.64MB read
  Socket errors: connect 0, read 0, write 0, timeout 1379
Requests/sec:    211.09
Transfer/sec:      1.32MB

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.69s   280.33ms   2.00s    91.89%
    Req/Sec    23.69     17.48   130.00     77.07%
  6440 requests in 30.05s, 40.24MB read
  Socket errors: connect 0, read 0, write 0, timeout 1112
Requests/sec:    214.34
Transfer/sec:      1.34MB

连续跑了 3 次，平均每秒请求 212 个

开启日志入库

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.75s   295.19ms   2.00s    92.88%
    Req/Sec    26.87     22.48   210.00     74.11%
  6198 requests in 30.04s, 38.73MB read
  Socket errors: connect 0, read 0, write 0, timeout 1535
Requests/sec:    206.29
Transfer/sec:      1.29MB

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.75s   289.59ms   2.00s    92.94%
    Req/Sec    30.00     25.83   141.00     74.47%
  6277 requests in 30.06s, 39.22MB read
  Socket errors: connect 0, read 0, write 0, timeout 1458
Requests/sec:    208.84
Transfer/sec:      1.31MB

Running 30s test @ http://localhost:3000
  12 threads and 400 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency     1.76s   293.76ms   2.00s    92.86%
    Req/Sec    27.49     22.41   151.00     70.22%
  6228 requests in 30.05s, 38.90MB read
  Socket errors: connect 0, read 0, write 0, timeout 1313
Requests/sec:    207.23
Transfer/sec:      1.29MB

连续跑了 3 次，平均每秒请求是 207，比开启前少了 5，可以忽略不计吧！ APM 平台的探针应该对性能损耗比这大不少吧，有经验的大佬们可以分享下。

后续

接下来就是撸几个视图在后台看看日志了，相对于把日志打到 外部的平台，在 Rails 应用内分析日志还有更多的收获，比如：

• 可以直接把请求和具体的用户关联起来，直接分析用户的行为；
• 可以更灵活，之前用 Newrelic 的时候，url 中含有中文的乱码都不给处理（也许外国人对看非英文没有需求吧），自己的应用我自己转；
• 可统计的数据维度可以极为丰富，比如所有的 sql, 所有的 render , 每个请求的 gc 对象数，想怎么加指标就怎么加；