Problem with Trace.Indent() and Trace.Unindent()

[Stewart Berman]

I noticed that some calls to Trace.Indent and Trace.Unindent did not seem to produce the expected
results

I had created a module with wrappers for all of the trace methods and I changed the ones for
Trace.Indent and Trace.Unindent to:

Public Sub TraceIndent()
Trace.Indent()
Trace.WriteLine("Indent")
End Sub


Public Sub TraceUnindent()
Trace.Unindent()
Trace.WriteLine("Unindent")
End Sub

I then ran the application with full tracing and saw formatting like <comments added afterwards>:

20090720 23:17:27.750: btnStop_Click Tracing Started
Indent
20090720 23:17:27.750: StopSlideShow Tracing Started
Indent
20090720 23:17:27.750: ShutDownBackgroundTask Tracing Started
Indent
20090720 23:17:27.765: Showing ballon tip
20090720 23:17:27.781: Dispose Tracing Started
Indent
20090720 23:17:28.906: MemoryInUse Tracing Started
Indent <****this indent went the wrong way****>
20090720 23:17:28.921: Memory in use: 181878784, Peak Memory in use: 227233792
Unindent
20090720 23:17:28.937: MemoryInUse Tracing Ended
20090720 23:17:28.937: Starting Memory: 181878784, Current Memory: 181878784, Maximum Memory:
181878784
Unindent
20090720 23:17:28.953: CBackgroundWorker_DoWork Tracing Ended
20090720 23:17:38.796: Disposing of BackgroundWorker class
20090720 23:17:38.796: Disposed of BackgroundWorker class
Unindent <****This unindent went the wrong way****>
20090720 23:17:38.796: Dispose Tracing Ended
20090720 23:17:38.812: Hiding ballon tip
Unindent
20090720 23:17:38.843: ShutDownBackgroundTask Tracing Ended
Unindent
20090720 23:17:38.843: StopSlideShow Tracing Ended
Unindent
20090720 23:17:38.859: btnStop_Click Tracing Ended

The above is from the Output window in VS 2005 using the default trace writer.

I then ran the release version with a trace listener defined in app.config:
<trace useGlobalLock="false" autoflush="true" indentsize="3">
<listeners>
<add name="traceListener" type="System.Diagnostics.TextWriterTraceListener"
initializeData="Application_Trace.log" />
<remove name="Default" />
</listeners>

The results included the same indent errors:
20090721 00:34:59.984: btnStop_Click Tracing Started
Indent
20090721 00:34:59.984: StopSlideShow Tracing Started
Indent
20090721 00:34:59.984: ShutDownBackgroundTask Tracing Started
Indent
20090721 00:34:59.984: Showing ballon tip
20090721 00:34:59.984: Dispose Tracing Started
Indent
20090721 00:35:00.906: MemoryInUse Tracing Started
Indent
20090721 00:35:00.906: Memory in use: 203644928, Peak Memory in use: 237846528
Unindent
20090721 00:35:00.906: MemoryInUse Tracing Ended
20090721 00:35:00.906: Starting Memory: 192491520, Current Memory: 203644928, Maximum Memory:
203644928
Unindent
20090721 00:35:00.906: CBackgroundWorker_DoWork Tracing Ended
20090721 00:35:10.984: Disposing of BackgroundWorker class
20090721 00:35:10.984: Disposed of BackgroundWorker class
Unindent
20090721 00:35:10.984: Dispose Tracing Ended
20090721 00:35:10.984: Hiding ballon tip
Unindent
20090721 00:35:11.015: ShutDownBackgroundTask Tracing Ended
Unindent
20090721 00:35:11.015: StopSlideShow Tracing Ended
Unindent
20090721 00:35:11.015: btnStop_Click Tracing Ended

What could be causing the Trace.Indent() and Trace.Unindent() to reverse direction?

 

[Stewart Berman]

I should have included:
Windows XP SP3 with all patches
Visual Studio 2005 with all patches
..Net 2.0

 

[Armin Zingler]

I noticed that some calls to Trace.Indent and Trace.Unindent did not seem to produce the expected
results

I had created a module with wrappers for all of the trace methods and I changed the ones for
Trace.Indent and Trace.Unindent to:

