Skip to content

Commit

Permalink
Merge pull request #1316 from ruby-agent/explain_plan
Browse files Browse the repository at this point in the history 
RUBY-1229 Run explain plans on parameterized slow queries in AR4
  • Loading branch information
Karl Sandwich committed Apr 14, 2016
2 parents 66a8b24 + fec7c99 commit c9f4318
Show file tree
Hide file tree
Showing 12 changed files with 452 additions and 337 deletions.
8 changes: 8 additions & 0 deletions CHANGELOG
View file
Expand Up @@ -2,6 +2,14 @@

## v3.15.2 ##

* Run explain plans on parameterized slow queries in AR4

In our ActiveRecord 4 instrumentation, we moved to tracing slow queries
using the payloads from subscribing to ActiveSupport::Notifications for
`sql.active_record` events. As a result, we were unable to run explain
plans on parameterized queries. This has now been updated to pass along
and use the parameter values, when available, to get the explain plans.

* Fix getMore metric grouping issue in Mongo 2.2.x instrumentation

A metric grouping issue had cropped up again when using the most recent
Expand Down
237 changes: 72 additions & 165 deletions lib/new_relic/agent/database.rb
View file
Expand Up @@ -3,9 +3,8 @@
# See https://github.com/newrelic/rpm/blob/master/LICENSE for complete details.

require 'singleton'
require 'new_relic/agent/database/obfuscation_helpers'
require 'new_relic/agent/database/explain_plan_helpers'
require 'new_relic/agent/database/obfuscator'
require 'new_relic/agent/database/postgres_explain_obfuscator'

module NewRelic
# columns for a mysql explain plan
Expand Down Expand Up @@ -95,157 +94,18 @@ def close_connections
ConnectionManager.instance.close_connections
end

# This takes a connection config hash from ActiveRecord or Sequel and
# returns a string describing the associated database adapter
def adapter_from_config(config)
if config[:adapter]
return config[:adapter].to_s
elsif config[:uri] && config[:uri].to_s =~ /^jdbc:([^:]+):/
# This case is for Sequel with the jdbc-mysql, jdbc-postgres, or
# jdbc-sqlite3 gems.
return $1
end
end

# Perform this in the runtime environment of a managed
# application, to explain the sql statement executed within a
# node of a transaction sample. Returns an array of
# explanations (which is an array rows consisting of an array of
# strings for each column returned by the the explain query)
# Note this happens only for statements whose execution time
# exceeds a threshold (e.g. 500ms) and only within the slowest
# transaction in a report period, selected for shipment to New
# Relic
def explain_sql(sql, connection_config, explainer=nil)
return nil unless sql && explainer && connection_config
statement = sql.split(";\n")[0] # only explain the first
explain_plan = explain_statement(statement, connection_config, explainer)
return explain_plan || []
end

SUPPORTED_ADAPTERS_FOR_EXPLAIN = %w[postgres postgresql mysql2 mysql sqlite].freeze

def explain_statement(statement, config, explainer)
return unless explainer && is_select?(statement)

if statement[-3,3] == '...'
NewRelic::Agent.logger.debug('Unable to collect explain plan for truncated query.')
return
end

if parameterized?(statement)
NewRelic::Agent.logger.debug('Unable to collect explain plan for parameterized query.')
return
end

adapter = adapter_from_config(config)
if !SUPPORTED_ADAPTERS_FOR_EXPLAIN.include?(adapter)
NewRelic::Agent.logger.debug("Not collecting explain plan because an unknown connection adapter ('#{adapter}') was used.")
return
end

handle_exception_in_explain do
start = Time.now
plan = explainer.call(config, statement)
::NewRelic::Agent.record_metric("Supportability/Database/execute_explain_plan", Time.now - start)
return process_resultset(plan, adapter) if plan
end
end

def process_resultset(results, adapter)
case adapter.to_s
when 'postgres', 'postgresql'
process_explain_results_postgres(results)
when 'mysql2'
process_explain_results_mysql2(results)
when 'mysql'
process_explain_results_mysql(results)
when 'sqlite'
process_explain_results_sqlite(results)
end
end

QUERY_PLAN = 'QUERY PLAN'.freeze

def process_explain_results_postgres(results)
if results.is_a?(String)
query_plan_string = results
else
lines = []
results.each { |row| lines << row[QUERY_PLAN] }
query_plan_string = lines.join("\n")
end

unless record_sql_method == :raw
query_plan_string = NewRelic::Agent::Database::PostgresExplainObfuscator.obfuscate(query_plan_string)
end
values = query_plan_string.split("\n").map { |line| [line] }

[[QUERY_PLAN], values]
end

# Sequel returns explain plans as just one big pre-formatted String
# In that case, we send a nil headers array, and the single string
# wrapped in an array for the values.
# Note that we don't use this method for Postgres explain plans, since
# they need to be passed through the explain plan obfuscator first.
def string_explain_plan_results(results)
[nil, [results]]
end

