From 9c84010c0ac02f0347951d5866c424061708d3aa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Knut=20Olav=20L=C3=B8ite?= Date: Tue, 19 Dec 2023 17:52:33 +0100 Subject: [PATCH] feat: support Query Logs Rails 7.0 introduced support for Query Logs. These automatically append comments to all SQL statements that are executed, so it is easier to find queries that perform badly. Cloud Spanner does not include comments from the SQL string in the query statistics, meaning that in order for these comments to be useful, they need to be translated to request tags. This change modifies the query execution path so the query transformer that is used by Query Logs is called by the Cloud Spanner provider. The comments that are added can then be translated to request tags. The latter requires that Query Logs is configured with two specific options: 1. `ActiveRecord::QueryLogs.prepend_comment = true` 2. The first tag must be `{ request_tag: "true" }` See the included sample application for a full working sample. Fixes #285 --- examples/snippets/query-logs/README.md | 43 ++++++++++ examples/snippets/query-logs/Rakefile | 13 +++ examples/snippets/query-logs/application.rb | 63 ++++++++++++++ .../snippets/query-logs/config/database.yml | 8 ++ .../query-logs/db/migrate/01_create_tables.rb | 21 +++++ examples/snippets/query-logs/db/schema.rb | 31 +++++++ examples/snippets/query-logs/db/seeds.rb | 24 ++++++ examples/snippets/query-logs/models/album.rb | 9 ++ examples/snippets/query-logs/models/singer.rb | 9 ++ .../spanner/database_statements.rb | 86 +++++++++++++------ .../connection_adapters/spanner_adapter.rb | 8 ++ ...ner_active_record_with_mock_server_test.rb | 85 ++++++++++++++++++ 12 files changed, 373 insertions(+), 27 deletions(-) create mode 100644 examples/snippets/query-logs/README.md create mode 100644 examples/snippets/query-logs/Rakefile create mode 100644 examples/snippets/query-logs/application.rb create mode 100644 examples/snippets/query-logs/config/database.yml create mode 100644 examples/snippets/query-logs/db/migrate/01_create_tables.rb create mode 100644 examples/snippets/query-logs/db/schema.rb create mode 100644 examples/snippets/query-logs/db/seeds.rb create mode 100644 examples/snippets/query-logs/models/album.rb create mode 100644 examples/snippets/query-logs/models/singer.rb diff --git a/examples/snippets/query-logs/README.md b/examples/snippets/query-logs/README.md new file mode 100644 index 00000000..a441e87f --- /dev/null +++ b/examples/snippets/query-logs/README.md @@ -0,0 +1,43 @@ +# Sample - Query Logs + +__NOTE__: Query logs require additional configuration for Cloud Spanner. Please read the entire file. + +Rails 7.0 and higher supports [Query Logs](https://api.rubyonrails.org/classes/ActiveRecord/QueryLogs.html). Query Logs +can be used to automatically annotate all queries that are executed based on the current execution context. + +The Cloud Spanner ActiveRecord provider can be used in combination with Query Logs. The query logs are automatically +translated to request tags for the queries. +See https://cloud.google.com/spanner/docs/introspection/troubleshooting-with-tags for more +information about request and transaction tags in Cloud Spanner. + +## Configuration +Using Query Logs with Cloud Spanner requires some specific configuration: +1. You must set `ActiveRecord::QueryLogs.prepend_comment = true` +2. You must include `{ request_tag: "true" }` as the first tag in your configuration. + +```ruby +ActiveRecord::QueryLogs.prepend_comment = true +config.active_record.query_log_tags = [ + { + request_tag: "true", + }, + :namespaced_controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id }, + tenant_id: -> { Current.tenant&.id }, + static: "value", + }, +] +``` + +The sample will automatically start a Spanner Emulator in a docker container and execute the sample +against that emulator. The emulator will automatically be stopped when the application finishes. + +Run the application with the command + +```bash +bundle exec rake run +``` diff --git a/examples/snippets/query-logs/Rakefile b/examples/snippets/query-logs/Rakefile new file mode 100644 index 00000000..009be88b --- /dev/null +++ b/examples/snippets/query-logs/Rakefile @@ -0,0 +1,13 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require_relative "../config/environment" +require "sinatra/activerecord/rake" + +desc "Sample showing how to use automatic query log tagging on Cloud Spanner with ActiveRecord." +task :run do + Dir.chdir("..") { sh "bundle exec rake run[query-logs]" } +end diff --git a/examples/snippets/query-logs/application.rb b/examples/snippets/query-logs/application.rb new file mode 100644 index 00000000..73a910c5 --- /dev/null +++ b/examples/snippets/query-logs/application.rb @@ -0,0 +1,63 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require "io/console" +require_relative "../config/environment" +require_relative "models/singer" +require_relative "models/album" + +class Application + def self.run + enable_query_logs + + puts "" + puts "Query all Albums and include an automatically generated request tag" + albums = Album.all + puts "Queried #{albums.length} albums using an automatically generated request tag" + + puts "" + puts "Press any key to end the application" + STDIN.getch + end + + def self.enable_query_logs + # Enables Query Logs in a non-Rails application. Normally, this should be done + # as described here: https://api.rubyonrails.org/classes/ActiveRecord/QueryLogs.html + ActiveRecord.query_transformers << ActiveRecord::QueryLogs + + # Query log comments *MUST* be prepended to be included as a request tag. + ActiveRecord::QueryLogs.prepend_comment = true + + # This block manually enables Query Logs without a full Rails application. + # This should normally not be needed in your application. + ActiveRecord::QueryLogs.taggings.merge!( + application: "example-app", + action: "run-test-application", + pid: -> { Process.pid.to_s }, + socket: ->(context) { context[:connection].pool.db_config.socket }, + db_host: ->(context) { context[:connection].pool.db_config.host }, + database: ->(context) { context[:connection].pool.db_config.database } + ) + + ActiveRecord::QueryLogs.tags = [ + # The first tag *MUST* be the fixed value 'request_tag:true'. + { + request_tag: "true" + }, + :controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id } + }, + :db_host, + :database + ] + end +end + +Application.run diff --git a/examples/snippets/query-logs/config/database.yml b/examples/snippets/query-logs/config/database.yml new file mode 100644 index 00000000..905be603 --- /dev/null +++ b/examples/snippets/query-logs/config/database.yml @@ -0,0 +1,8 @@ +development: + adapter: spanner + emulator_host: localhost:9010 + project: test-project + instance: test-instance + database: testdb + pool: 5 + timeout: 5000 diff --git a/examples/snippets/query-logs/db/migrate/01_create_tables.rb b/examples/snippets/query-logs/db/migrate/01_create_tables.rb new file mode 100644 index 00000000..14750674 --- /dev/null +++ b/examples/snippets/query-logs/db/migrate/01_create_tables.rb @@ -0,0 +1,21 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class CreateTables < ActiveRecord::Migration[6.0] + def change + connection.ddl_batch do + create_table :singers do |t| + t.string :first_name + t.string :last_name + end + + create_table :albums do |t| + t.string :title + t.references :singer, index: false, foreign_key: true + end + end + end +end diff --git a/examples/snippets/query-logs/db/schema.rb b/examples/snippets/query-logs/db/schema.rb new file mode 100644 index 00000000..dc7b860a --- /dev/null +++ b/examples/snippets/query-logs/db/schema.rb @@ -0,0 +1,31 @@ +# This file is auto-generated from the current state of the database. Instead +# of editing this file, please use the migrations feature of Active Record to +# incrementally modify your database, and then regenerate this schema definition. +# +# This file is the source Rails uses to define your schema when running `bin/rails +# db:schema:load`. When creating a new database, `bin/rails db:schema:load` tends to +# be faster and is potentially less error prone than running all of your +# migrations from scratch. Old migrations may fail to apply correctly if those +# migrations use external dependencies or application code. +# +# It's strongly recommended that you check this file into your version control system. + +ActiveRecord::Schema[7.1].define(version: 1) do + connection.start_batch_ddl + + create_table "albums", force: :cascade do |t| + t.string "title" + t.integer "singer_id", limit: 8 + end + + create_table "singers", force: :cascade do |t| + t.string "first_name" + t.string "last_name" + end + + add_foreign_key "albums", "singers" + connection.run_batch +rescue + abort_batch + raise +end diff --git a/examples/snippets/query-logs/db/seeds.rb b/examples/snippets/query-logs/db/seeds.rb new file mode 100644 index 00000000..e085f8e0 --- /dev/null +++ b/examples/snippets/query-logs/db/seeds.rb @@ -0,0 +1,24 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require_relative "../../config/environment.rb" +require_relative "../models/singer" +require_relative "../models/album" + +first_names = ["Pete", "Alice", "John", "Ethel", "Trudy", "Naomi", "Wendy", "Ruben", "Thomas", "Elly"] +last_names = ["Wendelson", "Allison", "Peterson", "Johnson", "Henderson", "Ericsson", "Aronson", "Tennet", "Courtou"] + +adjectives = ["daily", "happy", "blue", "generous", "cooked", "bad", "open"] +nouns = ["windows", "potatoes", "bank", "street", "tree", "glass", "bottle"] + +5.times do + Singer.create first_name: first_names.sample, last_name: last_names.sample +end + +20.times do + singer_id = Singer.all.sample.id + Album.create title: "#{adjectives.sample} #{nouns.sample}", singer_id: singer_id +end diff --git a/examples/snippets/query-logs/models/album.rb b/examples/snippets/query-logs/models/album.rb new file mode 100644 index 00000000..0d953c83 --- /dev/null +++ b/examples/snippets/query-logs/models/album.rb @@ -0,0 +1,9 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class Album < ActiveRecord::Base + belongs_to :singer +end diff --git a/examples/snippets/query-logs/models/singer.rb b/examples/snippets/query-logs/models/singer.rb new file mode 100644 index 00000000..389329ef --- /dev/null +++ b/examples/snippets/query-logs/models/singer.rb @@ -0,0 +1,9 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class Singer < ActiveRecord::Base + has_many :albums +end diff --git a/lib/active_record/connection_adapters/spanner/database_statements.rb b/lib/active_record/connection_adapters/spanner/database_statements.rb index 9872fbd4..a44b8dfa 100644 --- a/lib/active_record/connection_adapters/spanner/database_statements.rb +++ b/lib/active_record/connection_adapters/spanner/database_statements.rb @@ -13,6 +13,7 @@ module ConnectionAdapters module Spanner module DatabaseStatements VERSION_7_1_0 = Gem::Version.create "7.1.0" + RequestOptions = Google::Cloud::Spanner::V1::RequestOptions # DDL, DML and DQL Statements @@ -30,6 +31,8 @@ def internal_exec_query sql, name = "SQL", binds = [], prepare: false, async: fa def internal_execute sql, name = "SQL", binds = [], prepare: false, async: false # rubocop:disable Lint/UnusedMethodArgument statement_type = sql_statement_type sql + sql = transform sql + append_request_tag_from_query_logs sql, binds if preventing_writes? && [:dml, :ddl].include?(statement_type) raise ActiveRecord::ReadOnlyError( @@ -40,40 +43,69 @@ def internal_execute sql, name = "SQL", binds = [], if statement_type == :ddl execute_ddl sql else - transaction_required = statement_type == :dml - materialize_transactions - - # First process and remove any hints in the binds that indicate that - # a different read staleness should be used than the default. - staleness_hint = binds.find { |b| b.is_a? Arel::Visitors::StalenessHint } - if staleness_hint - selector = Google::Cloud::Spanner::Session.single_use_transaction staleness_hint.value - binds.delete staleness_hint - end - request_options = binds.find { |b| b.is_a? Google::Cloud::Spanner::V1::RequestOptions } - if request_options - binds.delete request_options - end + execute_query_or_dml statement_type, sql, name, binds + end + end + + def execute_query_or_dml statement_type, sql, name, binds + transaction_required = statement_type == :dml + materialize_transactions - log_args = [sql, name] - log_args.concat [binds, type_casted_binds(binds)] if log_statement_binds - - log(*log_args) do - types, params = to_types_and_params binds - ActiveSupport::Dependencies.interlock.permit_concurrent_loads do - if transaction_required - transaction do - @connection.execute_query sql, params: params, types: types, request_options: request_options - end - else - @connection.execute_query sql, params: params, types: types, single_use_selector: selector, - request_options: request_options + # First process and remove any hints in the binds that indicate that + # a different read staleness should be used than the default. + staleness_hint = binds.find { |b| b.is_a? Arel::Visitors::StalenessHint } + if staleness_hint + selector = Google::Cloud::Spanner::Session.single_use_transaction staleness_hint.value + binds.delete staleness_hint + end + request_options = binds.find { |b| b.is_a? Google::Cloud::Spanner::V1::RequestOptions } + if request_options + binds.delete request_options + end + + log_args = [sql, name] + log_args.concat [binds, type_casted_binds(binds)] if log_statement_binds + + log(*log_args) do + types, params = to_types_and_params binds + ActiveSupport::Dependencies.interlock.permit_concurrent_loads do + if transaction_required + transaction do + @connection.execute_query sql, params: params, types: types, request_options: request_options end + else + @connection.execute_query sql, params: params, types: types, single_use_selector: selector, + request_options: request_options end end end end + def append_request_tag_from_query_logs sql, binds + legacy_formatter_prefix = "/*request_tag:true," + sql_commenter_prefix = "/*request_tag='true'," + if sql.start_with? legacy_formatter_prefix + append_request_tag_from_query_logs_with_format sql, binds, legacy_formatter_prefix + elsif sql.start_with? sql_commenter_prefix + append_request_tag_from_query_logs_with_format sql, binds, sql_commenter_prefix + end + end + + def append_request_tag_from_query_logs_with_format sql, binds, prefix + end_of_comment = sql.index "*/", prefix.length + return unless end_of_comment + + request_tag = sql[prefix.length, end_of_comment - prefix.length] + options = binds.find { |bind| bind.is_a? RequestOptions } || RequestOptions.new + if options.request_tag == "" + options.request_tag = request_tag + else + options.request_tag += "," + request_tag + end + + binds.append options + end + # The method signatures for executing queries and DML statements changed between Rails 7.0 and 7.1. if ActiveRecord.gem_version >= VERSION_7_1_0 diff --git a/lib/active_record/connection_adapters/spanner_adapter.rb b/lib/active_record/connection_adapters/spanner_adapter.rb index b8e9b140..bdbc565b 100644 --- a/lib/active_record/connection_adapters/spanner_adapter.rb +++ b/lib/active_record/connection_adapters/spanner_adapter.rb @@ -261,6 +261,14 @@ def type_map include TypeMapBuilder end + def transform sql + if ActiveRecord::VERSION::MAJOR >= 7 + transform_query sql + else + sql + end + end + # Overwrite the standard log method to be able to translate exceptions. def log sql, name = "SQL", binds = [], type_casted_binds = [], statement_name = nil, *args super diff --git a/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb b/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb index 8322c5ef..41fe404f 100644 --- a/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb +++ b/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb @@ -10,6 +10,7 @@ module MockServerTests CommitRequest = Google::Cloud::Spanner::V1::CommitRequest + ExecuteSqlRequest = Google::Cloud::Spanner::V1::ExecuteSqlRequest class SpannerActiveRecordMockServerTest < BaseSpannerMockServerTest VERSION_7_1_0 = Gem::Version.create('7.1.0') @@ -956,6 +957,90 @@ def test_query_annotate_request_and_transaction_tag_and_binds end end + def test_query_logs + skip "Requires Rails version 7.0 or higher" if ActiveRecord::VERSION::MAJOR < 7 + + begin + current_query_transformers = _enable_query_logs + + sql = "/*request_tag:true,action:test_query_logs,database:testdb*/ SELECT `singers`.* FROM `singers`" + @mock.put_statement_result sql, MockServerTests::create_random_singers_result(4) + Singer.all.each do |singer| + refute_nil singer.id, "singer.id should not be nil" + end + select_requests = @mock.requests.select { |req| req.is_a?(ExecuteSqlRequest) && req.sql == sql } + select_requests.each do |request| + assert request.request_options + assert_equal "action:test_query_logs,database:testdb", request.request_options.request_tag + end + ensure + _disable_query_logs current_query_transformers + end + end + + def test_query_logs_combined_with_request_tag + skip "Requires Rails version 7.0 or higher" if ActiveRecord::VERSION::MAJOR < 7 + + begin + current_query_transformers = _enable_query_logs + + sql = "/*request_tag:true,action:test_query_logs,database:testdb*/ SELECT `singers`.* FROM `singers` /* request_tag: selecting all singers */" + @mock.put_statement_result sql, MockServerTests::create_random_singers_result(4) + Singer.annotate("request_tag: selecting all singers").all.each do |singer| + refute_nil singer.id, "singer.id should not be nil" + end + select_requests = @mock.requests.select { |req| req.is_a?(ExecuteSqlRequest) && req.sql == sql } + select_requests.each do |request| + assert request.request_options + assert_equal "selecting all singers,action:test_query_logs,database:testdb", request.request_options.request_tag + end + ensure + _disable_query_logs current_query_transformers + end + end + + def _enable_query_logs + # Make sure that the comment that is added by query_logs is actually added to the query string. + # The comment is not translated to a request tag, because the comment is added at a too late moment. + # Instead, we need to add that at a lower level in the Spanner connection. + + # Simulate that query_logs has been enabled. + current_query_transformers = ActiveRecord.query_transformers + + ActiveRecord.query_transformers << ActiveRecord::QueryLogs + ActiveRecord::QueryLogs.prepend_comment = true + ActiveRecord::QueryLogs.taggings.merge!( + application: "test-app", + action: "test_query_logs", + pid: -> { Process.pid.to_s }, + socket: ->(context) { context[:connection].pool.db_config.socket }, + db_host: ->(context) { context[:connection].pool.db_config.host }, + database: ->(context) { context[:connection].pool.db_config.database }, + ) + ActiveRecord::QueryLogs.tags = [ + { + request_tag: "true", + }, + :controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id }, + }, + :db_host, + :database + ] + + current_query_transformers + end + + def _disable_query_logs current_query_transformers + current_query_transformers.each do |transformer| + ActiveRecord.query_transformers.delete transformer + end + end + def test_insert_all values = [ {id: 1, first_name: "Dave", last_name: "Allison"},