TraceSource Thread-safety

TraceSource Thread-safety

l  Introduction

.NET 2.0 introduced a Tracing Framework which enables developers to easily add simple tracing functionality with built-in .NET support. At the core of the tracing framework is a loosely-coupled TraceSource-TraceListener design. A few posts from BCL Team Blog (A Tracing Primer series) could be a good place to start.

Of course, the .NET 2.0 tracing framework is far from being perfect. See [.NET Instrumentation Workshop, Why .NET Tracing is not reliable] for discussions on this.

This post discusses the thread-safety of TraceSource class. Even though msdn claims the TraceSource class is thread-safe. It seems that this is not the case.

l  Analysis

Here is a program to test TraceSource class thread-safety:

namespace Ditw.Demo.MultiThreadedTracing {     using System;     using System.Text;     using System.Diagnostics;     using System.Threading;       class Program     {         static void Main(string[] args)         {             Console.WriteLine("Press <Enter> to start tracing...");             Console.ReadLine();             MultiThreadedTraceTest();             Console.ReadLine();             _traceSource.Close();         }           static TraceSource _traceSource = new TraceSource("DemoTrace", SourceLevels.All);           static void TraceMethod(Object count)         {             Int32 c = (Int32)count;             for (Int32 i = 0; i < c; i++)             {                 _traceSource.TraceEvent(TraceEventType.Information, c, "{0} of {1}", i, count);             }             Console.WriteLine("Trace [{0}] Done!", c);         }           static void MultiThreadedTraceTest()         {             ThreadPool.QueueUserWorkItem(TraceMethod, 10);             ThreadPool.QueueUserWorkItem(TraceMethod, 20);             ThreadPool.QueueUserWorkItem(TraceMethod, 30);         }     } }

The application configuration file:

<?xml version="1.0" encoding="utf-8" ?> <configuration>   <system.diagnostics>     <sources>       <source name="DemoTrace">         <listeners>           <clear />           <add type="System.Diagnostics.TextWriterTraceListener" name="textListener"                initializeData="log.txt" />         </listeners>       </source>     </sources>   </system.diagnostics> </configuration>

 

The program schedules 3 background work items to write trace to the same log file log.txt. Even though the console output always shows that all the 3 work items completes:

Press <Enter> to start tracing...   Trace [10] Done! Trace [20] Done! Trace [30] Done!

Most of the time, the log file log.txt does not contain all the expected trace entries, and differs from one run to another. A typical output:

DemoTrace Information: 20 : 0 of 20 DemoTrace Information: 30 : 0 of 30 … DemoTrace Information: 30 : 29 of 30 DemoTrace Information: 20 : 1 of 20 … DemoTrace Information: 20 : 19 of 20

You can see from the previous listing that all the trace entries from

    ThreadPool.QueueUserWorkItem(TraceMethod, 10);

are not logged. And sometimes, all the trace entries from

    ThreadPool.QueueUserWorkItem(TraceMethod, 20);

are not logged. This looks like a typical thread-safety issue.

With Reflector, we can find the TraceEvent implementation details:

[Conditional("TRACE")] public void TraceEvent(TraceEventType eventType, int id, string format, params object[] args) {     // Ensure that config is loaded     Initialize();       if (internalSwitch.ShouldTrace(eventType) && listeners != null)     {         if (TraceInternal.UseGlobalLock)         {             // we lock on the same object that Trace does because we're writing to the same Listeners.             lock (TraceInternal.critSec)             {                 for (int i = 0; i < listeners.Count; i++)                 {                     TraceListener listener = listeners[i];                     listener.TraceEvent(manager, Name, eventType, id, format, args);                     if (Trace.AutoFlush) listener.Flush();                 }             }         }         else         {             for (int i = 0; i < listeners.Count; i++)             {                 TraceListener listener = listeners[i];                 if (!listener.IsThreadSafe)                 {                     lock (listener)                     {                         listener.TraceEvent(manager, Name, eventType, id, format, args);                         if (Trace.AutoFlush) listener.Flush();                     }                 }                 else                 {                     listener.TraceEvent(manager, Name, eventType, id, format, args);                     if (Trace.AutoFlush) listener.Flush();                 }             }         }         manager.Clear();     } }

At first glance, it’s not hard to find this is an implementation with thread-safety in mind: if useGlobalLock is true, the global trace lock is used. Else if the TraceListener declares itself thread-safe (by TraceListener.IsThreadSafe property), no lock is taken and the responsibility of ensuring thread-safety is left to the TraceListener. Otherwise, the listener object is locked. All these looks like a reasonable implementation and we should not be getting a log file with missing trace entries. However, the problem lies in the trace switch filtering logic.

if (internalSwitch.ShouldTrace(eventType) && listeners != null)

Here is the implementation detail of SourceSwitch:

public bool ShouldTrace(TraceEventType eventType) {     return (SwitchSetting & (int)eventType) != 0; }

The SwitchSetting is a property defined in the base class Switch:

protected int SwitchSetting {     get     {         if (!initialized)         {             if (!InitializeWithStatus())                 return 0;             OnSwitchSettingChanged();         }         return switchSetting;     }     Set { … } }

The method of interest is InitializeWithStatus, let go into one more function:

private bool InitializeWithStatus() {     if (!initialized)     {           if (initializing)             return false;           initializing = true;        … }

The problematic code reveals itself finally – the SourceSwitch implementation is not a thread-safe, more specifically, the SwitchSetting getter method is not. Let’s look back to our test program: when 2 trace work items are schedule simultaneously, then if one thread is in the middle of InitializeWithStatus call, and the 2^nd thread also runs into the SwitchSetting getter. What happens is (for the 2^nd thread) InitializeWithStatus returns false because initializing is already set to true by the 1^st thread. Consequently, in thread 2, the SwitchSetting getter returns 0, which eventually results in false being returned by SourceSwitch.ShouldTrace. And this is why we failed to see all the trace entries in log.txt – some trace entries are dropped because the switch has not been properly set up!

 

One interesting observation:

I ran the test on my VM. It seems that the number of CPU (VM settings) plays an important role in my demo test:

1.         With 1 CPU, most of the time, the trace file log.txt contains all the trace entries;

2.         With 2 CPUs, most of the time, the trace file contains trace entries from 2 of the 3 work items – traces from one of the first 2 work items gets lost;

3.         With 4 CPUs, sometimes, traces from only 1 work item gets logged.

This is an indication that .NET 2.0 ThreadPool probably decides the number of working threads based on the number of available processor cores – an optimization to maximize parallelism and minimize thread switching.

l  Summary

In this post, the thread-safety of TraceSource class is discussed. The TraceSource class is not thread-safe as MSDN declares due to an implementation deficit in Switch classes.