There will be times when threads end up waiting for a lock or access to a critical section when synchronizing code. Through planning, design and the proper patterns these times can be minimized. However good the design or theory it is always good to get real data on how fast the code is running. This is a class I came up with that handles multiple threads generating timing data at the same time. This class has lots of ways it can be improved, I mention a few while going through it, and because it will synchronize its own calls into the class it can not be used to debug a lock situation, only to time the duration inside locks or other branches of working, or bug lite, code.

For code that deals with basic locking check out this post on a locking pattern I wrote a class around.

The basics of the class are that it calculates the Mean, Max, Min, Median, and Range of calls to Start and Stop. One thread can call Start / Stop or the calls can be made from different call backs by providing an id to synchronize them on. e.g. like this.GetHashCode etc.. There is also the option to provide an ILog object, like the one used by Log4Net, to provide automatic statical logging of the performance of this object.

public Timed(int maxSample)
    :this (maxSample, null, TimeSpan.Zero, "") { }

public Timed(int maxSample, ILog log, TimeSpan reportInterval, string logIdString)
{
    _maxSample = maxSample;

    if(log != null)
    {
        _log = log;
        _logNameTag = logIdString;
        TimerCallback callBack = new TimerCallback(Log);
        _timer = new Timer(callBack, null, reportInterval, reportInterval);
    }
}

The next thing is to code the call back for the timer. The function should match the prototype of the TimerCallback. So make it return void and take an object, which you may or may not use to pass information into your call back. All my data is in the class and access is being synchronized so the use of a callback object is not needed.

private void Log(object o)
{
    _repoprtingLock.AcquireReaderLock(Timeout.Infinite);
    _log.Info(string.Format(
        "{0} - Mean: {1} / Max: {2} / Min: {3} / Median {4} / Range {5}",
         _logNameTag, Mean, Max, Min, Median, Range));
    _repoprtingLock.ReleaseLock();
}

The rest of the code is fairly straight forward. I put in lots of comments for the Linq statements for anyone who is not familiar.

The Start and Stop functions were where I began. Calling them with out any parameters allows you to use the id of the current thread as the timing tag. This way multiple concurrent calls to the code will produce accurate time stamps. Otherwise one thread could call start right after another and change the results. In cases where different threads will start and stop the code you can pass in a unique id. This was in case two different handlers running in separate threads were responsible for a start and stop.

public void Start()
{
    Start(Thread.CurrentThread.GetHashCode());
}

public void Start(int key)
{
    lock (_timeLock)
    {
        _starts[key] = DateTime.Now;
    }
}

public TimeSpan Stop()
{
    return Stop(Thread.CurrentThread.GetHashCode());
}

public TimeSpan Stop(int key)
{
    //Record the time now so when we get the lock
    // the timing will be accurate.
    DateTime now = DateTime.Now;
    TimeSpan span = TimeSpan.Zero;

    lock (_timeLock)
    {
        span = now - _starts[key];
    }

    _repoprtingLock.AcquireWriterLock(Timeout.Infinite);
    _statsLock.AcquireWriterLock(Timeout.Infinite);
    //If the list is full of samples make room by pruning the oldest
    if (_times.Count >= _maxSample) _times.RemoveAt(0);
    _times.Add(span);
    _statsLock.ReleaseLock();
    _repoprtingLock.ReleaseLock();
    return span;
}

Max is very simple. We lock access to _times and call .Max().

public TimeSpan Max
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        span = _times.Count > 0 ? _times.Max() : TimeSpan.Zero;
        _statsLock.ReleaseLock();

        return span;
    }
}

Min works the same way as Max.

public TimeSpan Min
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        span = _times.Count > 0 ? _times.Min() : TimeSpan.Zero;
        _statsLock.ReleaseLock();

        return span;
    }
}

Range is basically the same a Min and Max.

public TimeSpan Range
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        if (_times.Count == 0) span = TimeSpan.Zero;
        else span = _times.Max() - _times.Min();
        _statsLock.ReleaseLock();

        return span;
    }
}

Finding the Mean is the average of the values. This can be found with .Average but I used .Aggregate in case you decide to use a type that dose not support .Average.

public TimeSpan Mean
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        if (_times.Count == 0) span = TimeSpan.Zero;
        else
            span = new TimeSpan(
                //Use Aggregate to sum the TimeSpans
                _times.Aggregate((total, next) => total + next)
                //Convert to ticks for division
                .Ticks / _times.Count
                //TimeSpan constructor takes result as it's argument
                );
        _statsLock.ReleaseLock();

        return span;
    }
}

The Median is the middle value of the list. If there are an even number of values then it is the average of those numbers. Before we do this we have to sort the list first.

public TimeSpan Median
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        //These days memory is cheep and this
        // shorthand var is local in scope
        int count = _times.Count;
        _times.Sort();
        if (count == 0) span = TimeSpan.Zero;

        //If the list has an even number we take the average
        // of the two values in the middle
        if (count % 2 == 0)
        {
            span = new TimeSpan(
                //The addition returns a Timespan
                (_times[count / 2] + _times[(count / 2) + 1])
                //We have to convert to ticks to devide it by two
                .Ticks / 2
                //The Timespan constructor converts the ticks back
                );
        }
        else
        {
            //When odd, we have to add one
            span = _times[(count / 2) + 1];
        }
        _statsLock.ReleaseLock();

        return span;
    }
}

There are lots of places where the code could be cleaner if I were to use my Locked Class in place of the ReadWriterLocks. The class allows you to use short hand and return in the middle of a lock and not worry about releasing the lock you called. So the following code:

public TimeSpan Mean
{
    get
    {
        TimeSpan span;

        _statsLock.AcquireReaderLock(Timeout.Infinite);
        if (_times.Count == 0) span = TimeSpan.Zero;
        else
            span = new TimeSpan(
                //Use Aggregate to sum the TimeSpans
                _times.Aggregate((total, next) => total + next)
                //Convert to ticks for division
                .Ticks / _times.Count
                //TimeSpan constructor takes result as it's argument
                );
        _statsLock.ReleaseLock();

        return span;
    }
}

Would look like this:

public TimeSpan Mean
{
    get
    {
        using(new Locked(_statsLock, false))
        {
            if (_times.Count == 0) return TimeSpan.Zero;
            return new TimeSpan(
                //Use Aggregate to sum the TimeSpans
                _times.Aggregate((total, next) => total + next)
                //Convert to ticks for division
                .Ticks / _times.Count
                //TimeSpan constructor takes result as it's argument
                );
        }
    }
}