Timing locks in C#

By John Hurliman (Intel) (2 posts) on December 2, 2008 at 12:28 pm

A recent post to the opensim-dev mailing list highlighted a common problem in debugging complex C# code. Somewhere, a lock is being held for a long period of time and holding up other threads, bringing the entire system to a halt while the task completes. Debugging with Mono and gdb has the useful mono_locks_dump, but this is better suited for resolving deadlock situations. If you have a thread that is holding a lock for "only" 500ms, it's very difficult to dump all the lock information at the correct time. Even if you do manage to get the timing right, there's no way to know which of the current locks is taking too long. The solution I came up with is to inject code that measures the length of time locks are held.

LockTime

>LockTime.exe
-a, --assembly=VALUE       assembly to insert lock timers into
-v, --verbose              be verbose
-h, -?, --help             show this help

LockTime is a small snippet of code I wrote to measure the amount of time spent inside locks. It uses Mono.Cecil to load a managed assembly, look for locks, and inject CIL that measures lock timing. The usage is very simple. You feed it the name of an assembly, and it will produce a new assembly alongside the original that contains lock timing code. For example, if you run the command LockTime.exe -a LockTest.exe, it will produce a new LockTest-LockTime.exe binary. This program works on any managed assembly, including both .exes and .dlls. If a lock using a measurable amount of time is detected, the injected code will print out a line to the console similar to this:

*** LOCK in System.Void MyNamespace.MyApp::MyFunction(): 15

LockTime is provided free of charge under the BSD license. It includes the Mono.Cecil library and Mono.Options code which are both released under the MIT/X11 license.

Download LockTime v1.0

How It Works

In C#, locking is accomplished through the System.Threading.Monitor class. The following code:

lock (object)
{
    ...
}

is shorthand syntax for:

Monitor.Enter(object);
try
{
    ...
}
finally
{
    Monitor.Exit(object);
}

In CIL, this looks roughly like:

// Store the object to lock to a local variable
stloc.0
// Load our local variable onto the evaluation stack
ldloc.0
// Call Monitor.Enter() with our object
call void [mscorlib]System.Threading.Monitor::Enter(object)
.try
{
    // Leave the try block. Usually there would be other code here as well
    leave.s    IL_001c
}
finally
{
    // Load our local variable onto the evaluation stack again
    ldloc.0
    // Call Monitor.Exit() with our object to free the lock
    call void [mscorlib]System.Threading.Monitor::Exit(object)
    // Leave the finally block
    endfinally
}

LockTime injects code right after the Monitor.Enter() and Monitor.Exit() calls. The first injected code block simply stores Environment.TickCount to a new local variable that is created with Mono.Cecil. The second block of injected code gets the current Environment.TickCount again and subtracts the previous value. The result is stored where the original TickCount was previously stored. If the result is not zero, then Console.Write() and Console.WriteLine() are called to print out a string containing the current method name and the stored difference between the two TickCounts (length of time in milliseconds spent in the lock). If the result is zero, then the printing code is skipped. Since the time comparison is calculated after the lock is released, only two opcodes are injected inside the lock (reading Environment.TickCount and storing to a local variable). In other words, the new code will not measure itself in any significant way. However, one branching instruction is added after every lock, and if the lock was held for a non-zero number of milliseconds, it will call two print statements that add to the time spent in that method. Additionally, injecting strings for every function name that contains a lock can add a significant amount of data to the assembly.

Future Improvements

Environment.TickCount is not the most accurate measurement device for execution timing. If slow locks in your program are not taking at least 100ms to execute, those slow locks will fail to print warnings consistently. Changing to System.Diagnostics.StopWatch will yield much more accurate timing.
Any locks that take a (measured) non-zero amount of time to execute will print to the console. I implemented the measurement this way because it's very convenient to test for at the CIL level (loading the variable onto the evaluation stack and branching with brfalse). It would be nice to add a comparison with a user-specified threshold.

Categories: Open Source, Software Engineering

Comments (0)

Trackbacks (0)

To obtain technical support, please go to Software Support.

Intel® Software Network