The hidden costs of allocations

I mentioned in a pervious post that we have a code quality gateway to make sure that all logging statements are wrapped in an if statement, to reduce the number of allocations when the user has logging turned off. This is done because logging can be expensive, and is often turned off, so there is no point in paying a penalty for stuff that isn’t working.

There seems to be some confusion about why this is done. Let us assume that we have the following logging code:

void Debug(string msg)
{
	if(IsDebugEnabled)
		Console.WriteLine(msg);
}
void Debug(string format, params object[] args)
{
	if(IsDebugEnabled)
		Console.WriteLine(format, args);
}
void Debug(Func<string> generateMsg)
{
	if(IsDebugEnabled)
		Console.WriteLine(generateMsg());
}

Now, the obvious bad example would be to use:

Debug("Hello "+ user.Name);

Since that is going to allocate a new string, and this will happen regardless of whatever logging is enabled or not. On high frequency call sites, this can end up allocating a lot of useless stuff.

So we will move to this mode:

Debug("Hello {0}", user.Name);

And we saved the allocation, right? Except that this actually generate this code, do you see the allocation now?

Debug("Hello {0}", new[] { user.Name });

So let us introduce a better option, shall we? We’ll add a few common overloads without the use of params.

void Debug(string format, object p1);
void Debug(string format, object p1, object p2);
void Debug(string format, object p1, object p2, object p3);

And now we saved the allocation. Unless…

int requestNumber = ...;
Debug("Request # {0}", requestNumber);

Do you see the allocation now? We pass an int to a object, which require us to do boxing, which is an allocation .

So let us try using the lambda method, this way nothing is executed!

Debug(() => return "Hello " + user.Name);

Except… this is actually translated to:

var loggerMsg = new LoggerMessage(user);
Func<string> func = new Func<string>(loggerMsg.Write);
Debug(() => return "Hello " + user.Name);

Here are all the allocations.

There is another issue with logging via lambdas, consider the following code:

void Index(JsonDocument[] docs)
{
	var batch = new IndexBatchStats();
	database.Stats.Add(batch);// long lived
	batch.Completed += () => database.Stats.IncrmentCompletedBatches(batch);
	Log(() => "Indexing " + docs.Length + " documents");
}

You might notice that we have two lambdas here. C# is optimizing the number of types generated, and will generally output a single type for all the lifted member in all the lambdas in the method. This means that we have:

void Index(JsonDocument[] docs)
{
	var batch = new IndexBatchStats();
	database.Stats.Add(batch);// long lived
	var args = new { database, batch, docs }; // all lifted members
	batch.Completed += (args) => args.database.Stats.IncrmentCompletedBatches(args.batch);
	Log((args) => "Indexing " + args.docs.Length + " documents");
}

As you can see, we have a long lived lambda, which we think is using only other long lived objects (database & batch), but is actually holding a reference to the docs, which are VERY large.

Except for the last issue, which require moving the logging to a separate method to avoid this optimization, all of the issues outlined above can be handled by explicitly calling IsDebugEnabled in the calling code.

And this is why we require it.