Troubleshooting a web service's speed

Question

C# .NET 2.0 if that turns out to be applicable.

I'm going to start to get to the bottom of why a web service we have is acting slow - this web service jumps over a proxy, into another domain, queries a stored procedure for some data, and then returns a int/string/dataset, depending on what I asked for. I just wrote a console app that queries it repeatedly in the same fashion so that I can gather some statistics to start out with.

Keep-alive is turned off for each request, for some legacy reason nobody documented, so there's an immediate smell.

When looping through the same request multiple times, I noticed some strange behavior. Here's my output that reflects how long each iteration took to make the query and return data.

Beginning run #1...completed in 4859.3128 ms
Beginning run #2...completed in 3812.4512 ms
Beginning run #3...completed in 3828.076 ms
Beginning run #4...completed in 3828.076 ms
Beginning run #5...completed in 546.868 ms
Beginning run #6...completed in 3828.076 ms
Beginning run #7...completed in 546.868 ms
Beginning run #8...completed in 3828.076 ms
Beginning run #9...completed in 3828.076 ms
Beginning run #10...completed in 578.1176 ms
Beginning run #11...completed in 3796.8264 ms
Beginning run #12...completed in 3828.076 ms
Beginning run #13...completed in 3828.076 ms
Beginning run #14...completed in 3828.076 ms
Beginning run #15...completed in 3828.076 ms
Beginning run #16...completed in 3828.076 ms
Beginning run #17...completed in 546.868 ms
Beginning run #18...completed in 3828.076 ms
Beginning run #19...completed in 3828.076 ms
Beginning run #20...completed in 546.868 ms
Total time: 61165 ms
Average time per request: 3058 ms

I find it odd that there are multiple repeated values, down to a very small level. Is there some bottleneck that would cause it to be returned in the same amount of time repeatedly?

...hopefully my code for figuring out and displaying the millisecond duration isn't off, but the TimeSpan object tracking it is local to each loop, so I don't think it's that.

EDIT: Jon asked for the timing code, so here ya go (variable names changed to protect the proprietary, so might have fat-fingered something that would make this not compile)...

int totalRunTime = 0;
for (int i = 0; i < numberOfIterations; i++)
{
    Console.Write("Beginning run #" + (i + 1).ToString() + "...");
    DateTime start = DateTime.Now;
    SimpleService ws = new SimpleService();
    DataSet ds = ws.CallSomeMethod();
    DateTime end = DateTime.Now;
    TimeSpan runTime = end - start;
    totalRunTime += (int)runTime.TotalMilliseconds;
    Console.Write("completed in " + runTime.TotalMilliseconds.ToString() + " ms\n");
}
Console.WriteLine("Total time: " + totalRunTime.ToString() + " ms");
Console.WriteLine("Average time per request: " + (totalRunTime / numberOfIterations).ToString() + " ms\n");

Answer 1

The simplest way, without running a profiler etc, is to make the web app log the exact time (as near as you can get it, obviously) it starts the operation, various times within the call, and the time it finishes. Then you can see where it's taking the time. (Using a Stopwatch will give you more accuracy, but it'll be slightly harder to do.)

I agree that it's odd that you've got repeated times. Could you post the code that's measuring it? I wouldn't be hugely surprised to see some sort of captured variable problem which is confusing your timings.

EDIT: Your timing code looks okay. That's very strange. I suggest you record the times at the web service as well, and see whether it looks the same. It's almost as if there's something deliberately throttling it.

When you run it, does it look like it's taking the amount of time it says it is - i.e. when it says it's taken 3 seconds, is that about 3 seconds after the last line was written?

Answer 2

now you need to get some benchmark values for the other steps in the chain. See the server logs to get the time your request hit the webserver, and add some logging into the webservice code to see when the webserver hands off to the actual "working" code.

Once you've done that you can start to narrow down the performance of the slowest part, repeat as much as you like.

Answer 3

Could creating (and timing the creation) of the SimpleService be skewing your numbers? What happens if you pull that out of the loop?

int totalRunTime = 0;
SimpleService ws = new SimpleService();
for (int i = 0; i < numberOfIterations; i++)
{
    Console.Write("Beginning run #" + (i + 1).ToString() + "...");
    DateTime start = DateTime.Now;
    DataSet ds = ws.CallSomeMethod();
    DateTime end = DateTime.Now;
    TimeSpan runTime = end - start;
    totalRunTime += (int)runTime.TotalMilliseconds;
    Console.Write("completed in " + runTime.TotalMilliseconds.ToString() + " ms\n");
}
Console.WriteLine("Total time: " + totalRunTime.ToString() + " ms");
Console.WriteLine("Average time per request: " + (totalRunTime / numberOfIterations).ToString() + " ms\n");