Add duration for blocking queries (#26)

* add duration for blocking queries

* Update log

* Remove absolute time

* Fix tests

Author: Thomas Hareau

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

@@ -3,7 +3,7 @@
 module SafePgMigrations
   module BlockingActivityLogger
     SELECT_BLOCKING_QUERIES_SQL = <<~SQL.squish
-      SELECT blocking_activity.query
+      SELECT blocking_activity.query, blocked_activity.xact_start as start
       FROM pg_catalog.pg_locks           blocked_locks
       JOIN pg_catalog.pg_stat_activity   blocked_activity
         ON blocked_activity.pid = blocked_locks.pid
@@ -50,7 +50,7 @@ def log_blocking_queries(method)
       blocking_queries_retriever_thread =
         Thread.new do
           sleep delay_before_logging(method)
-          SafePgMigrations.alternate_connection.query_values(SELECT_BLOCKING_QUERIES_SQL % raw_connection.backend_pid)
+          SafePgMigrations.alternate_connection.query(SELECT_BLOCKING_QUERIES_SQL % raw_connection.backend_pid)
         end
 
       yield
@@ -75,7 +75,7 @@ def log_blocking_queries(method)
           "Statement was being blocked by the following #{'query'.pluralize(queries.size)}:", true
         )
         SafePgMigrations.say '', true
-        queries.each { |query| SafePgMigrations.say "  #{query}", true }
+        queries.each { |query, start_time| SafePgMigrations.say "#{format_start_time start_time}:  #{query}", true }
         SafePgMigrations.say(
           'Beware, some of those queries might run in a transaction. In this case the locking query might be '\
           'located elsewhere in the transaction',
@@ -86,5 +86,10 @@ def log_blocking_queries(method)
 
       raise
     end
+
+    def format_start_time(start_time, reference_time = Time.now)
+      duration = (reference_time - start_time).round
+      "transaction started #{duration} #{'second'.pluralize(duration)} ago"
+    end
   end
 end

test/safe_pg_migrations_test.rb

@@ -85,7 +85,7 @@ def up
       '   -> Statement was being blocked by the following query:',
       '   -> ',
     ], calls[0..4]
-    assert_includes calls[5], '   ->   BEGIN; SELECT 1 FROM users'
+    assert_match(/\s*-> transaction started 1 second ago:\s*BEGIN; SELECT 1 FROM users/, calls[5])
     assert_equal [
       '   -> ',
       '   -> Retrying in 1 seconds...',