Profiling Lock Contention

The Improving .NET Application Performance and Scalability talk at PDC previewed of the new lock contention mode in the Visual Studio 2010 profiler. I haven’t seen a detailed list of capabilities, but starting at 57:15 in the video you can see that it appears to identify synchronization objects that cause threads to block, reports which locks have the highest contention, and records the total amount of time spent waiting. This sounds like a great way to identify why a concurrent app may be experiencing sub-linear speed-up.

There doesn’t appear to be any tools available right now that collect this information, so I wrote a TimedMonitor class to help identify the locks in my code that could be causing problems. To use it, you have to change the objects you’re locking on to instances of the TimedMonitor class. The Lock() method acquires a lock (using Monitor.Enter) and returns an IDisposable struct that releases the lock. (Returning a struct incurs no heap allocation, and the Dispose method gets inlined by the JIT, making this approach efficient.)

// Instead of:

object myLock = new object();
lock (myLock) { /* do work */ }

// Use:

TimedMonitor timedLock = new TimedMonitor();
using (timedLock.Lock()) { /* do work */ }
Console.WriteLine("Lock was entered {0} times; total wait time: {1}.",
    timedLock.EnterCount, timedLock.WaitTime);

The full code for TimedMonitor is at the end of this post. It uses a conditional directive named “ENABLE_TIMING”. If this is not set, the timing code isn’t compiled into the assembly, the JITter completely inlines the Lock method, and the performance of TimedMonitor is on par with the C# lock keyword. Otherwise, the timing code is executed; TimedMonitor.Lock() is about 30x slower than lock on my Core 2 Duo (which is fine for most cases, when this overhead is negligible compared to the work done inside the lock).

One final thing to note is that this code does not account for the case where thread A calls Monitor.Pulse, and thread B (which had called Monitor.Wait) wakes up and immediately has to block waiting for thread A to release the lock (so that thread B can re-acquire it before it returns from Monitor.Wait). The time B spends blocked will not be reported by TimedMonitor.

Update: The original code P/Invoked to QueryPerformanceCounter; I’ve since updated it to just use a Stopwatch (which simplifies the code and adds little additional overhead).

/// <summary>

/// Initializes a new instance of the <see cref="TimedMonitor"/> class.

/// </summary>

public TimedMonitor()
{
    // use a private lock so that clients must go through Lock()

    m_lock = new object();
#if ENABLE_TIMEDMONITOR
    m_sw = new Stopwatch();
#else
    m_sw = null;
    m_enterCount = 0;
#endif
    }
 
    /// <summary>

    /// Acquires an exclusive lock and records how long the acquisition took.

    /// </summary>

    /// <returns>An object that can be disposed to release the lock.</returns>

    public LockHolder Lock()
    {
#if ENABLE_TIMEDMONITOR
        m_sw.Start();
#endif
        Monitor.Enter(m_lock);
#if ENABLE_TIMEDMONITOR
        m_sw.Stop();
        m_enterCount++;
#endif
        return new LockHolder(m_lock);
    }
 
    // TODO: Implement Enter() and Exit() as separate methods for more

    //   complex locks that can't be wrapped in a 'using' block.

 
    // TODO: Implement Pulse, PulseAll, and Wait.

 
    /// <summary>

    /// Gets the number of times the lock was acquired.

    /// </summary>

    /// <value>The number of times the lock was acquired.</value>

    public long EnterCount
    {
        get { return m_enterCount; }
    }
 
    /// <summary>

    /// Gets the total time spent waiting to acquire the lock.

    /// </summary>

    /// <value>The total time spent waiting to acquire the lock.</value>

    public TimeSpan WaitTime
    {
        get { return m_sw == null ? TimeSpan.Zero : m_sw.Elapsed;  }
    }
 
    /// <summary>

    /// Releases the lock acquired by <see cref="TimedMonitor.Lock"/>.

    /// </summary>

    public struct LockHolder : IDisposable
    {
        /// <summary>

        /// Releases the lock.

        /// </summary>

        public void Dispose()
        {
            Monitor.Exit(m_lock);
        }
 
        internal LockHolder(object objLock)
        {
            m_lock = objLock;
        }
        
        readonly object m_lock;
    }
 
    readonly object m_lock;
    readonly Stopwatch m_sw;
    long m_enterCount;
}

Posted by Bradley Grainger on December 04, 2008