def process_explain_results_mysql(results)
return string_explain_plan_results(results) if results.is_a?(String)
headers = []
values = []
if results.is_a?(Array)
# We're probably using the jdbc-mysql gem for JRuby, which will give
# us an array of hashes.
headers = results.first.keys
results.each do |row|
values << headers.map { |h| row[h] }
end
else
# We're probably using the native mysql driver gem, which will give us
# a Mysql::Result object that responds to each_hash
results.each_hash do |row|
headers = row.keys
values << headers.map { |h| row[h] }
end
end
[headers, values]
end

def process_explain_results_mysql2(results)
return string_explain_plan_results(results) if results.is_a?(String)
headers = results.fields
values = []
results.each { |row| values << row }
[headers, values]
end

SQLITE_EXPLAIN_COLUMNS = %w[addr opcode p1 p2 p3 p4 p5 comment]

def process_explain_results_sqlite(results)
return string_explain_plan_results(results) if results.is_a?(String)
headers = SQLITE_EXPLAIN_COLUMNS
values = []
results.each do |row|
values << headers.map { |h| row[h] }
end
[headers, values]
end

def handle_exception_in_explain
yield
rescue => e
begin
# guarantees no throw from explain_sql
::NewRelic::Agent.logger.error("Error getting query plan:", e)
nil
rescue
# double exception. throw up your hands
nil
end
# node of a transaction sample. Returns an array of two arrays.
# The first array contains the headers, while the second consists of
# arrays of strings for each column returned by the explain query.
# Note this happens only for statements whose execution time exceeds
# a threshold (e.g. 500ms) and only within the slowest transaction
# in a report period, selected for shipment to New Relic
def explain_sql(statement)
return nil unless statement.sql && statement.explainer && statement.config
statement.sql = statement.sql.split(";\n")[0] # only explain the first
return statement.explain || []
end

KNOWN_OPERATIONS = [
Expand Down Expand Up @@ -273,14 +133,6 @@ def parse_operation_from_query(sql)
end
end

def is_select?(statement)
parse_operation_from_query(statement) == 'select'
end

def parameterized?(statement)
Obfuscator.instance.obfuscate_single_quote_literals(statement) =~ /\$\d+/
end

class ConnectionManager
include Singleton

Expand Down Expand Up @@ -318,33 +170,88 @@ def close_connections
end

class Statement
attr_accessor :sql, :config, :explainer
include ExplainPlanHelpers

attr_accessor :sql, :config, :explainer, :binds, :name

def initialize(sql, config={}, explainer=nil)
DEFAULT_QUERY_NAME = "SQL".freeze

def initialize(sql, config={}, explainer=nil, binds=[], name=DEFAULT_QUERY_NAME)
@sql = Database.capture_query(sql)
@config = config
@explainer = explainer
@binds = binds
@name = name
end

# This takes a connection config hash from ActiveRecord or Sequel and
# returns a symbol describing the associated database adapter
def adapter
config && config[:adapter] && symbolized_adapter(config[:adapter].to_s.downcase)
return unless @config

@adapter ||= if @config[:adapter]
symbolized_adapter(@config[:adapter].to_s.downcase)
elsif @config[:uri] && @config[:uri].to_s =~ /^jdbc:([^:]+):/
# This case is for Sequel with the jdbc-mysql, jdbc-postgres, or jdbc-sqlite3 gems.
symbolized_adapter($1)
else
nil
end
end

def explain
return unless explainable?
handle_exception_in_explain do
start = Time.now
plan = @explainer.call(self)
::NewRelic::Agent.record_metric("Supportability/Database/execute_explain_plan", Time.now - start)
return process_resultset(plan, adapter) if plan
end
end

private

POSTGRES_PREFIX = 'postgres'.freeze
MYSQL_PREFIX = 'mysql'.freeze
SQLITE_PREFIX = 'sqlite'.freeze
MYSQL_PREFIX = 'mysql'.freeze
MYSQL2_PREFIX = 'mysql2'.freeze
SQLITE_PREFIX = 'sqlite'.freeze

def symbolized_adapter(adapter)
if adapter.start_with? POSTGRES_PREFIX
:postgres
elsif adapter.start_with? MYSQL_PREFIX
elsif adapter == MYSQL_PREFIX
:mysql
# For the purpose of fetching explain plans, we need to maintain the distinction
# between usage of mysql and mysql2. Obfuscation is the same, though.
elsif adapter == MYSQL2_PREFIX
:mysql2
elsif adapter.start_with? SQLITE_PREFIX
:sqlite
else
adapter.to_sym
end
end

def explainable?
return false unless @explainer && is_select?(@sql)

if @sql[-3,3] == '...'
NewRelic::Agent.logger.debug('Unable to collect explain plan for truncated query.')
return false
end

if parameterized?(@sql) && @binds.empty?
NewRelic::Agent.logger.debug('Unable to collect explain plan for parameter-less parameterized query.')
return false
end

if !SUPPORTED_ADAPTERS_FOR_EXPLAIN.include?(adapter)
NewRelic::Agent.logger.debug("Not collecting explain plan because an unknown connection adapter ('#{adapter}') was used.")
return false
end

true
end
end
end
end
Expand Down

0 comments on commit c9f4318

Please sign in to comment.