Skip to content

Commit 0f2db89

Browse files
bperbosbperbos
authored
Merge pull request #42 from doctolib/TT-3754
TT-3754: New option to hide raw SQL queries in blocking queries logger.
2 parents d184638 + b0eba9f commit 0f2db89

File tree

4 files changed

+101
-47
lines changed

4 files changed

+101
-47
lines changed

‎README.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -208,6 +208,8 @@ So you can actually check that the `CREATE INDEX` statement will be performed co
208208
```ruby
209209
SafePgMigrations.config.safe_timeout = 5.seconds # Lock and statement timeout used for all DDL operations except from CREATE / DROP INDEX
210210

211+
SafePgMigrations.config.blocking_activity_logger_verbose = true # Outputs the raw blocking queries on timeout. When false, outputs information about the lock instead
212+
211213
SafePgMigrations.config.blocking_activity_logger_margin = 1.second # Delay to output blocking queries before timeout. Must be shorter than safe_timeout
212214

213215
SafePgMigrations.config.batch_size = 1000 # Size of the batches used for backfilling when adding a column with a default value pre-PG11

‎lib/safe-pg-migrations/configuration.rb‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,15 @@ module SafePgMigrations
66
class Configuration
77
attr_accessor :safe_timeout
88
attr_accessor :blocking_activity_logger_margin
9+
attr_accessor :blocking_activity_logger_verbose
910
attr_accessor :batch_size
1011
attr_accessor :retry_delay
1112
attr_accessor :max_tries
1213

1314
def initialize
1415
self.safe_timeout = 5.seconds
1516
self.blocking_activity_logger_margin = 1.second
17+
self.blocking_activity_logger_verbose = true
1618
self.batch_size = 1000
1719
self.retry_delay = 1.minute
1820
self.max_tries = 5

‎lib/safe-pg-migrations/plugins/blocking_activity_logger.rb‎

Lines changed: 56 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -2,27 +2,18 @@
22

33
module SafePgMigrations
44
module BlockingActivityLogger
5-
SELECT_BLOCKING_QUERIES_SQL = <<~SQL.squish
6-
SELECT blocking_activity.query, blocked_activity.xact_start as start
7-
FROM pg_catalog.pg_locks blocked_locks
8-
JOIN pg_catalog.pg_stat_activity blocked_activity
9-
ON blocked_activity.pid = blocked_locks.pid
10-
JOIN pg_catalog.pg_locks blocking_locks
11-
ON blocking_locks.locktype = blocked_locks.locktype
12-
AND blocking_locks.DATABASE IS NOT DISTINCT FROM blocked_locks.DATABASE
13-
AND blocking_locks.relation IS NOT DISTINCT FROM blocked_locks.relation
14-
AND blocking_locks.page IS NOT DISTINCT FROM blocked_locks.page
15-
AND blocking_locks.tuple IS NOT DISTINCT FROM blocked_locks.tuple
16-
AND blocking_locks.virtualxid IS NOT DISTINCT FROM blocked_locks.virtualxid
17-
AND blocking_locks.transactionid IS NOT DISTINCT FROM blocked_locks.transactionid
18-
AND blocking_locks.classid IS NOT DISTINCT FROM blocked_locks.classid
19-
AND blocking_locks.objid IS NOT DISTINCT FROM blocked_locks.objid
20-
AND blocking_locks.objsubid IS NOT DISTINCT FROM blocked_locks.objsubid
21-
AND blocking_locks.pid != blocked_locks.pid
22-
JOIN pg_catalog.pg_stat_activity blocking_activity
23-
ON blocking_activity.pid = blocking_locks.pid
24-
WHERE blocked_locks.pid = %d
25-
SQL
5+
FILTERED_COLUMNS = %w[
6+
blocked_activity.xact_start
7+
blocked_locks.locktype
8+
blocked_locks.mode
9+
blocking_activity.pid
10+
blocked_locks.transactionid
11+
].freeze
12+
13+
VERBOSE_COLUMNS = %w[
14+
blocking_activity.query
15+
blocked_activity.xact_start
16+
].freeze
2617

2718
%i[
2819
add_column remove_column add_foreign_key remove_foreign_key change_column_default change_column_null create_table
@@ -34,14 +25,40 @@ module BlockingActivityLogger
3425

3526
private
3627

28+
def select_blocking_queries_sql
29+
columns = SafePgMigrations.config.blocking_activity_logger_verbose ? VERBOSE_COLUMNS : FILTERED_COLUMNS
30+
31+
<<~SQL.squish
32+
SELECT #{columns.join(', ')}
33+
FROM pg_catalog.pg_locks blocked_locks
34+
JOIN pg_catalog.pg_stat_activity blocked_activity
35+
ON blocked_activity.pid = blocked_locks.pid
36+
JOIN pg_catalog.pg_locks blocking_locks
37+
ON blocking_locks.locktype = blocked_locks.locktype
38+
AND blocking_locks.DATABASE IS NOT DISTINCT FROM blocked_locks.DATABASE
39+
AND blocking_locks.relation IS NOT DISTINCT FROM blocked_locks.relation
40+
AND blocking_locks.page IS NOT DISTINCT FROM blocked_locks.page
41+
AND blocking_locks.tuple IS NOT DISTINCT FROM blocked_locks.tuple
42+
AND blocking_locks.virtualxid IS NOT DISTINCT FROM blocked_locks.virtualxid
43+
AND blocking_locks.transactionid IS NOT DISTINCT FROM blocked_locks.transactionid
44+
AND blocking_locks.classid IS NOT DISTINCT FROM blocked_locks.classid
45+
AND blocking_locks.objid IS NOT DISTINCT FROM blocked_locks.objid
46+
AND blocking_locks.objsubid IS NOT DISTINCT FROM blocked_locks.objsubid
47+
AND blocking_locks.pid != blocked_locks.pid
48+
JOIN pg_catalog.pg_stat_activity blocking_activity
49+
ON blocking_activity.pid = blocking_locks.pid
50+
WHERE blocked_locks.pid = %d
51+
SQL
52+
end
53+
3754
def log_blocking_queries
3855
delay_before_logging =
3956
SafePgMigrations.config.safe_timeout - SafePgMigrations.config.blocking_activity_logger_margin
4057

4158
blocking_queries_retriever_thread =
4259
Thread.new do
4360
sleep delay_before_logging
44-
SafePgMigrations.alternate_connection.query(SELECT_BLOCKING_QUERIES_SQL % raw_connection.backend_pid)
61+
SafePgMigrations.alternate_connection.query(select_blocking_queries_sql % raw_connection.backend_pid)
4562
end
4663

4764
yield
@@ -66,7 +83,7 @@ def log_blocking_queries
6683
"Statement was being blocked by the following #{'query'.pluralize(queries.size)}:", true
6784
)
6885
SafePgMigrations.say '', true
69-
queries.each { |query, start_time| SafePgMigrations.say "#{format_start_time start_time}: #{query}", true }
86+
output_blocking_queries(queries)
7087
SafePgMigrations.say(
7188
'Beware, some of those queries might run in a transaction. In this case the locking query might be '\
7289
'located elsewhere in the transaction',
@@ -78,6 +95,22 @@ def log_blocking_queries
7895
raise
7996
end
8097

98+
def output_blocking_queries(queries)
99+
if SafePgMigrations.config.blocking_activity_logger_verbose
100+
queries.each { |query, start_time| SafePgMigrations.say "#{format_start_time start_time}: #{query}", true }
101+
else
102+
queries.each do |start_time, locktype, mode, pid, transactionid|
103+
SafePgMigrations.say(
104+
"#{format_start_time(start_time)}: lock type: #{locktype || 'null'}, " \
105+
"lock mode: #{mode || 'null'}, " \
106+
"lock pid: #{pid || 'null'}, " \
107+
"lock transactionid: #{transactionid || 'null'}",
108+
true
109+
)
110+
end
111+
end
112+
end
113+
81114
def format_start_time(start_time, reference_time = Time.now)
82115
duration = (reference_time - start_time).round
83116
"transaction started #{duration} #{'second'.pluralize(duration)} ago"

‎test/safe_pg_migrations_test.rb‎

Lines changed: 41 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -49,33 +49,21 @@ def change
4949
refute @connection.table_exists?(:users)
5050
end
5151

52-
def test_statement_retry
53-
@connection.create_table(:users)
54-
@migration =
55-
Class.new(ActiveRecord::Migration::Current) do
56-
def up
57-
# Simulate a blocking transaction from another connection.
58-
thread_lock = Concurrent::CountDownLatch.new
59-
thread =
60-
Thread.new do
61-
ActiveRecord::Base.connection.execute('BEGIN; SELECT 1 FROM users')
62-
thread_lock.count_down
63-
sleep 1
64-
ActiveRecord::Base.connection.commit_db_transaction
65-
end
66-
67-
thread_lock.wait # Wait for the above transaction to start.
68-
69-
add_column :users, :email, :string
52+
def test_blocking_activity_logger_filtered
53+
SafePgMigrations.config.blocking_activity_logger_verbose = false
7054

71-
thread.join
72-
end
73-
end.new
55+
@connection.create_table(:users)
56+
@migration = simulate_blocking_transaction_from_another_connection
7457

75-
SafePgMigrations.config.retry_delay = 1.second
76-
SafePgMigrations.config.safe_timeout = 0.5.second
77-
SafePgMigrations.config.blocking_activity_logger_margin = 0.1.seconds
58+
calls = record_calls(@migration, :write) { run_migration }.join
59+
assert_includes calls, 'lock type: relation'
60+
assert_includes calls, 'lock mode: AccessExclusiveLock'
61+
assert_includes calls, 'lock pid:'
62+
assert_includes calls, 'lock transactionid: null'
63+
end
7864

65+
def test_statement_retry
66+
@migration = simulate_blocking_transaction_from_another_connection
7967
calls = record_calls(@migration, :write) { run_migration }.map(&:first)
8068
assert @connection.column_exists?(:users, :email, :string)
8169
assert_equal [
@@ -597,4 +585,33 @@ def up
597585
assert_match("SET lock_timeout TO '70s'", logs[4])
598586
end
599587
end
588+
589+
private
590+
591+
def simulate_blocking_transaction_from_another_connection
592+
SafePgMigrations.config.retry_delay = 1.second
593+
SafePgMigrations.config.safe_timeout = 0.5.second
594+
SafePgMigrations.config.blocking_activity_logger_margin = 0.1.seconds
595+
596+
@connection.create_table(:users)
597+
598+
Class.new(ActiveRecord::Migration::Current) do
599+
def up
600+
thread_lock = Concurrent::CountDownLatch.new
601+
thread =
602+
Thread.new do
603+
ActiveRecord::Base.connection.execute('BEGIN; SELECT 1 FROM users')
604+
thread_lock.count_down
605+
sleep 1
606+
ActiveRecord::Base.connection.commit_db_transaction
607+
end
608+
609+
thread_lock.wait # Wait for the above transaction to start.
610+
611+
add_column :users, :email, :string
612+
613+
thread.join
614+
end
615+
end.new
616+
end
600617
end

0 commit comments

Comments
 (0)