Why is my web service taking 11 seconds to respond

See more:

C#

WCF

webservice

Hi,

Before you say "Because your code takes that long to run", just look:

This is running on my local machine.

I have recently added logging. The log takes DataTime.Now and adds that to the string to be logged. It then puts that string into a queue to be written in the log file. This means that the log might not be updated immediately, but the times are accurate.

I have a web service to consume requests (big objects get thrown at it. About 2-6Kb).
I have a test harness that throws objects at it constantly so I can try to break it (still trying).

My logging in my web service is as follows:

public Response SendDetails(Details details, string ident, Guid accessGuid, object syncState)
{
    string requestIdStr = "";
    int requestId;
    if (int.TryParse(syncState.ToString(), out requestId))
        requestIdStr = string.Format("{0:D4}: ", requestId);

    //Log before all the work
    Logs.Log(string.Format("{1}New notice from {0}", ident, requestIdStr));
    int responseId = 0;
    try
    {
        if [Boring validation stuff ]
        else
        {
            ThreadPool.QueueUserWorkItem(delegate
            {
                [The Heavy Lifting work]
            });
        }
        //log after all the work (just before return)
        Logs.Log(string.Format("{2}Responded to New notice from {0} with:{1}", ident, _errorCodes[responseId], requestIdStr));
        return _errorCodes[responseId];
    }
    catch (Exception exception)
    {
        //This hasn't happened in a while.
        Logs.LogException(exception);
        return new Response("x99", exception.ToString());
    }
}

My logging in my test harness is as follows:

//Log just before and after web call
Logs.Log("{0:D4}: Sending to secure access service", userstate);
client.SendDetails(details, "x", Guid.Parse([NDA]),userstate);
Logs.Log("{0:D4}: Sent to secure access service", userstate);

So: The service log says:

12:03:37:918	SendDetails     '0009: New notice from x'
12:03:37:920	SendDetails     '0009: Responded to New notice from x with:[x00] Success'

So 2 milliseconds to do all the work

The testharness log:

12:03:37:912	WriteLine             '0009: Sending to secure access service'
12:03:48:858	WriteLine             '0009: Sent to secure access service' 

To conclude:
It takes 0.006 seconds to send the request, 0.002 seconds to process the request and then ~11 seconds to send the response?

What the heck?

PS: In case you think that Response is at fault, here is that class too:

[DataContract]
public class Response
{
    [DataMember]
    public string ResponseCode { get; set; }
    [DataMember]
    public string ResponseDetail { get; set; }

    public Response(string responseCode, string responseDetail)
    {
        ResponseCode = responseCode;
        ResponseDetail = responseDetail;
    }

    public override string ToString()
    {
        return string.Format("[{0}] {1}", ResponseCode, ResponseDetail);
    }
}

UPDATE: i have run the service trace as Richard D suggested:

Some are quick: 
Message Sent - 12:41:51.3914836
Message Received - 12:41:51.3994892

Some, not so much
Message Sent - 13:42:22:23798318
Message Received - 13:42:40.6326977

Is there anything else I can glean from these?