0

We are debugging some performace problems and have notice some strange results from stopwatch.

  1. We have a client that calls a web service
  2. We log the time at the service layer og the web service with stop watch
  3. We log the time at the lower layer with datetime.now.ticks

Layer 2 is just a pass through layer with 2 lines of logging.

The times recorded are:

  1. 110 ms
  2. 52125 ms
  3. 125 ms

We had expected 2 to be less than 1, although no api is accurate to 1 ms.

We create a new stopwatch in each service call so this is not the time of an old stopwatch thar has been restarted.

Anyone know why we are getting these figures?

Edit

2 and 3 are on the same machine and the same app domain

The stopwatch code is:

            var sw = new Stopwatch();
            sw.Start();

            //code to call layer 3

            sw.Stop();
            orchestrationContext.LogOperationTime(functionName, sw.ElapsedMilliseconds);

logging of time in layer 3

    protected DateTime StartTime { get; set; }
    StartTime = DateTime.Now;

    // code 

    new TimeSpan(DateTime.Now.Ticks - StartTime.Ticks).Milliseconds

The logging of 1 is on a seperate machine, logging using Websphere.

Shiraz Bhaiji
  • 64,065
  • 34
  • 143
  • 252
  • 1
    Show us the code of the time calculation! I expect errors there. E.g. Milliseconds instead of TotalMilliseconds – Emond Aug 28 '12 at 08:29
  • You log the time with the `StopWatch`? Aren't your layers running in different application domains? Are they running on the same machine? Please show the code for how you get these numbers. – Jodrell Aug 28 '12 at 08:33
  • You calculation for layer 3 should be `new TimeSpan(DateTime.Now - StartTime).TotalMilliseconds` – Lee Aug 28 '12 at 08:59
  • If you want to use `DateTime` for timing you should use `DateTime.UtcNow`, not `DateTime.Now`. The second is much slower than the first because it has to handle timezones. – Martin Liversage Aug 28 '12 at 09:12
  • @MartinLiversage yes but, why wouldn't you just use a `StopWatch` in this case. – Jodrell Aug 28 '12 at 09:17
  • 1
    @Jodrell: `StopWatch` is better than `DateTime.UtcNow` but you can only use it to perform timings in a single process. If you want to perform timings between multiple processes or hosts (as apparently it is done in the question) you need to record the time, and my comment was simply that you should prefer `DateTime.UtcNow` over `DateTime.Now`. – Martin Liversage Aug 28 '12 at 09:23
  • Also see http://stackoverflow.com/questions/394020/how-accurate-is-system-diagnostics-stopwatch?rq=1 and http://stackoverflow.com/questions/795377/what-if-any-is-the-resource-penalty-for-using-system-diagnostics-stopwatch – nawfal Apr 22 '13 at 12:24

2 Answers2

3

Okay, your second code sample should be returning TimeSpan.TotalMilliseconds, using just Milliseconds you will get the sub second part.

Why aren't you using a StopWatch in the layer 3 code, in the same style as your layer 2 code, it is more accurate?

Your question title is "Correctness of StopWatch" but it seems you are comparing bananas with peaches and apples. StopWatch will use a HighResolution timer if supported by your hardware or operating system otherwise it will fallback to a System.Timer which offers a granularity of around 15ms.

I can't comment on how or whether to use WebSphere but it will not offer more accurate timing than StopWatch unless it uses an API to some other high accuracy time source.

Jodrell
  • 34,946
  • 5
  • 87
  • 124
1

As I guessed:

new TimeSpan(DateTime.Now.Ticks - StartTime.Ticks).TotalMilliseconds

TotalMilliseconds gets the timespan in milliseconds

Millisecond gets the millisecond part of the timespan

Emond
  • 50,210
  • 11
  • 84
  • 115