Writing to console char by char, fastest way

Question

In a current project of mine I have to parse a string, and write parts of it to the console. While testing how to do this without too much overhead, I discovered that one way I was testing is actually faster than Console.WriteLine, which is slightly confusing to me.

I'm aware this is not the proper way to benchmark stuff, but I'm usually fine with a rough "this is faster than this", which I can tell after running it a few times.

static void Main(string[] args)
{
    var timer = new Stopwatch();

    timer.Restart();
    Test1("just a little test string.");
    timer.Stop();
    Console.WriteLine(timer.Elapsed);

    timer.Restart();
    Test2("just a little test string.");
    timer.Stop();
    Console.WriteLine(timer.Elapsed);

    timer.Restart();
    Test3("just a little test string.");
    timer.Stop();
    Console.WriteLine(timer.Elapsed);
}

static void Test1(string str)
{
    Console.WriteLine(str);
}

static void Test2(string str)
{
    foreach (var c in str)
        Console.Write(c);
    Console.Write('\n');
}

static void Test3(string str)
{
    using (var stream = new StreamWriter(Console.OpenStandardOutput()))
    {
        foreach (var c in str)
            stream.Write(c);
        stream.Write('\n');
    }
}

As you can see, Test1 is using Console.WriteLine. My first thought was to simply call Write for every char, see Test2. But this resulted in taking roughly twice as long. My guess would be that it flushes after every write, which makes it slower. So I tried Test3, using a StreamWriter (AutoFlush off), which resulted in being about 25% faster than Test1, and I'm really curious why that is. Or is it that writing to the console can't be benchmarked properly? (noticed some strange data when adding more test cases...)

Can someone enlighten me?

Also, if there's a better way to do this (going though a string and only writing parts of it to the console), feel free to comment on that.

Answer 1

First I agree with the other comments that your test harness leaves something to be desired... I rewrote it and included it below. The result after rewrite post a clear winner:

//Test 1 = 00:00:03.7066514
//Test 2 = 00:00:24.6765818
//Test 3 = 00:00:00.8609692

From this you are correct the buffered stream writer is better than 25% faster. It's faster only because it's buffered. Internally the StreamWriter implementation uses a default buffer size of around 1~4kb (depending on the stream type). If you construct the StreamWriter with an 8-byte buffer (the smallest allowed) you will see most of your performance improvement disappear. You can also see this by using a Flush() call following each write.

Here is the test rewritten to obtain the numbers above:

    private static StreamWriter stdout = new StreamWriter(Console.OpenStandardOutput());
    static void Main(string[] args)
    {
        Action<string>[] tests = new Action<string>[] { Test1, Test2, Test3 };
        TimeSpan[] timming = new TimeSpan[tests.Length];

        // Repeat the entire sequence of tests many times to accumulate the result
        for (int i = 0; i < 100; i++)
        {
            for( int itest =0; itest < tests.Length; itest++)
            {
                string text = String.Format("just a little test string, test = {0}, iteration = {1}", itest, i);
                Action<string> thisTest = tests[itest];

                //Clear the console so that each test begins from the same state
                Console.Clear();
                var timer = Stopwatch.StartNew();
                //Repeat the test many times, if this was not using the console 
                //I would use a much higher number, say 10,000
                for (int j = 0; j < 100; j++)
                    thisTest(text);
                timer.Stop();
                //Accumulate the result, but ignore the first run
                if (i != 0)
                    timming[itest] += timer.Elapsed;

                //Depending on what you are benchmarking you may need to force GC here
            }
        }

        //Now print the results we have collected
        Console.Clear();
        for (int itest = 0; itest < tests.Length; itest++)
            Console.WriteLine("Test {0} = {1}", itest + 1, timming[itest]);
        Console.ReadLine();
    }

    static void Test1(string str)
    {
        Console.WriteLine(str);
    }

    static void Test2(string str)
    {
        foreach (var c in str)
            Console.Write(c);
        Console.Write('\n');
    }

    static void Test3(string str)
    {
        foreach (var c in str)
            stdout.Write(c);
        stdout.Write('\n');
    }

Answer 2

I've ran your test for 10000 times each and the results are the following on my machine:

test1 - 0.6164241  
test2 - 8.8143273    
test3 - 0.9537039  

this is the script I used:

 static void Main(string[] args)
        {
            Test1("just a little test string.");     // warm up
            GC.Collect();  // compact Heap
            GC.WaitForPendingFinalizers(); // and wait for the finalizer queue to empty
            Stopwatch timer = new Stopwatch();
            timer.Start();
            for (int i = 0; i < 10000; i++)
            {
                Test1("just a little test string.");
            }
            timer.Stop();
            Console.WriteLine(timer.Elapsed);
        }

Answer 3

I changed the code to run each test 1000 times.

    static void Main(string[] args) {
        var timer = new Stopwatch();

        timer.Restart();
        for (int i = 0; i < 1000; i++)
            Test1("just a little test string.");
        timer.Stop();
        TimeSpan elapsed1 = timer.Elapsed;

        timer.Restart();
        for (int i = 0; i < 1000; i++)
            Test2("just a little test string.");
        timer.Stop();
        TimeSpan elapsed2 = timer.Elapsed;

        timer.Restart();
        for (int i = 0; i < 1000; i++)
            Test3("just a little test string.");
        timer.Stop();
        TimeSpan elapsed3 = timer.Elapsed;

        Console.WriteLine(elapsed1);
        Console.WriteLine(elapsed2);
        Console.WriteLine(elapsed3);

        Console.Read();
    }

My output:

00:00:05.2172738
00:00:09.3893525
00:00:05.9624869

Answer 4

I also ran this one 10000 times and got these results:

00:00:00.6947374
00:00:09.6185047
00:00:00.8006468

Which seems in keeping with what others observed. I was curious why Test3 was slower than Test1, so wrote a fourth test:

timer.Start();
using (var stream = new StreamWriter(Console.OpenStandardOutput()))
{
    for (int i = 0; i < testSize; i++)
    {
        Test4("just a little test string.", stream);
    }
}
timer.Stop();

This one reuses the stream for each test, thus avoiding the overhead of recreating it each time. Result:

00:00:00.4090399

Although this is the fastest, it writes all the output at the end of the using block, which may not be what you are after. I would imagine that this approach would chew up more memory as well.