ASP.NET Core 2.0 application running in Linux container suffers from locking issues when there are many calls to Trace.WriteLine()

Question

Our application is an ASP.NET Core 2.0 WebAPI deployed in Linux Docker containers and running in Kubernetes.

During load testing, we discovered intermittent spikes in CPU usage that our application would never recover from.

We used perfcollect to collect traces from a container so that we could compare a successful test and a test with CPU spikes. We discovered that around 75% of the CPU time in the failing test was spent in JIT_MonRelaibleEnter_Protable, an interface of lock operations. The caller was System.Diagnostics.TraceSource.dll.

Our application was ported from .NET Framework and contained a lot of calls to System.Diagnostics.Trace.WriteLine(). When we removed all of these, our CPU/memory usage reduced by more than 50% and we don't see the CPU spikes anymore.

I want to understand the cause of this issue.

In the corefx repo, I can see that a default trace listener is setup in TraceInternal.cs:

public static TraceListenerCollection Listeners
    {
        get
        {
            InitializeSettings();
            if (s_listeners == null)
            {
                lock (critSec)
                {
                    if (s_listeners == null)
                    {
                        // In the absence of config support, the listeners by default add
                        // DefaultTraceListener to the listener collection.
                        s_listeners = new TraceListenerCollection();
                        TraceListener defaultListener = new DefaultTraceListener();
                        defaultListener.IndentLevel = t_indentLevel;
                        defaultListener.IndentSize = s_indentSize;
                        s_listeners.Add(defaultListener);
                    }
                }
            }
            return s_listeners;
        }
    }

I can see that DefaultTraceListener.cs calls Debug.Write():

private void Write(string message, bool useLogFile)
    {
        if (NeedIndent) 
            WriteIndent();

        // really huge messages mess up both VS and dbmon, so we chop it up into 
        // reasonable chunks if it's too big
        if (message == null || message.Length <= InternalWriteSize)
        {
            Debug.Write(message);
        }
        else
        {
            int offset;
            for (offset = 0; offset < message.Length - InternalWriteSize; offset += InternalWriteSize)
            {
                Debug.Write(message.Substring(offset, InternalWriteSize));
            }
            Debug.Write(message.Substring(offset));
        }

        if (useLogFile && !string.IsNullOrEmpty(LogFileName))
            WriteToLogFile(message);
    }

In Debug.Unix.cs, I can see that there is a call to SysLog:

 private static void WriteToDebugger(string message)
        {
            if (Debugger.IsLogging())
            {
                Debugger.Log(0, null, message);
            }
            else
            {
                Interop.Sys.SysLog(Interop.Sys.SysLogPriority.LOG_USER | Interop.Sys.SysLogPriority.LOG_DEBUG, "%s", message);
            }
        }

I don't have a lot of experience working with Linux but I believe that I can simulate the call to SysLog by running the following command in the container:

logger --socket-errors=on 'SysLog test'

When I run that command, I get the following response:

socket /dev/log: No such file or directory

So it looks like I can't successfully make calls to SysLog from the container. If this is indeed what is going on when I call Trace.WriteLine(), why is it causing locking issues in my application?

As far as I can tell, EnvVar_DebugWriteToStdErr is not set in my container so it should not be attempting to write to StdErr.

Answer 1

The solution can be that rsyslog is not running. Is that installed in your container? Use a base image that has rsyslog built in.

This link can help too.