Performance miracles of ToString()

TL;DR — When printing primitive types (like int32 etc…) consider using a ToString() method for much (much!) better performance.

TL;DR2 — Some people should stop using the terms “Boxing”/”Unboxing” whenever they can’t explain something.

Background

A couple of days ago i had lunch with a friend of mine, lets call him Joe.
Joe had written a simple logging component for an enterprise application he was assigned to maintain. The program runs on a schedule on some server. His ecosystem consists mostly of .NET framework and C#.

Joe told me that after turning the logging “ON”, he experienced a non-trivial performance hit for his program. So we decided to turn our lunch in to a debugging hour.

What did this new component do? Well, when the component ran, it showed a Console with a very detailed logging information printing info at a speed of light (Well, time did not go backwards, so perhaps it was a bit slower than a speed of light).

I don’t want to go in to too much details on the business logic of his application, but 80% of the logging info was printing out numbers with some template text. Basically, the logging looked something like this:

int number = GetCurrentNumberState();
    Console.WriteLine("Current number state is: " + number);

Now, do you know what is happening on the second line where the logger actually prints the information to the console? You are right, you don’t need to know, it was written by Microsoft and its just a stupid PrintLine. They must have done amazing job maxing it’s performance.

Ok, i am with you there, but what if this action prints millions of lines a minute? I think it’s worth at least browsing through the code.

Empirical Part

I ran this piece of code in debug mode, debugger attached, win7 64bit machine.

int number = 42;
    long seconds;
Stopwatch watch = Stopwatch.StartNew();
    for (int i = 0; i < 100000; i++)
    {
        Console.WriteLine(number);
    }
    watch.Stop();
seconds = watch.ElapsedMilliseconds / 1000;
    Console.WriteLine("seconds = {0}", seconds);
The loop took 57 seconds to complete.
Can we do better? Lets try. (changes underlined)
int number = 42;
    long seconds;
Stopwatch watch = Stopwatch.StartNew();
    for (int i = 0; i < 100000; i++)
    {
        Console.WriteLine(number.ToString());
    }
    watch.Stop();
seconds = watch.ElapsedMilliseconds / 1000;
    Console.WriteLine("seconds = {0}", seconds);
This loop took 45 seconds to complete.
The improvement was a total of 15 seconds, meaning we shaved off a little more than 26% of the performance time for this program!
Technical explanation
I googled some articles on the matter, and most of them state that when you print a primitive type like an integer, your application performs Boxing of the primitive type and as we know this action is not free (performance wise). Is it really Boxing??
From my knowledge on the Boxing and Unboxing topics, this seemed somewhat strange, since the PrintLine() function is not expecting a reference type, so i decided to investigate the IL code that was generated by the compiler. I reviewed every little instruction and did not find anything related to Boxing or Unboxing.
The actual difference in performance is caused by the fact that when you pass a primitive type like an integer to PrintLine(), the .NET framework will call a native function (C++) called "FormatInt32", perform a conversion of each decimal to a char and return the whole string back to .NET.
Boxing would occur if the function was expecting a reference type. For example, if you look at the last line of my code-snippet, the call to
Console.WriteLine("seconds = {0}", seconds);
actually does box the "seconds" integer, because in this particular case the function expects an object.
Joe was pretty happy with the findings, in his case the solution of calling ToString() was a great one. I helped with his code, he payed for my drink in return. Win-Win.
If you are angry, mad or just happy about this post and want to share it with me – leave a comment.
Code on,
Shonn Lyga.