Public Sub TraceIndent()
Trace.Indent()
Trace.WriteLine("Indent")
End Sub


Public Sub TraceUnindent()
Trace.Unindent()
Trace.WriteLine("Unindent")
End Sub

I then ran the application with full tracing and saw formatting like <comments added afterwards>:

20090720 23:17:27.750: btnStop_Click Tracing Started
Indent
20090720 23:17:27.750: StopSlideShow Tracing Started
Indent
20090720 23:17:27.750: ShutDownBackgroundTask Tracing Started
Indent
20090720 23:17:27.765: Showing ballon tip
20090720 23:17:27.781: Dispose Tracing Started
Indent
20090720 23:17:28.906: MemoryInUse Tracing Started
Indent <****this indent went the wrong way****>

I'd love to say "gottcha!" if I'm right.... And I can only be if you call
the methods from different threads. Otherwise ignore the following suggestion:

Try this:

private lockobject as new object

Public Sub TraceIndent()
synclock lockobject
Trace.Indent()
Trace.Write("Indent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
end synclock
End Sub


Public Sub TraceUnindent()
synclock lockobject
Trace.Unindent()
Trace.Write("Unindent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
end synclock
End Sub


Because, between _calling_ Indent/Unindent and _writing_
"Indent"/"Unindent", the other thread can call one of these methods.
It still may output the actual text at the wrong identation level but the
"(Un)indent" messages should be correct now.


Armin

 

[Stewart Berman]

I'd love to say "gottcha!" if I'm right.... And I can only be if you call
the methods from different threads. Otherwise ignore the following suggestion:

Try this:

private lockobject as new object

Public Sub TraceIndent()
synclock lockobject
Trace.Indent()
Trace.Write("Indent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
end synclock
End Sub


Public Sub TraceUnindent()
synclock lockobject
Trace.Unindent()
Trace.Write("Unindent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
end synclock
End Sub


Because, between _calling_ Indent/Unindent and _writing_
"Indent"/"Unindent", the other thread can call one of these methods.
It still may output the actual text at the wrong identation level but the
"(Un)indent" messages should be correct now.


Armin

Give that man half a cigar. It is being called from different threads but the synclock didn't help.
I ran a little test:

This was in the BackgroundWorker DoWork background task:

Do While ((0 = Interlocked.CompareExchange(cvarReload, -1, -1)) AndAlso (Not
CBackgroundWorker.CancellationPending))
Trace.WriteLineIf(cvarTraceSwitch.TraceInfo, Format$(Now(), "yyyyMMdd
HH:mm:ss.fff: ") & "Before invoking ReportProgress, Thread: " &
Threading.Thread.CurrentThread.ManagedThreadId & ", indentLevel: " & Trace.IndentLevel)
CBackgroundWorker.ReportProgress(nDuration)
Thread.Sleep(1000)
Trace.WriteLineIf(cvarTraceSwitch.TraceInfo, Format$(Now(), "yyyyMMdd
HH:mm:ss.fff: ") & "After invoking ReportProgress, Thread: " &
Threading.Thread.CurrentThread.ManagedThreadId & ", indentLevel: " & Trace.IndentLevel)
Loop

This was the override that caught the ProgressChanged event in the foreground task.

Private Sub CBackgroundWorker_ProgressChanged(ByVal sender As Object, ByVal e As _
System.ComponentModel.ProgressChangedEventArgs) Handles CBackgroundWorker.ProgressChanged
Trace.WriteLineIf(cvarTraceSwitch.TraceInfo, Format$(Now(), "yyyyMMdd HH:mm:ss.fff: ") &
"ProgressChangedEvents , Thread: " & Threading.Thread.CurrentThread.ManagedThreadId & ",
indentLevel: " & Trace.IndentLevel)
End Sub

The trace has:
Thread 10 is the foreground (GUI) thread. Thread 7 is the BackgroundWorker thread.
Unindent 7
<snip> (no indents/unindents
20090721 22:46:24.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:24.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:25.531: After invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:25.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:25.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:26.531: After invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:26.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:26.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:27.531: After invoking ReportProgress, Thread: 7, indentLevel: 2

This shows that each thread has its own indentLevel and also that the actual Indent Level of the
trace listeners does not change on a thread switch. It is 2 (six spaces) as last set by thread 7.

The problem is that TraceInternal.indentLevel is defined as:
<ThreadStatic> _
Private Shared indentLevel As Integer
which makes it unique for each thread.

This is for .Net 2.0.502727 in System.dll. I don't have the 3.0 and 3.5 System.dll handy to see if
it has changed.

The code for Trace.Indent() is:
Public Shared Sub Indent()
SyncLock TraceInternal.critSec
TraceInternal.InitializeSettings
If (TraceInternal.indentLevel < &H7FFFFFFF) Then
TraceInternal.indentLevel += 1
End If
Dim listener As TraceListener
For Each listener In TraceInternal.Listeners
listener.IndentLevel = TraceInternal.indentLevel
Next
End SyncLock
End Sub

The IndentLevel for each listener is not incremented -- it is set to a calculated value -
TraceInternal.indentLevel which is access as a property through:

Public Shared Property IndentLevel As Integer
Get
Return TraceInternal.indentLevel
End Get
Set(ByVal value As Integer)
SyncLock TraceInternal.critSec
If (value < 0) Then
value = 0
End If
TraceInternal.indentLevel = value
If (Not TraceInternal.listeners Is Nothing) Then
Dim listener As TraceListener
For Each listener In TraceInternal.Listeners
listener.IndentLevel = TraceInternal.indentLevel
Next
End If
End SyncLock
End Set
End Property

And, as noted above TraceInternal.indentLevel is unique for each thread.

 

[Colbert Zhou [MSFT]]

Hi Sarberman,

If we wrap the Trace.Indent() like this, we need to Syncblock as Armin
suggest. Otherwise, the output from different threads will mess up because
Unindent() can be executed between another thread's Indent and WriteLine.
The Trance.IndentLevel is stored as per-thread. That is to say, if
different threads call Trace.WriteLine(), the output's IndentLevel will
look different based on which thread executes that Trace.WriteLine().(I
think that maybe the problem we see in your first post) So I suggest when
printing Indent we aslo print the thread id behind. That will help for
troubleshooting.

If Trace.Indent()/Unindent() are called from the same threads, I do not see
the problem as you mention in the first post. The following is my test
codes,
--------------------------------------------------------
Private lockobject As New Object

Public Sub TraceIndent()
SyncLock lockobject
Trace.Indent()
Trace.WriteLine("Indent" & Trace.IndentLevel)
End SyncLock
End Sub

Public Sub TraceUnindent()
SyncLock lockobject
Trace.Unindent()
Trace.WriteLine("Unindent" & Trace.IndentLevel)
End SyncLock
End Sub

Private Sub Form1_Load(ByVal sender As System.Object, ByVal e As
System.EventArgs) Handles MyBase.Load
Dim t As Thread = New Thread(AddressOf ThreadTask)
t.Start()

Do
Trace.WriteLine("Test String")
Thread.Sleep(800)
Loop
End Sub

Private Sub ThreadTask()
Dim rnd As New Random()
Do
Dim r As New Random
If r.Next(0, 2) = 0 Then
TraceIndent()
Thread.Sleep(1000)
Else
TraceUnindent()
Thread.Sleep(1000)
End If
Loop
End Sub
------------------------------------------------------------
The following is output,
Indent1
Test String
Indent2
Test String
Indent3
Test String
Indent4
Test String
Test String
Indent5
Test String
Unindent4
Test String
Unindent3
Test String
Unindent2
Test String
Test String
Unindent1
Test String
Unindent0
Test String
Unindent0
Test String
Indent1
Test String
Test String
Indent2
Test String


Best regards,
Colbert Zhou
Microsoft Online Support Team

 

[Armin Zingler]

Give that man half a cigar. It is being called from different threads but the synclock didn't help.

"Didn't help" means what? As I wrote, it was not intended to solve the
problem. I thought you'd post the trace output after you've made the
change. I believe you that nothing has changed, though I'm interested in
the trace output. I was almost sure that the Un/Indent messages now have
correct indent levels. And after seeing the thread-ids I may also be have
been able to find a real solution.

This shows that each thread has its own indentLevel and also that the actual Indent Level of the
trace listeners does not change on a thread switch. It is 2 (six spaces) as last set by thread 7.

The problem is that TraceInternal.indentLevel is defined as:
<ThreadStatic> _
Private Shared indentLevel As Integer
which makes it unique for each thread.

I didn't know this attribute. I wonder how this can work. It would require
additional overhead to access the field - because assembler code doesn't
care about any attribute. (If there was one field per thread, there would
have to be a check each time the field is to be accessed if there's already
an instance of the field for the executing thread. Kind of thread-to-field
relation.) The attribute help doen't say anything about it. Well, I accept
that it works as described.


Armin

 

[Stewart Berman]

If you look through my last message again you will see:

Give that man half a cigar. It is being called from different threads but the synclock didn't help.

I ran a little test:
<snip> Details of code
The trace has:
Thread 10 is the foreground (GUI) thread. Thread 7 is the BackgroundWorker thread.
Unindent 7
<snip> (no indents/unindents
20090721 22:46:24.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:24.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:25.531: After invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:25.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:25.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:26.531: After invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:26.531: Before invoking ReportProgress, Thread: 7, indentLevel: 2
20090721 22:46:26.531: ProgressChangedEvents , Thread: 10, indentLevel: 0
20090721 22:46:27.531: After invoking ReportProgress, Thread: 7, indentLevel: 2

This shows that each thread has its own indentLevel and also that the actual Indent Level of the
trace listeners does not change on a thread switch. It is 2 (six spaces) as last set by thread 7.

The problem is that TraceInternal.indentLevel is defined as:
<ThreadStatic> _
Private Shared indentLevel As Integer
which makes it unique for each thread.

The reason your test appears to work is that all of the indent and unindent calls are made from on
thread. So there is effectively a single incident of TraceInternal.indentLevel. Try launching two
instances of ThreadTask with different sleep values.

Is this by design or by mistake?

 

[Colbert Zhou [MSFT]]

Hi Sarberman,

Actually I tested using different threads, it still work as expected in my
side. The following is codes and results,

-----------------Codes-------------------------
Private lockobject As New Object

Public Sub TraceIndent()
SyncLock lockobject
Trace.Indent()
Trace.WriteLine("Indent" & Trace.IndentLevel & ", " &
System.Threading.Thread.CurrentThread.ManagedThreadId)
End SyncLock
End Sub

Public Sub TraceUnindent()
SyncLock lockobject
Trace.Unindent()
Trace.WriteLine("Unindent" & Trace.IndentLevel & ", " &
System.Threading.Thread.CurrentThread.ManagedThreadId)
End SyncLock
End Sub

Private Sub Form1_Load(ByVal sender As System.Object, ByVal e As
System.EventArgs) Handles MyBase.Load
Dim t As Thread = New Thread(AddressOf ThreadTask)
t.Start()
Dim t2 As Thread = New Thread(AddressOf ThreadTask2)
t2.Start()
Do
Trace.WriteLine("Test String")
Thread.Sleep(800)
Loop
End Sub

Private Sub ThreadTask()
Dim rnd As New Random()
Do
Dim r As New Random
If r.Next(0, 2) = 0 Then
TraceIndent()
Thread.Sleep(1000)
Else
TraceUnindent()
Thread.Sleep(1000)
End If
Loop
End Sub

Private Sub ThreadTask2()
Dim rnd As New Random()
Do
Dim r As New Random
If r.Next(0, 2) = 0 Then
TraceIndent()
Thread.Sleep(1000)
Else
TraceUnindent()
Thread.Sleep(1000)
End If
Loop
End Sub
---------Codes--------------------

---------------Results---------------
Unindent0, 11
Test String
Indent1, 12
Test String
Indent1, 11
Indent2, 12
Test String
Indent2, 11
Indent3, 12
Test String
Unindent1, 11
Unindent2, 12
Test String
Unindent0, 11
Indent3, 12
Test String
Test String
Indent1, 11
Indent4, 12
Test String
Indent2, 11
Unindent3, 12
Test String
Indent3, 11
Indent4, 12
Test String
Indent4, 11
Indent5, 12
Test String
Test String
Indent5, 11
Indent6, 12
Test String
Indent6, 11
Indent7, 12
---------------Results---------------

Actually from my test, I find that different threads act like they have
thier own IndentLevel. That is to say although from Reflector we see that
the TraceInternal.IndentLevel is thread static(shared), but I believe when
threads switching happens, .NET runtime will set the
TraceInternel.IndentLevel to the corresponding thread's level. So evey
thread's IndentLevel will work independently, like the output I post above.

So I did not reproduce the issue you mentioned in your two replies. If you
use my codes above, does the output mess up?


Best regards,
Colbert Zhou
Microsoft Online Support Team

 

[Stewart Berman]

I don't think you read the results of your test correctly:
Indent1, 12 <== After Thread 12 Issued TraceIndent the Trace.IndentLevel was 1
Test String
Indent1, 11 <== After Thread 12 Issued TraceIndent the Trace.IndentLevel was still 1
Indent2, 12 <== After Thread 12 Issued TraceIndent the Trace.IndentLevel was 2
Test String
Indent2, 11 <== After Thread 12 Issued TraceIndent the Trace.IndentLevel was still 2

If you walk through your test you will see that Tread 11 and Thread 12 are maintaining two
indepentdent Trace.IndentLevel items.

The Test String lines up with the Trace.IndentLevel of which ever thread updated it's IndentLevel
last.

Unindent1, 11
Unindent2, 12
Test String
Unindent0, 11
Indent3, 12
Test String
Test String

Each thread maintains it's own IndentLevel. The Trace Listeners have only one IndentLevel and it
has the value of the last thread to update it.

The problem is that TraceInternal.indentLevel is defined as:
<ThreadStatic> _
Private Shared indentLevel As Integer
which makes it unique for each thread that sets it.

 

[Andrew Morton]

If you walk through your test you will see that Tread 11 and Thread 12 are

maintaining two
indepentdent Trace.IndentLevel items.

Is that entirely unreasonable?

If you want the indent sizes to be per-app rather than per-thread, could you
make some class owned by the application through which all Trace calls would
pass so that it could maintain its (as in: the application's) own indent
level, regardless of which thread called it?

Andrew

 

[Stewart Berman]

Is that entirely unreasonable?
Actually, it is. Trace Listeners are shared across all threads. All of the other methods work
across threads. That is if a Trace.Write is issued the next Trace.Write or Trace.WriteLine will be
on the same line no matter which thread issues it. All of the methods have the same results in the
trace output independent of which thread issues them EXCEPT for Trace.Indent() and Trace.Unindent().
There might be a slight case for each thread having its own indentLevel but that is not the current
case. The Trace Listeners have the indentLevel of the last thread that issued a Trace.Indent() or a
Trace.Unindent(). If thread 10 has an internal trace indentLevel of 5 and thread 11 has an internal
trace indentLevel of 10. The trace indentation of a Trace.Write or Trace.Writeline execute by
thread 12 will depend on whether thread 10 or thread 11 issued the last Trace.Indent() call. If
thread 10 issued it the indentLevel used will be 5 but if thread 11 issued it the indentLevel used
will be 10. Also, if thread 10 issued the last Trace.Indent() call and thread 11 issues a
Trace.WriteLine the indentLevel that will be used is 5 not 10. However, if thread 11 issues another
Trace.Indent() call and then issues a Trace.WriteLine call the indentLevel used will jump from 5 to
11.

If you want the indent sizes to be per-app rather than per-thread, could you
make some class owned by the application through which all Trace calls would
pass so that it could maintain its (as in: the application's) own indent
level, regardless of which thread called it?

I did just that but in a module not a class. (Trace cannot be inherited.)

Private indentLevel As Integer = 0

Public Sub TraceIndent()
If (indentLevel < &H7FFFFFFF) Then
indentLevel += 1
End If
Trace.IndentLevel = indentLevel
Trace.Write("Indent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
End Sub

Public Sub TraceUnindent()
If (indentLevel > 0) Then
indentLevel -= 1
End If
Trace.IndentLevel = indentLevel
Trace.Write("Unindent ")
Trace.WriteLine(Threading.Thread.CurrentThread.ManagedThreadId)
End Sub

This fixes the problem. Trace.Indent() and Trace.Unindent are never called so the by thread
Internal IndentLevel is not used.