1

I have a multithreaded program for which I'd like to use the Trace.WriteLine, and redirect the output to a text file:

_LogTracer = new System.Diagnostics.TextWriterTraceListener(logPath);   
Trace.AutoFlush = true;
Trace.Listeners.Add(_LogTracer); 

Is this sufficient to be thread safe? What if two threads are trying to write to the output file at the same time?

Wai Ha Lee
  • 8,598
  • 83
  • 57
  • 92
spiderman
  • 1,565
  • 2
  • 16
  • 37
  • 2
    Could you not at least read the [documentation](https://msdn.microsoft.com/en-us/library/system.diagnostics.trace(v=vs.110).aspx) first? "This type is thread safe." – Damien_The_Unbeliever Oct 27 '15 at 07:52
  • 1
    "Thread-safe" is not a very good description because typically it will at most ensure the program will not crash if more than one thread mucks around with shared data structures, as well as the type have certain expectations that will still hold in a multithreaded environment. It says very little about the *behavior* other than that. For instance, what would you expect multiple calls to `Trace.Write` to behave like? Always be together in the final output? Can they be split up by another thread managing to write something in between? – Lasse V. Karlsen Oct 27 '15 at 12:32

2 Answers2

4

{wrt. overall thread-safety}

Using Trace.Listeners.Add (or Remove) is not thread-safe with respect to Trace.Write (or WriteLine) when Trace.UseGlobalLock is explicitly disabled.

The threadsafety - or lack of - for Write applies only the individual trace listener type (as noted the TextWriterTraceListener implementation is thread safe) or as guarded via the global trace lock (see TraceListener.IsThreadSafe for a discussion).

I've some janky old code that modifies the Listener collection that can result in errors in a multithreaded environment:

[System.InvalidOperationException]
Collection was modified; enumeration operation may not execute.
-------------------------------------------------- -- >
   at System.Collections.ArrayList.ArrayListEnumeratorSimple.MoveNext()
   at System.Diagnostics.TraceInternal.WriteLine(String message, String category)

The documentation says Listeners is thread-safe and it is slightly misleading: Listeners.GetEnumerator does not establish a lock-over-copy as hinted. The thread-safe lock is acquired only over a few individual Add/Remove methods.

To make Trace.Write thread-safe with respect to modifying Listeners requires the use of Trace.UseGlobalLock which will acquire the lock over enumerating and writing to all listeners.

user2864740
  • 60,010
  • 15
  • 145
  • 220
  • Which source code with good patterns using `Trace.Listeners.Add(_LogTracer);` ? using ***lock*** ? – Kiquenet Aug 13 '20 at 14:12
  • https://stackoverflow.com/a/41115500/206730 ***`Heavily threaded code started blocking for upwards of 12 seconds (!!) on the Trace.WriteLine as it had to acquire the lock over the "trivial" work in the DefaultTraceListener`.*** – Kiquenet Aug 13 '20 at 14:15
  • So it "is" thread-safe :D -- None of our systems use the default writer and explicitly disable locking, except for the _brief_ moment of modifying listeners. – user2864740 Aug 14 '20 at 00:16
-2

The test below proves that using TextWriterTraceListener is thread safe if used via Trace object. Tested in .net6

First, the code from the library, where we see that listener is locked if it is not a thread safe listener.

foreach (TraceListener listener in TraceInternal.Listeners)
{
  if (!listener.IsThreadSafe)
  {
    lock (listener)
    {
      listener.TraceEvent(eventCache, TraceInternal.AppName, eventType, id, format, args);
      if (TraceInternal.AutoFlush)
        listener.Flush();
    }
  }
  else
  {
    listener.TraceEvent(eventCache, TraceInternal.AppName, eventType, id, format, args);
    if (TraceInternal.AutoFlush)
      listener.Flush();
  }
}

Unit test

Trace.Listeners.Clear();

Trace.Listeners.Add(new TextWriterTraceListener("C:\\temp\\TEMP-\\mylog.log"));

var rand = new Random();
var sw = Stopwatch.StartNew();

var t1 = Task.Run(() => Write(sw, "Thread#1", rand));
var t2 = Task.Run(() => Write(sw, "Thread#2", rand));
var t3 = Task.Run(() => Write(sw, "Thread#3", rand));
var t4 = Task.Run(() => Write(sw, "Thread#4", rand));
var t5 = Task.Run(() => Write(sw, "Thread#5", rand));

Task.WaitAll(t1, t2, t3, t4, t5);

Trace.Close();
//-----------
static void Write(Stopwatch sw, string threadName, Random rand)
{
    while(sw.Elapsed.TotalSeconds < 30)
    {
        int ms = rand.Next(10, 20);
        //System.Threading.Thread.Sleep(ms); -- no slow down process
        Trace.TraceInformation("Thread '{0}' @ {1}", threadName, ms);
    }

}

And the file

TestCode Information: 0 : Thread 'Thread#2' @ 14
TestCode Information: 0 : Thread 'Thread#1' @ 18
TestCode Information: 0 : Thread 'Thread#2' @ 15
TestCode Information: 0 : Thread 'Thread#1' @ 18
TestCode Information: 0 : Thread 'Thread#1' @ 13
TestCode Information: 0 : Thread 'Thread#2' @ 12
TestCode Information: 0 : Thread 'Thread#1' @ 12
TestCode Information: 0 : Thread 'Thread#2' @ 14
TestCode Information: 0 : Thread 'Thread#1' @ 12
TestCode Information: 0 : Thread 'Thread#1' @ 10
TestCode Information: 0 : Thread 'Thread#2' @ 11
TestCode Information: 0 : Thread 'Thread#1' @ 16
TestCode Information: 0 : Thread 'Thread#2' @ 16
TestCode Information: 0 : Thread 'Thread#1' @ 12
TestCode Information: 0 : Thread 'Thread#2' @ 14
TestCode Information: 0 : Thread 'Thread#1' @ 14
TestCode Information: 0 : Thread 'Thread#2' @ 18
TestCode Information: 0 : Thread 'Thread#1' @ 12
TestCode Information: 0 : Thread 'Thread#2' @ 12
TestCode Information: 0 : Thread 'Thread#2' @ 16
TestCode Information: 0 : Thread 'Thread#3' @ 18
TestCode Information: 0 : Thread 'Thread#1' @ 18
TestCode Information: 0 : Thread 'Thread#1' @ 11
TestCode Information: 0 : Thread 'Thread#1' @ 13
TestCode Information: 0 : Thread 'Thread#3' @ 19
TestCode Information: 0 : Thread 'Thread#2' @ 19
TestCode Information: 0 : Thread 'Thread#1' @ 10
TestCode Information: 0 : Thread 'Thread#3' @ 14
TestCode Information: 0 : Thread 'Thread#1' @ 10

T.S.
  • 18,195
  • 11
  • 58
  • 78
  • You can never "prove" thread safety. (although you can disprove it) And this is a particularly bad test, because in all likelihood only one thread will try to call `TraceInformation` and the others will be sleeping. – Ben Voigt Aug 22 '23 at 19:53
  • @BenVoigt Even of I remove sleep (served for randomizing), add more threads, and run longer, there are no conflicts and all traces are written. – T.S. Aug 22 '23 at 20:30
  • I should clarify that my earlier comment should say "*Tests* can never prove thread safety". There are of course analyses that work. I had rephrased halfway through and would up with something inconsistent. Sorry about that. – Ben Voigt Aug 22 '23 at 20:53
  • @BenVoigt In this case, will this be fair to say that even thought the listener itself might not be thread safe, using it via `Trace.[]` is thread safe? See my update – T.S. Aug 22 '23 at 22:42