5

After the recent Windows 10 Update (Fall Creators Update) the performance of our .NET c# 4.0 application had decreased a lot. I think there are various issues and one of them is log4net (or disk IO).

Our application is very complex (various WCF applications and a ASPNET MVC 3.0 app) and in development there are a lot of log4net traces. Loading the first page in startup lasts 4 or 5 minutes and before the updates lasts a minute, If I deactivate log4net the performance.

I've done a test with two cloned virtual machines, logging after a regex operation, and the diferrences are significant.

The code:

    static void Main(string[] args)
    {
        Log.Info("Log4net1");

        DateTime start = DateTime.Now;

        for (int i = 0; i < 50; i++)
        {
            DoTheThing();
        }


        TimeSpan elapsedTime = DateTime.Now - start;
        Log.DebugFormat("TOTAL Elapsed time: {0}", elapsedTime.TotalMilliseconds);
        Console.ReadKey();
    }

    private static void DoTheThing()
    {
        DateTime start = DateTime.Now;
        Regex.Replace(TEXT, " nec ", m =>
        {
            return " (word nec) ";
        });
        TimeSpan elapsedTime = DateTime.Now - start;
        Log.DebugFormat("Elapsed time: {0}", elapsedTime.TotalMilliseconds);
    }

I've done tests with log4net 1.2.1 and 2.0.8:

average beforeUpdate -> TOTAL Elapsed time: 600ms

average afterUpdate -> TOTAL Elapsed time: 1000ms

It's a very important issue for us, and I haven't found any info on the net.

-- UPDATE --

I've found another (unanswered) thread on stackoverflow: log4net became very slow with caller location information after Windows 10 Fall Creators Update (1709)

I've ran a disk benchmark on both environments and there's no significant differences on read/write rates. I've tested the application disabling completely log4net (log4net threshold="OFF") and now the timings are very similar, so, as @DalmTo comments, there a lot of possibilities that it would be due to log4net, I'll try to put an issue there, although there is already a related microsoft issue: https://connect.microsoft.com/VisualStudio/feedback/details/3143189/after-installing-windows-10-1709-update-creating-a-stacktrace-class-has-become-a-magnitude-slower

Marc
  • 1,359
  • 1
  • 15
  • 39
  • I think you should consider posting an issue to log4net – Linda Lawton - DaImTo Jan 17 '18 at 08:58
  • 1
    Have you gone through the release notes to see what changes have been made? Maybe you can get some idea about what to look for. – Fildor Jan 17 '18 at 08:58
  • Could the slowdown be related to Meltdown/Spectre patches? – sgmoore Jan 17 '18 at 09:10
  • @DaImTo Yes, but I really think it's not directly its responsability, I'll wait for a more generic response... – Marc Jan 17 '18 at 09:36
  • @Fildor Yes, but I haven't found any relevant info about that. – Marc Jan 17 '18 at 09:42
  • @sgmoore I thought that too. The problem is that FCU was released before Meltdown/Spectre were famous, and I've no evidence that FCU included fixes on those vulnerabilities. I'm afraid that it could go worse when I install those patches! – Marc Jan 17 '18 at 09:48

1 Answers1

5

You could be hit by this issue:

Starting in October 2017, after you upgrade to Windows 10 Version 1709 or .NET Framework 4.7.1, you notice a significant decrease in performance when you run .NET Framework applications that use the System.Diagnostics.StackFrame class.

Applications typically rely on StackFrame when they throw .NET exceptions. If this occurs at a high rate (more than 10 incidents per second), applications can slow down significantly (tenfold) and run noticeably slower than before.

https://support.microsoft.com/en-us/help/4057154/performance-of-system-diagnostics-stackframe-degrades-in-windows-10-17

The .NET Framework 4.7.1 added support for detecting and parsing the Portable PDB file format to show file and line number information in stack traces. As part of this change, each function in a stack trace has its defining module checked to determine if that module uses the Portable PDB format.

Due to some differences in the internal caching policy, the runtime spends far more time searching for Portable PDBs than previous .NET Framework versions spent searching for classic Windows PDBs. This causes formatted stack traces to be produced more slowly than before.

https://github.com/Microsoft/dotnet/blob/master/releases/net471/KnownIssues/517815-BCL%20Applications%20making%20heavy%20use%20of%20System.Diagnostics.StackTrace%20might%20run%20more%20slowly%20on%20.NET%204.7.1.md

Installing the latest .NET 4.7.1 Reliability Update (KB4054856) should resolve this.

The following fixes are included: Applications making heavy use of System.Diagnostics.StackTrace or Exception.StackTrace might run more slowly on the .NET Framework 4.7.1.

https://blogs.msdn.microsoft.com/dotnet/2018/01/09/net-framework-4-7-1-is-available-on-windows-update-wsus-and-mu-catalog/

Rolf Kristensen
  • 17,785
  • 1
  • 51
  • 70
  • This confirms my bias that Exceptions should be Exceptional and are expensive (this is also borne out from other sources). – Mgetz Jan 17 '18 at 18:22
  • @Mgetz log4net can be configured to uses the StackTrace-class for capturing the callsite (class + method + etc.). Which will probably receive a performance hit (though already expensive). – Rolf Kristensen Jan 17 '18 at 18:52
  • I'm using .Net Framework 4.0, and I'm not ready to migrate to 4.7.1 in short term. @RolfKristensen do you know if there's another way to configure log4net to reduce that performance hit? – Marc Jan 18 '18 at 07:07
  • @Marc Think you can fix it by just installing the mentioned KB4054856 on the Windows10-machines. Changing log4net capture sounds like a different question, but you can try and configure the `` for the appender (See also https://logging.apache.org/log4net/release/sdk/html/T_log4net_Core_FixFlags.htm ) – Rolf Kristensen Jan 18 '18 at 15:25
  • @Marc: _"I'm using .Net Framework 4.0"_ -- then the issue described above can't be what's causing your apparent problem, as the above problem only appears in 4.7.1, before the also-mentioned Reliability Update. – Peter Duniho Jan 18 '18 at 22:10
  • @PeterDuniho You're right! It's not my issue, but it's an interesting response for other with a similar problem. I think that I've the same problem but on .NetFramework 4.0. – Marc Jan 19 '18 at 07:18
  • @PeterDuniho The support article is not clear. It says after you upgrade to Windows 10 Version 1709 **OR** .NET Framework 4.7.1, (which implies one thing) but the workarounds seem to be either to downgrade the Windows **OR** Framework version (which implies another thing). But if the issue only applies to Framework 4.7.1 then why mention Windows 10 Version 1709 as a special case at all). – sgmoore Jan 19 '18 at 09:18
  • 1
    Not working at Microsoft, so maybe things are different now. But last time I checked, then Net4-version-updates works as CLR replacement ( https://weblog.west-wind.com/posts/2012/Mar/13/NET-45-is-an-inplace-replacement-for-NET-40 ). Older versions of net4 are simulated using shims (to ensure old behavior stays), but sometimes the simulation fails. – Rolf Kristensen Jan 19 '18 at 19:16
  • With the last update of the KB, I've updated my Windows and that's solved: https://support.microsoft.com/en-us/help/4057154/performance-of-system-diagnostics-stackframe-degrades-in-windows-10-17 --> https://support.microsoft.com/en-us/help/4058258 – Marc Feb 07 '18 at 17:56