Tracking SQL queries in Rails

Trong quá trình phát triển, và đặc biệt là giai đoạn tối ưu của một app Rails, một trong những vấn đề được quan tâm nhất là về các SQL query. Bất cứ ai cũng từng đặt ra các câu hỏi như:

• Để thực hiện một request này cần bao nhiêu query?
• Để chạy hết số query đấy mất bao lâu?
• SQL query nào là chạy tốn thời gian nhất?
• Trong request có query nào bị gọi trùng không?
• SQL query nào được gọi đến nhiều nhất?

và nhiều câu hỏi tương tự nữa. Bình thường, ta hoàn toàn có thể check được bằng việc đọc log server, nhưng nếu muốn phân tích chi tiết và đầy đủ một request hoặc một nhóm các request cùng lúc, việc lọc ra các thông tin cần thiết từ log server là một việc hết sức khó khăn.

Một tool thường được sử dụng trong trường hợp này là gem rack-mini-profiler, nhưng gem này cũng rất khó sử dụng vì không có sẵn các giao diện người dùng (HTML, json, ajax…) để có thể xem xét một cách trực quan hoặc để so sánh các dữ liệu với nhau.

Để trả lời một vài câu hỏi trên, ta có thể sử dụng gem sql_tracker. Bài này sẽ nói về cách mà sql_tracker làm việc, các chức năng của gem có thể giúp trong việc tìm kiếm và phân tích các SQL query.

Cài đặt

Cũng như việc cài đặt các gem khác, ta thêm vào Gemfile:

group :development, :test do
  ... ...
  gem 'sql_tracker'
end

và chạy trên console:

bundle install

Tracking

Về cơ bản, sql_tracker sử dụng instrumentation API để tracking các SQL query được gọi từ Active Record, bằng cách đăng ký với sql.active_record hook:

ActiveSupport::Notifications.subscribe('sql.active_record') do |_name, _start, _finish, _id, payload|
 sql_query = payload[:sql]
end

Ngoài việc sử dụng block, ta có thể sử dụng một instance object, và gọi bằng method:

class Handler
  def call(_name, _start, _finish, _id, payload)
    sql_query = payload[:sql]
  end
end

ActiveSupport::Notifications.subscribe('sql.active_record', Handler.new)

sql_tracker sẽ được khởi tạo và bắt đầu chạy mỗi khi một Rails process được khởi động, và dừng lại khi process bị kill.

Filtering

Công cụ này sẽ không có ý nghĩa gì nếu ta phải đọc tất cả các query. Thường thì ta chỉ muốn kiểm tra các query thuộc một kiểu nhất định, hoặc được gọi từ một nhóm các request nhất định.

Ở chế độ mặc định, sql_tracker sẽ theo dõi và ghi lại tất các các query thuộc 4 nhóm (SELECT, INSERT, UPDATE, DELETE), nhưng ta có thể chỉnh sửa lại bằng một lệnh setting đơn giản:

SqlTracker::Config.tracked_sql_command = %w(SELECT)

Giống như mysql, các lệnh này không phân biệt chữ hoa, nên ta có thể nhập %w(select) nếu muốn mà không thay đổi kết quả.

Ta cũng có thể thay đổi thư mục theo dõi, bằng cách setting tracked_paths:

SqlTracker::Config.tracked_paths = %w(app/controllers/api)

Nếu không thay đổi, sql_tracker chỉ theo dõi thư mục app và lib của dự án và bỏ qua tất cả các query không liên quan ví dụ như từ thư mục test.

sql_tracker sử dụng phương thức gọi của Ruby cùng với backtrace_cleaner của Rails để có thể filter theo path. Phương thức gọi sẽ trả về một dãy các stack đang được thực thi, sau đó backtrace_cleaner dọn dẹp các thông tin lấy được từ stack bằng regex. Code đơn giản của quá trình này có dạng như sau:

