Why is the speed of Console.WriteLine more inconsistent than Debug.WriteLine?

Question

This code outputs almost all 0's with an occasional output of 3-5.

For i As Integer = 1 To 1000
    Dim Watch As Stopwatch = Stopwatch.StartNew()
    Debug.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time1")
    Debug.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time2")
Next

This code outputs almost all 0's with an occasional output of 200.

For i As Integer = 1 To 1000
    Dim Watch As Stopwatch = Stopwatch.StartNew()
    Console.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time1")
    Console.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time2")
Next

Any ideas why?

The only difference is Console.WriteLine. Also, it seems having two WriteLines per loop is important for some reason.

I found this out while trying to time my code speed and got seemingly random 150ms spikes during a loop.

Answer 1

Luckily for us Microsoft has released the source code of the .NET platform here

A quick inspection shows that Debug.Writeline uses the Writeline method of the TraceInternal class. You can see an example here and the TraceInternal method here

As you can see there are a lot of stuff going on involving hooked TraceListeners, locks etc. So we can assume that Debug.WriteLine should be slower in general but only if there are any "extra" TraceListeners configured and of course other IDE parameters that in some way interfere with the Debug infrastructure.

The Console.WriteLine method uses the TextWriter.WriteLine method which is designed to be fast (at least as fast as possible, take a look at their comments).

About the inconsistency that you ask it isn't easy to answer (and IMO you should not try to answer) because of three reasons:

1. When you are developing in a high level language or platform like .NET then you should not bother of how much time the "internals" take because you can not have any control on them. I mean that you cannot make the WriteLine methods faster unless you write your own "faster" versions but that beats the purpose of using a high level platform anyway. I hope you can see my point here.
2. When you are using some methods (like WriteLine) in order to output the time some other code of yours took to execute then you should not bother how much time the output method takes to complete as long as the result is accurate. If for example the WriteLine takes 2 seconds to show you that the code you are measuring took 1ms to complete then the 1ms is what matters even though you waited 2 seconds to find it out. If the output method is too slow then you should change your measuring method, in your case, for example, it might be faster to have a counter variable in your loop and display (WriteLine) the result at the end of it.
3. When you are developing software intended to run in multi tasking systems like windows you should not expect that the same code will always take the same time to execute every time simply because there are a ton of other (outside your app) parameters that can (and will) affect the overall performance of the system. That's why (and I am sure that you already know it) we have the restart option in a very easy to access place (LOL).

Nevertheless to finalize my answer the inconsistency of your timings depends on many factors that makes it worthless to find out why it happens. However, in your code I noticed that you are using the statement:

Dim Watch As Stopwatch = Stopwatch.StartNew()

inside the loop which is a bad thing to do because as you can see in the Stopwatch code here it creates a new instance every time which is a time consuming operation. I believe that if you have it outside of the loop like:

Dim Watch As Stopwatch = Stopwatch.StartNew()
For i As Integer = 1 To 1000
    Debug.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time1")
    Debug.WriteLine(Watch.ElapsedMilliseconds & " - Processing Time2")
Next

You will get more "consistent" results but I haven't test it though. Moreover it might be wiser to use higher timing resolution like

Watch.ElapsedTicks

because it will give you more accurate results and because if you look at the source code here ElapsedMilliseconds uses a slightly different version (maybe slower) of ElapsedTicks to calculate the milliseconds.

Hope this helps.