Tests using log4net run very slowly

Bug #761579 reported by Gareth White
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
NUnit V2
Fix Released
Medium
Charlie Poole

Bug Description

I've recently been upgrading some tests from NUnit 2.2.8 to 2.5.8 and noticed they were running a lot slower with the newer version of NUnit. I managed to narrow it down to their usage of log4net.

For example, the following test runs in 0.06 seconds on my machine using 2.2.8, but with 2.5.8 it takes 4.5 seconds. This is using .NET 2.0 on 32-bit Windows 7.

[Test]
public void Test1()
{
    log4net.ILog logger = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    for (int i = 0; i < 3000; i++)
    {
        logger.ErrorFormat("test");
    }
}

See the attached VS2005 project for a complete example.

One workaround I found is to do the following in the constructor:

LogManager.GetRepository().Threshold = Level.Off;

This seems a bit strange, because there is no logging visible in either case, yet it runs much slower without that line. Is this expected behaviour?

Related branches

Revision history for this message
Gareth White (gwhite-deactivatedaccount) wrote :
Changed in nunitv2:
assignee: nobody → Charlie Poole (charlie.poole)
Changed in nunitv2:
importance: Undecided → Medium
milestone: none → 2.6.0
status: New → Fix Committed
Revision history for this message
Charlie Poole (charlie.poole) wrote :

The slowdown is because NUnit captures all log events so that they can be displayed in the Gui. This takes place at the level of NUnit's own Appender, since we can't interfere with the overall level of logging for the app.

In NUnit 2.5, the capture occurs under the console runner as well as the gui, even though it is only actually used in the gui. With NUnit 2.6, due to a previous bug fix, we no longer capture logging at all under the console runner.

Under the 2.6 Gui runner, the delay was still occuring. This is because NUnit's default level for it's own Appender is 'Error' rather
than 'Off'. In order to fix this bug, the default has been changed to 'Off' and the slowdown will only occur if you actually turn on logging.

Note that the test config file controls which log events are _sent_ to the gui, while the gui settings dialog controls which received events are displayed in a particular tab.

Changed in nunitv2:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.