Monitored Lock

Example.cs

/*
 * This is an example console application to illustrate the usage
 * of the MonitoredLock class and technique.
 */
using System;
using System.Diagnostics;
using System.Threading;

namespace MonitoredLock
{
    public static class Example
    {
        private static object _lockObj = new object();
        public static object LockObj
        {
            get { return _lockObj;}
        }

        public static void OtherStuff()
        {
            Thread.Sleep(1000);
            using (new MonitoredLock(_lockObj, "LockObj"))
            {
                Console.WriteLine();
                Console.WriteLine("** Entered other thread's locked statement");
                Console.WriteLine();
            }
            Thread.Sleep(1000);
            using (new MonitoredLock(_lockObj, "LockObj"))
            {
                Console.WriteLine();
                Console.WriteLine("** Entered other thread's locked statement AGAIN");
                Console.WriteLine();
            }
        }

        public static void Main()
        {
            //Trace.Listeners.Add(new ConsoleTraceListener());
            //Trace.Indent();

            Console.WriteLine("** Started!");
            Console.WriteLine();

            var thread = new Thread(OtherStuff)
                            {
                                Name = "Other Thread",
                                IsBackground = false            
                            };
            thread.Start();

            try
            {
                using (MonitoredLock.From(() => LockObj))
                {
                    Console.WriteLine();
                    Console.WriteLine("** Starting body of Main lock");
                    Console.WriteLine();
                    Thread.Sleep(1500);
                    using (MonitoredLock.From(() => LockObj))
                    {
                        Console.WriteLine("*** Nested lock!");
                    }
                    Thread.Sleep(1500);
                    Console.WriteLine();
                    Console.WriteLine("** Ending body of Main lock");
                    Console.WriteLine();
                }
                
                Thread.Sleep(500); // allow other thread to lock
                using (MonitoredLock.From(() => LockObj))
                {
                    Console.WriteLine();
                    Console.WriteLine("** Starting body of SECOND Main lock");
                    Console.WriteLine();
                    Thread.Sleep(1500);
                    throw new Exception();
                }
            }
            catch (Exception e)
            {
                Console.WriteLine("** Caught exception: " + e);
            }
            Console.ReadKey(true);
        }
    }
}

MonitoredLock.cs

using System;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Linq.Expressions;
using System.Runtime.CompilerServices;
using System.Runtime.InteropServices;
using System.Threading;

namespace MonitoredLock
{
    /// <summary>
    /// Used to simulate syntax of 'lock' statement but with logging of
    /// entry and exit of the lock. Intended to be used with the
    /// 'using' statement.
    /// </summary>
    [DebuggerStepThrough]
    public class MonitoredLock : IDisposable
    {
        private readonly static ConditionalWeakTable<object, Counter> LockDepthCounter = new ConditionalWeakTable<object, Counter>();
        private readonly string _callerFilePath;
        private readonly int _callerLine;
        private readonly string _callerName;
        private Counter _lockDepthCounter;
        private readonly string _lockName;
        private readonly object _lockObj;
        private readonly bool _lockWasTaken;
        private bool _disposed;

        public MonitoredLock(object lockObj, string lockName, [CallerFilePath] string callerFilePath = null, [CallerMemberName] string callerName = null, [CallerLineNumber] int callerLine = -1)
        {
            if (lockObj == null) throw new ArgumentNullException("lockObj");
            _lockObj = lockObj;
            _lockName = lockName ?? "<none>";
            _callerFilePath = callerFilePath;
            _callerName = callerName;
            _callerLine = callerLine;

            // Log that we're about to enter so it's clear who's waiting
            // if we can't immediately take out the lock
            LogMessage("WAIT ", false, false);
            
            // Actually take out the lock
            Monitor.Enter(_lockObj, ref _lockWasTaken);

            // Increment depth counter and log entry
            IncrementDepthCounter();
            LogMessage("ENTER", false, false);
        }

        /// <summary>
        /// <see cref="IDisposable"/> implementation.
        /// </summary>
        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }

