Add comprehensive concurrent-test-locking logging to aid future debugging
[dbsrgits/DBIx-Class.git] / t / lib / DBICTest / BaseSchema.pm
index ae8d74a..92234dc 100644 (file)
@@ -8,48 +8,55 @@ use base qw(DBICTest::Base DBIx::Class::Schema);
 use Fcntl qw(:DEFAULT :seek :flock);
 use Time::HiRes 'sleep';
 use DBICTest::Util::LeakTracer qw(populate_weakregistry assert_empty_weakregistry);
-use DBICTest::Util 'local_umask';
+use DBICTest::Util qw( local_umask dbg DEBUG_TEST_CONCURRENCY_LOCKS );
 use namespace::clean;
 
-{
-  package # moar hide
-    DBICTest::SQLTracerObj;
-  use base 'DBIx::Class::Storage::Statistics';
-
-  sub query_start { push @{$_[0]{sqlbinds}}, [ ($_[1] =~ /^\s*(\S+)/)[0], [ $_[1], @{ $_[2]||[] } ] ] }
-
-  # who the hell came up with this API >:(
-  for my $txn (qw(begin rollback commit)) {
-    no strict 'refs';
-    *{"txn_$txn"} = sub { push @{$_[0]{sqlbinds}}, [ uc $txn => [ uc $txn ] ] };
-  }
-
-  sub svp_begin { push @{$_[0]{sqlbinds}}, [ SAVEPOINT => [ "SAVEPOINT $_[1]" ] ] }
-  sub svp_release { push @{$_[0]{sqlbinds}}, [ RELEASE_SAVEPOINT => [ "RELEASE $_[1]" ] ] }
-  sub svp_rollback { push @{$_[0]{sqlbinds}}, [ ROLLBACK_TO_SAVEPOINT => [ "ROLLBACK TO $_[1]" ] ] }
-
-}
-
 sub capture_executed_sql_bind {
   my ($self, $cref) = @_;
 
   $self->throw_exception("Expecting a coderef to run") unless ref $cref eq 'CODE';
 
+  require DBICTest::SQLTracerObj;
+
   # hack around stupid, stupid API
   no warnings 'redefine';
   local *DBIx::Class::Storage::DBI::_format_for_trace = sub { $_[1] };
   Class::C3->reinitialize if DBIx::Class::_ENV_::OLD_MRO;
 
+
   local $self->storage->{debugcb};
   local $self->storage->{debugobj} = my $tracer_obj = DBICTest::SQLTracerObj->new;
   local $self->storage->{debug} = 1;
 
-
+  local $Test::Builder::Level = $Test::Builder::Level + 2;
   $cref->();
 
   return $tracer_obj->{sqlbinds} || [];
 }
 
