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);
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]
});
}
Logs.Log(string.Format("{2}Responded to New notice from {0} with:{1}", ident, _errorCodes[responseId], requestIdStr));
return _errorCodes[responseId];
}
catch (Exception exception)
{
Logs.LogException(exception);
return new Response("x99", exception.ToString());
}
}
My logging in my test harness is as follows:
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?