NHibernate Concurrency problem

Question

I have a S#arp Architecture app that implements a lightweight queue-processing thing whereby various threads pull entities from a list and set their status to mark the fact that processing has started on those items.

Despite wrapping the start-processing bit in explicit transactions and using a C# lock(), I still get them starting at the same time sometimes.

Do I regret not using MSMQ ... well, yeah, but now this concurrency behaviour has got me baffled. Evidently there's something that I don't understand about NHibernate transactions and flushing. Can you help me out?

Here's the relevant bits of code:

private static object m_lock = new object();

private bool AbleToStartProcessing(int thingId)
{
    bool able = false;
    try
    {
        lock (m_lock)
        {
            this.thingRepository.DbContext.BeginTransaction();
            var thing = this.thingRepository.Get(thingId);
            if (thing.Status == ThingStatusEnum.PreProcessing)
            {
                able = true;
                thing.Status = ThingStatusEnum.Processing;
            }
            else
            {
                logger.DebugFormat("Not able to start processing {0} because status is {1}",
                        thingId, thing.Status.ToString());
            }
            this.thingRepository.DbContext.CommitTransaction();
        }
    }
    catch (Exception ex)
    {
        this.thingRepository.DbContext.RollbackTransaction();
        throw ex;
    }
    if (able)
        logger.DebugFormat("Starting processing of {0}",
                        thingId);
    return able;
}

I would have expected this to guarantee that only one thread could change the status of a 'thing' at one time, but I get this in my logs pretty regularly:

2011-05-18 18:41:23,557 thread41 DEBUG src:MyApp.Blah.ThingJob - Starting processing of 78090
2011-05-18 18:41:23,557 thread51 DEBUG src:MyApp.Blah.ThingJob - Starting processing of 78090

.. and then both threads try and operate on the same thing and create a mess.

What am I missing? Thanks.

edit: changed code to reflect how my logging works in the real version

Havent had a chance to try your suggestions yet, but I will give it a go soon. — codeulike, May 23 '11 at 21:46

score 1 · Answer 1 · answered May 23 '11 at 17:06

1

Setup concurrency in your NHibernate mappings, this post should help you get started.

http://ayende.com/blog/3946/nhibernate-mapping-concurrency

answered May 23 '11 at 17:06

Rex Morgan

2,979
2
21
32

Wow, does this mean all that Nhibernate transaction code doesn't do anything unless the concurrency option is set somewhere? – codeulike May 23 '11 at 17:11
I'm not sure, but you can try this if you don't want to setup your mappings. `session.Lock(thing, LockMode.Upgrade);` – Rex Morgan May 23 '11 at 17:21

score 0 · Answer 2 · answered May 23 '11 at 17:13

0

i think you are just crossed up on the status you are using to set that you are processing and to check that you are already processing. first one in sets ThingStatusEnum.Processing, but the next guy is checking for something different - ThingStatusEnum.PreProcessing. because ThingStatusEnum.Processing != ThingStatusEnum.PreProcessing, your locking means two threads are not

answered May 23 '11 at 17:13

Dave Rael

1,759
2
16
21

But I don't get, even if there is a logical problem somewhere, how does the logger reports the same time if it is logging from within the critical section. It could be that the logger itself is not being accurate (Log4net?). Maybe try appending yourself the time to the log, and see if they actually collide, which seems unlikely. – Ernesto May 23 '11 at 17:24
hadn't noticed before that the times were exactly the same. you are right, that does indicate it's running simultaneously. shouldn't be possible with the static lock object. has nothing to do with nhibernate or s#arp architecture. multiple threads shouldn't be able to run that code at the same time regardless of any database interaction. if the lock object wasn't static, i'd think you were dealing with different instances, but i don't have an answer for you as is. i still say there's a flaw in the check on the status, but i can't explain the time in the log. – Dave Rael May 23 '11 at 20:55
@Ernesto,@Dave - oops, sorry guys, I 'simplified' the code when I posted it here, and moved the log statements. In my version the logging happens outside the lock - you are quite right that two logs at the same time are impossible with the posted code. I will edit the question. – codeulike May 23 '11 at 21:30
don't think there's a logic problem - the items start at PreProcessing status, and change to Processing when they are picked up. The aim of the code excerpt is to make sure only one thread can make that change at any one time. – codeulike May 23 '11 at 21:37
@codeulike - i know this was a long time ago, but i was looking back at some old stuff and saw this was still unanswered and looks like i didn't revisit after you updated. with your update, i'd say you are only doing one at a time. with the logging outside the lock, you have no restriction against logging at the same time, but the actually transaction is only happening one at a time. it seems you might think the lock would prevent the second transaction from happening - if you think that, it's a misconception - it just waits until the first completes and then continues. – Dave Rael Nov 12 '11 at 13:06

NHibernate Concurrency problem

2 Answers2