Parallel Bug #2

This time, the bug is wrong handling of database connections in an id generator (class IdGen). The intention of the IdGen class is that a new id is created in a separate transaction. Because of this, parallel requests can get new ids without (much) waiting for each other even if the request transactions themselves are long. However, due to a tiny error we made, the behavior was not as intended. Yet, the buggy code was not detected for almost 6 months - it seems that in real life, there were not too many parallel requests; and/or they were short enough; and/or users accepted waiting times.

In the following code, the threads t1 and t2 represent two requests, e.g. in a web server. The SQL Server WAITFOR statements represent SQL statements that take a few seconds. This allows us to reproduce the bug deterministally.

Here is the code:

    1 using System;

    2 using System.Data;

    3 using System.Data.SqlClient;

    4 using System.Threading;

    5 

    6 #region An SQL Connection And Id Generation Framework

    7 

    8 public static class Logger {

    9     private static readonly DateTime _st = DateTime.Now;

   10     public static void Log(string msg) {

   11         Console.WriteLine((Thread.CurrentThread.Name ?? "m ") +

   12             " @ " + (DateTime.Now - _st).TotalSeconds + ": " + msg);

   13     }

   14 }

   15 

   16 public class DBContext : IDisposable {

   17     public string ConnectionString { get; private set; }

   18     private readonly SqlConnection _conn;

   19     private readonly SqlTransaction _tx;

   20 

   21     public DBContext(string connectionString) {

   22         ConnectionString = connectionString;

   23         _conn = new SqlConnection(connectionString);

   24         _conn.Open();

   25         _tx = _conn.BeginTransaction();

   26         Logger.Log("Enter Transaction");

   27     }

   28 

   29     public int ExecuteIntQuery(string sql) {

   30         using (IDbCommand cmd = _conn.CreateCommand()) {

   31             try {

   32                 Logger.Log("Starting " + sql);

   33                 cmd.CommandText = sql;

   34                 cmd.CommandTimeout = 5;

   35                 cmd.Transaction = _tx;

   36                 return (int)(cmd.ExecuteScalar() ?? 0);

   37             } finally {

   38                 Logger.Log("Done     " + sql);

   39             }

   40         }

   41     }

   42 

   43     public void Dispose() {

   44         Logger.Log("Commit Transaction");

   45         _tx.Commit();

   46         _conn.Close();

   47     }

   48 }

   49 

   50 public static class IdGen {

   51     public static int GetNewIdInSeparateTransaction(DBContext cxt) {

   52         using (new DBContext(cxt.ConnectionString)) {

   53             return cxt.ExecuteIntQuery(

   54                 "UPDATE fwk_id SET ct = ct + 1; SELECT ct FROM fwk_id"

   55             );

   56         }

   57     }

   58 }

   59 

   60 #endregion An SQL Connection And Id Generation Framework

   61 

   62 #region An Application

   63 

   64 class Program {

   65     static void Main() {

   66         const string connString = @"server=.\SQLEXPRESS;Initial Catalog=MyToyDatabase;Integrated Security=SSPI";

   67         using (var setup = new DBContext(connString)) {

   68             setup.ExecuteIntQuery(@"

   69                     BEGIN TRY DROP TABLE fwk_id END TRY

   70                     BEGIN CATCH END CATCH;

   71                     CREATE TABLE fwk_id (ct INTEGER);

   72                     INSERT INTO fwk_id VALUES(1000)");

   73         }

   74 

   75         var t1 = new Thread(() => {

   76             int newId;

   77             using (var cxt = new DBContext(connString)) {

   78                 cxt.ExecuteIntQuery("WAITFOR DELAY '00:00:02'");

   79                 newId = IdGen.GetNewIdInSeparateTransaction(cxt);

   80                 cxt.ExecuteIntQuery("WAITFOR DELAY '00:00:03'");

   81             }

   82             Logger.Log("Result = " + newId);

   83         }) { Name = "t1" };

   84 

   85         var t2 = new Thread(() => {

   86             int newId;

   87             using (var cxt = new DBContext(connString)) {

   88                 cxt.ExecuteIntQuery("WAITFOR DELAY '00:00:01'");

   89                 newId = IdGen.GetNewIdInSeparateTransaction(cxt);

   90             }

   91             Logger.Log("Result = " + newId);

   92         }) { Name = "t2" };

   93         t1.Start(); t2.Start();

   94         t1.Join(); t2.Join();

   95     }

   96 }

   97 

   98 #endregion An Application

   99 

If you run this code, everything works fine. However, if you increase the time in line 80 from 3 seconds to 5, you get a timeout exception.