C# MongoDB Driver Concurrent Update Issue(with test code)

Question

I created following program to demonstrate the concurrent update issue in official C# mongodb driver. My test version: 1.9.0. Can you please help if I am missing something. I believe this is a bug in C# driver.

Explanation:

1. Program drops and creates new pages collection in mytest database.
2. Fills pages collection with 1000 pages with incremental ids.
3. Starts 2 update tasks, one forward and one backward loop for each.
4. According to logged data, there must be exactly 1000 updates in total.
5. Because there is a time condition check before each update.
6. Tests shows that there are around 1000~ updates. Non deterministic situation.
7. I can understand results greater than 1000 but can't understand results below 1000 which I can see 1 of 3 execution.

Any help appreciated. Thanks.

public class Document
{
    public int _id { get; set; }

    public long time { get; set; }
}
class Program
{
    MongoClient Client;
    MongoServer Server;
    MongoDatabase DB;
    MongoCollection<Document> Pages;

    int NextId = 0;
    DateTime TimeLimit;

    int TotalUpdate = 0;

    int totalPage = 1000;
    private void Start()
    {
        Client = new MongoClient("mongodb://localhost:9147");
        Server = Client.GetServer();
        DB = Server.GetDatabase("mytest");
        Pages = DB.GetCollection<Document>("pages");
        Pages.Drop();
        if (Pages.Count() > 0)
        {
            NextId = Pages.AsQueryable().Max(x => x._id);
        }
        else
        {
            Console.WriteLine(DateTime.Now + " Inserts started...");
            for (int i = 0; i < totalPage; ++i)
            {
                Pages.Save(new Document
                {
                    _id = Interlocked.Increment(ref NextId),
                    time = DateTime.Now.Ticks
                });
            }
            Console.WriteLine(DateTime.Now + " Inserts finished...");
        }

        TimeLimit = DateTime.Now;
        Thread.Sleep(500);
        List<Task> tasks =new List<Task>();
        tasks.Add(Task.Factory.StartNew(() => Updates()));
        tasks.Add(Task.Factory.StartNew(() => Updates2()));

        Task.WaitAll(tasks.ToArray());
        Console.WriteLine("Total Update: " + TotalUpdate);
        Console.WriteLine("Expected Total Update: " + totalPage);
    }

    private void Updates()
    {
        Console.WriteLine(DateTime.Now + " Updates 1 started...");
        Parallel.ForEach(Enumerable.Range(1, totalPage), (id) =>
        {
            try
            {
                if (id % 100 == 0)
                    Console.WriteLine(DateTime.Now + " Update1: " + id);
                var found = Pages.FindOne(Query.EQ("_id", id)).time;
                if (found < TimeLimit.Ticks)
                {
                    var res = Pages.Update(Query.EQ("_id", id), Update.Set("time", DateTime.Now.Ticks), UpdateFlags.Upsert, WriteConcern.Acknowledged);
                    if (res.DocumentsAffected > 0)
                        Interlocked.Increment(ref TotalUpdate);
                    else
                        Console.WriteLine(res.Response);
                }
            }
            catch(Exception e)
            {
                Console.WriteLine(e.Message);
            }
        });
        Console.WriteLine(DateTime.Now + " Updates 1 finished...");
    }

    private void Updates2()
    {

        Console.WriteLine(DateTime.Now + " Updates 2 started...");
        Parallel.ForEach(Enumerable.Range(1, totalPage), (id) =>
        {
            try
            {
                if ((id - 1) % 100 == 0)
                    Console.WriteLine(DateTime.Now + " Update2: " + (totalPage - id + 1));
                var found = Pages.FindOne(Query.EQ("_id", totalPage - id + 1)).time;
                if (found < TimeLimit.Ticks)
                {
                    var res = Pages.Update(Query.EQ("_id", totalPage - id + 1), Update.Set("time", DateTime.Now.Ticks), UpdateFlags.Multi, WriteConcern.Acknowledged);
                    if (res.DocumentsAffected > 0)
                        Interlocked.Increment(ref TotalUpdate);
                    else
                        Console.WriteLine(res.Response);
                }
            }
            catch(Exception e)
            {
                Console.WriteLine(e.Message);
            }
        });
        Console.WriteLine(DateTime.Now + " Updates 2 finished...");
    }

    static void Main(string[] args)
    {
        new Program().Start();
    }
}

Answer 1

That happens because DateTime.Now.Ticks is not very precise and will often return the same value. Have you looked at the data you're creating? Many time values are equal (depending on how fast your machine is).

The collision can only happen in the middle where the two walking directions meet. The problem should worsen dramatically when you make them walk in the same way.

Use the performance counter to get high-resolution times, use a counter instead, or change the comparison from if (found < TimeLimit.Ticks) to if (found <= TimeLimit.Ticks). The latter will give you results larger than expected from time to time, but never lower than expected.

EDIT

Maybe I'm missing something, but I'm not sure your test can provide reproducible results at all. The check if found < TimeLimit will always fail once the other thread has finished. However, in the other thread, the check if found < currentTime() (where currentTime is a high-performance timer) will practically always result in true, even if the other thread had just updated the document a microsecond before. So the test should yield roughly 1,500 updates, not 1,000. The roughness depends on the precision of the timer and the machine's performance.