Console.WriteLine speeds up my code?

Question

I have been looking into speeding up my application as it is performance critical... i.e. every millisecond I can get out of it is better. To do this I have a method that calls some other methods and each of these other methods is wrapped with a Stopwatch timer and Console.WriteLine calls. I.e.:

private void SomeMainMethod()
{
    System.Diagnostics.Stopwatch sw = new System.Diagnostics.Stopwatch();
    sw.Start();
    SomeMethod();
    sw.Stop();
    Console.WriteLine("Time for SomeMethod = {0}ms", sw.ElapsedMilliseconds);

    sw.Reset();
    sw.Start();
    SomeOtherMethod();
    sw.Stop();
    Console.WriteLine("Time for SomeOtherMethod= {0}ms", sw.ElapsedMilliseconds);

    //...
}

The problem is whenever I comment out the Stopwatch and Console.WriteLine lines the code runs about 20ms (not 50) slower which is a lot for what I need.

Does anyone know why this is?

EDIT: The SomeMainMethod method and others in the class are also wrapped in a Stopwatch and Console.WriteLine calls similar to above.

The SomeMainMethod and the methods it calls is part of a class that is part of a Class Library that is called from a console testbed, all of which is single threaded.

For more information: The app is running in x86 .NET 4.6.1 Release mode with optimisations enabled. I am also running this in visual studio 2013 not outside of it.

That does sound freaky odd.. I cant say Ive noticed changes in speed like that — BugFinder, May 09 '16 at 15:27
If you're not using the Stopwatch, you're _not measuring the time in the same way_. Have you accounted for that? — stuartd, May 09 '16 at 15:27
@stuartd but hes saying that by removing the stopwatch and displays its *slower*, not faster? so theres less code — BugFinder, May 09 '16 at 15:29
Is this app using multiple threads, for example ASP.NET or PLINQ? — Tim Schmelter, May 09 '16 at 15:32
@TimSchmelter It is a single threaded app, actually part of a class library called from a console app testbed — TheLethalCoder, May 09 '16 at 15:34
@stuartd The whole class calls are wrapped in a `Stopwatch` so the overall time of the code goes up, including what is shown in the question — TheLethalCoder, May 09 '16 at 15:34
Can you [create a Minimal, Complete, and Verifiable example](http://stackoverflow.com/help/mcve)? — Matteo Umili, May 10 '16 at 07:11
Are you running your code with debugger attached (F5) or detached(ctrl + f5)? — Bruno Costa, May 13 '16 at 07:51
@BrunoCosta With it attached, if you look at my answer you'll see what I believe was causing this — TheLethalCoder, May 13 '16 at 07:56
A basic loop with one instrucion, i++, will be 6 times slower when running in debug mode. Actual performance can only be determined by running with no debugger attached — Patrick, May 20 '16 at 08:02
@Patrick Oh I know I've tested outside of the debugger in release mode as well. I believe my answer was the culprit, i.e. `Console.WriteLine` was allowing my thread more processing time. — TheLethalCoder, May 20 '16 at 08:13

score 2 · Accepted Answer · edited May 23 '17 at 12:31

After reading a very similar question with no answers I may have found the issue. In the comments section a user (ForguesR) made the following comment:

It is really a big guess : maybe because you are writing to IO your thread gets more processor time because WriteLine is synchronized and thus blocking other threads.

So I wanted to check if this was indeed the case so I changed SomeMainMethod to like the following:

NOTE: It is generally not advised to play around with thread priorities, this was only a workaround to test the theory. I would strongly advise against doing this in production code unless you are 100% sure you know what you are doing. Then probably still stay away from it.

private void SomeMainMethod()
{
    System.Threading.ThreadPriority tp = System.Threading.ThreadPriority.Normal;
    try
    {
        tp = System.Threading.Thread.CurrentThread.Priority;

        System.Threading.Thread.CurrentThread.Priority = System.Threading.ThreadPriority.Highest;

        System.Diagnostics.Stopwatch sw = new System.Diagnostics.Stopwatch();
        sw.Start();
        SomeMethod();
        sw.Stop();
        Console.WriteLine("Time for SomeMethod = {0}ms", sw.ElapsedMilliseconds);

        sw.Reset();
        sw.Start();
        SomeOtherMethod();
        sw.Stop();
        Console.WriteLine("Time for SomeOtherMethod= {0}ms", sw.ElapsedMilliseconds);

        //...
    }
    finally
    {
        System.Threading.Thread.CurrentThread.Priority = tp;
    }
}

After making this change my code now runs consistently faster (~10ms) when the Console and Stopwatch lines are commented out. Therefore I believe his comment was probably correct, at least in my situation.

Out of interest, what if you were to perform SomeMethod a hundred times. My guess is that CPU throtling is infact the culprit (seemingly cured by Console.Write). Are you in High Performance mode? Balanced mode will take one second to 'spin up' - and it will also be shy of full turbo speeds. And you say 10ms is a significant amount of time for you, but 10ms is easily going to be introduced if the code is run on a slower computer. — Patrick, May 25 '16 at 02:08
@Patrick My PC is terrible so the code should never be run on anything worse. And I did run the code a lot of times without restarting — TheLethalCoder, May 25 '16 at 09:23

Console.WriteLine speeds up my code?

1 Answers1

Linked