The other side of the moon

I'd been doing some stress testing of my mysql application today, and I was hitting some weird cases. Several transactions were deadlocking - this was expected - but the number of records that got inserted into my table was more than the number that I expected after subtracting errors.

My test was fairly simple:

1. Fork 15 processes
2. Insert and update 100 records in each process, running each INSERT/UPDATE pair inside one transaction
3. ROLLBACK on error

Either the INSERT or the UPDATE was expected to fail due to deadlock, and the whole transaction should have rolled back leaving no record in the table.

Before I go on, I should mention that I was using InnoDB, which does support transactions.

What I expected was that the total number of records in the table + the total number of INSERT/UPDATE aborts due to deadlock should be equal to 1500 (15*100). What I was actually seeing, was completely off. At one point I had 400 errors and 1299 records in the table - that's 199 extra records, and at another point I had 344 errors with 1497 records left over. On inspection of the records, I found that many of them had bad data. In most cases, it looked as though the UPDATE had never run, and in other cases, it looked as though the UPDATE ran on more than one record.

Now, my code looked something like this:

   mysql_query("START TRANSACTION", $db);

   $result = mysql_query("INSERT ...", $db);
   if(!$result)
   {
      log_error($db);
      mysql_query("ROLLBACK", $db);
      return false;
   }

   $result = mysql_query("UPDATE ...", $db);
   if(!$result)
   {
      log_error($db);
      mysql_query("ROLLBACK", $db);
      return false;
   }

   if(mysql_affected_rows($db) != 1)
   {
      log_error("bad update");
      mysql_query("ROLLBACK", $db);
      return false;
   }

   mysql_query("COMMIT", $db);
   return true;

So if anything failed, there should have been no record in the table, yet I was seeing records that did the INSERT, but not the UPDATE, or that did the UPDATE for more than one record. Control was getting in to all the if conditions - I was getting log messages for that, but the ROLLBACK was never taking effect.

Again, before anyone asks, the log_error() function I wrote uses debug_backtrace to log the filename and line number that it was called from.

I stared at the screen for a while wondering what the problem could be. The MySQL docs said a few things:

• InnoDB supports transactions
• AUTOCOMMIT is On by default
• Use START TRANSACTION or BEGIN to turn AUTOCOMMIT OFF until the next ROLLBACK OR COMMIT
• ROLLBACK rolls back everything until the last START TRANSACTION if a transaction is in effect, or the last statement (if AUTOCOMMIT is OFF)
• COMMIT commits the last statement or transaction depending on whether AUTOCOMMIT is OFF and a transaction is active or not

Nothing explained why ROLLBACK wasn't working here.

The only possibility I could think of, was that the START TRANSACTION itself failed, but when I checked the mysql docs, there was no mention of START TRANSACTION ever failing. Anyway, I decided to check, so I changed the start of the code to this:

   if(!mysql_query("START TRANSACTION", $db))
   {
      log_error($db);
      return false;
   }

And immediately I started seeing errors on this line.

The error I got was:

   Lost connection to MySQL server during query

Searching on Yahoo! got me this link on the MySQL reference manual. The second last point on that page answered my question immediately:

You can also encounter this error with applications that fork child processes, all of which try to use the same connection to the MySQL server. This can be avoided by using a separate connection for each child process.

That's exactly what I was doing. I was opening the db connection before forking, so each child inherited a copy of that connection, and as soon as one of them closed it, all the others would fail.

So, I changed my code so that the db connection was opened and closed inside each child process, and now my results are consistent. I still get deadlocks, but the sum of errors seen and records added does add up correctly to the expected total.

Moral of the story: It may be okay to ignore the return values of COMMIT and ROLLBACK, but always check the return value of START TRANSACTION.