        /// <summary>
        /// Dispose is where the lock is exited.
        /// </summary>
        protected virtual void Dispose(bool disposing)
        {
            if (_disposed) return;
            _disposed = true;

            if (_lockWasTaken)
            {
                // Write exit message and decrement before exiting lock to ensure that 
                // it will output before the next entry into the lock.
                LogMessage("EXIT ", true, disposing);

                DecrementDepthCounter();

                Monitor.Exit(_lockObj);
            }
        }

        /// <summary>
        /// Locates the counter for the lock object and increments it or
        /// creates a new counter and initializes it to 1.
        /// </summary>
        [Conditional("TRACE")]
        private void IncrementDepthCounter()
        {
            // Manage entry depth
            if (LockDepthCounter.TryGetValue(_lockObj, out _lockDepthCounter))
            {
                // Increment existing counter
                if (_lockWasTaken) _lockDepthCounter.Value++;
            }
            else
            {
                // Start new counter
                _lockDepthCounter = new Counter() { Value = 1 };
                LockDepthCounter.Add(_lockObj, _lockDepthCounter);
            }
        }
        /// <summary>
        /// Decrements a counter if there is one.
        /// </summary>
        [Conditional("TRACE")]
        private void DecrementDepthCounter()
        {
            if (_lockDepthCounter == null) return;

            // Decrement depth
            _lockDepthCounter.Value--;
        }

        /// <summary>
        /// Log the current action.
        /// </summary>
        /// <param name="action">Name of the action.</param>
        /// <param name="isExit">Whether or not this is the exit message--slightly different formatting for this.</param>
        /// <param name="isDisposing"></param>
        [Conditional("TRACE")]
        private void LogMessage(string action, bool isExit, bool isDisposing)
        {
            var currentThread = Thread.CurrentThread;
            var exitInFinalizer = isExit && !isDisposing;

            var msg = string.Format("{0} Lock '{1}'{2} on thread '{3}' [{4};{5}]{6} at {7} in {8}:line {9}{10}",
                                 action,
                                 _lockName,
                                 null != _lockDepthCounter ? string.Format(" at depth {0}", _lockDepthCounter.Value) : null,
                                 currentThread.Name ?? "<No Name>",
                                 GetCurrentThreadId(),
                                 currentThread.ManagedThreadId,
                                 isExit ? " entered" : "",
                                 _callerName,
                                 _callerFilePath,
                                 _callerLine,
                                 exitInFinalizer ? " - WARNING: Lock was exited in finalizer!" : "");

            if (exitInFinalizer) 
                Trace.TraceWarning(msg);
            else 
                Trace.TraceInformation(msg);
        }

        /// <summary>
        /// Create a <see cref="MonitoredLock"/> from an expression.
        /// </summary>
        /// <param name="memberExpression">Expression from which the object reference and name of the lock object are obtained.</param>
        [SuppressMessage("ReSharper", "ExplicitCallerInfoArgument")]
        public static MonitoredLock From<T>(Expression<Func<T>> memberExpression, [CallerFilePath] string callerFilePath = null, [CallerMemberName] string callerName = null, [CallerLineNumber] int callerLine = -1)
        {
            var expressionBody = (MemberExpression)memberExpression.Body;
            return new MonitoredLock(memberExpression.Compile().Invoke(), expressionBody.Member.Name, callerFilePath, callerName, callerLine);
        }

        /// <summary>
        /// Implemente a finalizer because want to make absolutely sure the lock has been cleared.
        /// </summary>
        ~MonitoredLock()
        {
            Dispose(false);
        }

        /// <summary>
        /// Have to call into OS to get real thread id. May not be desirable on non-Windows platforms.
        /// </summary>
        [DllImport("kernel32.dll")]
        private static extern uint GetCurrentThreadId();

        /// <summary>
        /// This class only exists to provide a reference type for use with the ConditionalWeakTable above.
        /// </summary>
        private class Counter
        {
            public int Value { get; set; }
        }
    }
}