+sub is_executed_querycount {
+  my ($self, $cref, $exp_counts, $msg) = @_;
+
+  local $Test::Builder::Level = $Test::Builder::Level + 1;
+
+  $self->throw_exception("Expecting an hashref of counts or an integer representing total query count")
+    unless ref $exp_counts eq 'HASH' or (defined $exp_counts and ! ref $exp_counts);
+
+  my @got = map { $_->[0] } @{ $self->capture_executed_sql_bind($cref) };
+
+  return Test::More::is( @got, $exp_counts, $msg )
+    unless ref $exp_counts;
+
+  my $got_counts = { map { $_ => 0 } keys %$exp_counts };
+  $got_counts->{$_}++ for @got;
+
+  return Test::More::is_deeply(
+    $got_counts,
+    $exp_counts,
+    $msg,
+  );
+}
+
 sub is_executed_sql_bind {
   my ($self, $cref, $sqlbinds, $msg) = @_;
 
@@ -101,7 +108,8 @@ our $locker;
 END {
   # we need the $locker to be referenced here for delayed destruction
   if ($locker->{lock_name} and ($ENV{DBICTEST_LOCK_HOLDER}||0) == $$) {
-    #warn "$$ $0 $locker->{type} LOCK RELEASED";
+    DEBUG_TEST_CONCURRENCY_LOCKS
+      and dbg "$locker->{type} LOCK RELEASED (END): $locker->{lock_name}";
   }
 }
 
@@ -149,28 +157,28 @@ sub connection {
     ($_[0]||'') !~ /^ (?i:dbi) \: SQLite \: (?: dbname\= )? (?: \:memory\: | t [\/\\] var [\/\\] DBIxClass\-) /x
   ) {
 
-    my $locktype = do {
+    my $locktype;
+
+    {
       # guard against infinite recursion
       local $ENV{DBICTEST_LOCK_HOLDER} = -1;
 
-      # we need to connect a forced fresh clone so that we do not upset any state
+      # we need to work with a forced fresh clone so that we do not upset any state
       # of the main $schema (some tests examine it quite closely)
       local $SIG{__WARN__} = sub {};
       local $@;
-      my $storage = eval {
-        my $st = ref($self)->connect(@{$self->storage->connect_info})->storage;
-        $st->ensure_connected;  # do connect here, to catch a possible throw
-        $st;
+
+      # this will either give us an undef $locktype or will determine things
+      # properly with a default ( possibly connecting in the process )
+      eval {
+        my $s = ref($self)->connect(@{$self->storage->connect_info})->storage;
+
+        $locktype = $s->sqlt_type || 'generic';
+
+        # in case sqlt_type did connect, doesn't matter if it fails or something
+        $s->disconnect;
       };
-      $storage
-        ? do {
-          my $t = $storage->sqlt_type || 'generic';
-          eval { $storage->disconnect };
-          $t;
-        }
-        : undef
-      ;
-    };
+    }
 
     # Never hold more than one lock. This solves the "lock in order" issues
     # unrelated tests may have
@@ -179,18 +187,27 @@ sub connection {
 
       # this will release whatever lock we may currently be holding
       # which is fine since the type does not match as checked above
+      DEBUG_TEST_CONCURRENCY_LOCKS
+        and $locker
+        and dbg "$locker->{type} LOCK RELEASED (UNDEF): $locker->{lock_name}";
+
       undef $locker;
 
       my $lockpath = DBICTest::RunMode->tmpdir->file("_dbictest_$locktype.lock");
 
-      #warn "$$ $0 $locktype GRABBING LOCK";
+      DEBUG_TEST_CONCURRENCY_LOCKS
+        and dbg "Waiting for $locktype LOCK: $lockpath...";
+
       my $lock_fh;
       {
         my $u = local_umask(0); # so that the file opens as 666, and any user can lock
         sysopen ($lock_fh, $lockpath, O_RDWR|O_CREAT) or die "Unable to open $lockpath: $!";
       }
+
       flock ($lock_fh, LOCK_EX) or die "Unable to lock $lockpath: $!";
-      #warn "$$ $0 $locktype LOCK GRABBED";
+
+      DEBUG_TEST_CONCURRENCY_LOCKS
+        and dbg "Got $locktype LOCK: $lockpath";
 
       # see if anyone was holding a lock before us, and wait up to 5 seconds for them to terminate
       # if we do not do this we may end up trampling over some long-running END or somesuch
@@ -201,12 +218,17 @@ sub connection {
           and
         ($old_pid) = $old_pid =~ /^(\d+)$/
       ) {
+        DEBUG_TEST_CONCURRENCY_LOCKS
+          and dbg "Post-grab WAIT for $old_pid START: $lockpath";
+
         for (1..50) {
           kill (0, $old_pid) or last;
           sleep 0.1;
         }
+
+        DEBUG_TEST_CONCURRENCY_LOCKS
+          and dbg "Post-grab WAIT for $old_pid FINISHED: $lockpath";
       }
-      #warn "$$ $0 $locktype POST GRAB WAIT";
 
       truncate $lock_fh, 0;
       seek ($lock_fh, 0, SEEK_SET) or die "seek failed $!";