Rails.backtrace_cleaner.add_silencer do |line|
  line !~ %r{^(#{tracked_paths.join('|')})/}
end

cleaned_trace = Rails.backtrace_cleaner.clean(caller)

# if cleaned_trace is empty, then the caller of this query is not included in tracked_paths
return false if cleaned_trace.empty?

Grouping

sql_tracker có thể tự động chuẩn hóa và nhóm các query tương tự nhau bằng cách thay một giá trị nhất định bằng chuỗi xxx. Ví dụ, với một request gọi đến SQL query:

SELECT users.* FROM users WHERE users.id = 1;

Và một query khác:

SELECT users.* FROM users WHERE users.id = 2;

sql_tracker sẽ nhóm các query này lại thành một:

SELECT users.* FROM users WHERE users.id = xxx;

Sâu hơn nữa, ta có thể sử dụng các regex tự đặt để nhóm các query. Ví dụ, ta có thể yêu cầu tìm kiếm và thay thế các giá trị sau các phép so sánh như =, <>, >, < hoặc ở trong cụm BETWEEN … AND, …

Sau khi nhóm các query, việc phân tích, tổng hợp, tính toán các query sẽ trở nên dễ dàng hơn.

Storing

sql_tracker sẽ lưu trữ tất cả dữ liệu tracking vào bộ nhớ, và xuất data ra dưới dạng file JSON mỗi khi process Rails kết thúc. Để tiện cho việc này, tất cả dữ liệu sẽ được tạo và lưu trong Rails process dưới dạng Hash có cấu trúc giống như:

{
  key1: {
    sql: 'SELECT users.* FROM users ...',
    count: 1,
    duration: 0.34,
    source: ['apps/model/user.rb:57:in ...', ...]
  },
  key2: { ... },
  ... ...
}

trong đó các key là mã hóa MD5 của các SQL query đã được chuẩn hóa, và value là các câu query đầy đủ và một vài thông số liên quan.

Ở chế độ mặc định, file xuất ra sẽ được lưu ở thư mục tmp trong thư mục dự án, nhưng ta có thể thay đổi ở config:

SqlTracker::Config.output_path = File.join(Rails.root.to_s, 'my_folder')

Nếu sử dụng một app server như puma, và đặt nhiều hơn một worker chạy song song, có thể có nhiều file JSON được xuất ra cùng lúc, vì mỗi worker thực hiện tracking và lưu trữ dữ liệu riêng biệt.

Reporting

Cuối cùng, ta có thể sinh ra một file report từ một hoặc nhiều file JSON:

sql_tracker tmp/sql_tracker-*.json

Report sẽ có dạng như:

==================================
Total Unique SQL Queries: 24
==================================
Count | Avg Time (ms)   | SQL Query                                                                                                 | Source
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
8     | 0.33            | SELECT `users`.* FROM `users` WHERE `users`.`id` = xxx LIMIT 1                                            | app/controllers/users_controller.rb:125:in `create'
      |                 |                                                                                                           | app/controllers/projects_controller.rb:9:in `block in update'
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
4     | 0.27            | SELECT `projects`.* FROM `projects` WHERE `projects`.`user_id` = xxx AND `projects`.`id` = xxx LIMIT 1    | app/controllers/projects_controller.rb:4:in `update'
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2     | 0.27            | UPDATE `projects` SET `updated_at` = xxx WHERE `projects`.`id` = xxx                                      | app/controllers/projects_controller.rb:9:in `block in update'
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
2     | 1.76            | SELECT projects.* FROM projects WHERE projects.priority BETWEEN xxx AND xxx ORDER BY created_at DESC      | app/controllers/projects_controller.rb:35:in `index'
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
... ...

Trong report sẽ đưa ra tổng số query, thời gian chạy trung bình một query, và dòng code nào gọi đến query đó. Từ report này, ta có thể biết được những query nào được gọi nhiều nhất, và vì sao chúng được gọi đến. Nếu những query tương tự nhau được gọi nhiều lần, có lẽ ta nên bắt đầu bằng việc cache query đó. Nếu một query được gọi từ nhiều nơi trong code, rõ ràng code đó cần được refactor.

Kết luận

Mặc dù chỉ cung cấp những thông tin hết sức cơ bản, sql_tracker là một tool hữu ích cho việc refactoring và optimization, công đoạn quan trọng và tốn rất nhiều công sức mà đôi khi kết quả thủ về chỉ là một phần mười giây. Source code và hướng dẫn chi tiết của gem được đăng tải tại đây.