5

We are seeing a memory leak with one of our WCF applications and I was wondering if someone could clarify something for me. Using windbg I ran !finalizequeue and it shows thousands of objects in each Heap set as "Ready for finalization". 

Heap 0
generation 0 has 464 finalizable objects (0000000033877190->0000000033878010)
generation 1 has 52 finalizable objects (0000000033876ff0->0000000033877190)
generation 2 has 19958 finalizable objects (0000000033850040->0000000033876ff0)
Ready for finalization 228791 objects (0000000033878010->0000000033a36dc8)
------------------------------
Heap 1
generation 0 has 1508 finalizable objects (000000002ee2e168->000000002ee31088)
generation 1 has 91 finalizable objects (000000002ee2de90->000000002ee2e168)
generation 2 has 23498 finalizable objects (000000002ee00040->000000002ee2de90)
Ready for finalization 249421 objects (000000002ee31088->000000002f0182f0)
------------------------------
Heap 2
generation 0 has 66 finalizable objects (00000000292660d0->00000000292662e0)
generation 1 has 63 finalizable objects (0000000029265ed8->00000000292660d0)
generation 2 has 19411 finalizable objects (0000000029240040->0000000029265ed8)
Ready for finalization 238531 objects (00000000292662e0->00000000294380f8)
------------------------------
Heap 3
generation 0 has 510 finalizable objects (0000000034e470d8->0000000034e480c8)
generation 1 has 77 finalizable objects (0000000034e46e70->0000000034e470d8)
generation 2 has 19910 finalizable objects (0000000034e20040->0000000034e46e70)
Ready for finalization 226933 objects (0000000034e480c8->0000000035003470)
Statistics for all finalizable objects (including all objects ready for finalization):

That tells me that the finalizer thread is stuck. So I ran the !Threads command in windbg to get the finalizer thread id and this is what it shows....

ThreadCount:      2969
UnstartedThread:  0
BackgroundThread: 187
PendingThread:    0
DeadThread:       2782
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
XXXX    2 19e8 0000000001f64b10 80039220 Preemptive  0000000000000000:0000000000000000 000000000d4aacb0 0     Ukn (Finalizer) 
  18    3  cb4 000000000d9bf7a0  102a220 Preemptive  0000000000000000:0000000000000000 000000000150e940 0     MTA (Threadpool Worker) 
  19    4 1a24 000000000f762720    21220 Preemptive  0000000000000000:0000000000000000 000000000150e940 0     Ukn 
  20    6  e1c 0000000010f4eae0  3029220 Preemptive  0000000000000000:0000000000000000 000000000d4aacb0 0     MTA (Threadpool Worker) 
  22   48 1548 000000001feb1880    21220 Preemptive  0000000000000000:0000000000000000 000000000150e940 0     Ukn 
  23   49 11a4 000000001feb2050    21220 Preemptive  0000000000000000:0000000000000000 000000000150e940 0     Ukn 
  24   50  a64 000000001feb2820    21220 Preemptive  0000000000000000:0000000000000000 000000000150e940 0     Ukn

The first thread in the list is the finalizer thread and the thread id is XXXX. What does that mean? I'm guessing it means the thread does not exist anymore, or isn't running. Can someone confirm that or correct my understanding?

UPDATE

I ran ~2s;kb command like Kjell Gunnar suggested in the comments and here's the output.

0:028> ~2s;kb
ntdll!ZwRemoveIoCompletion+0xa:
00000000`77c1bdca c3              ret
RetAddr           : Args to Child                                                           : Call Site
000007fe`fe0e16ad : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!ZwRemoveIoCompletion+0xa
00000000`776f9991 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : KERNELBASE!GetQueuedCompletionStatus+0x39
000007fe`fb7f6bb1 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!GetQueuedCompletionStatusStub+0x11
00000000`777059cd : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nativerd!NOTIFICATION_THREAD::ThreadProc+0x71
00000000`77bfa561 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

What does the ZwRemoveIoCompletion mean?

Dan H
  • 1,828
  • 2
  • 21
  • 38
  • A deadlock in the finalizer thread is a pretty common mishap. You'll have to look at its stack trace. – Hans Passant Feb 23 '17 at 15:21
  • I was going to do that but don't I need the thread index for the finalizer to see it's stack trace? Or is there another way? I was following this example - http://dotnetdebug.net/2005/06/22/blocked-finalizer-thread/ – Dan H Feb 23 '17 at 15:39
  • issue the ~ command, and you will see all threads alive. look for 2 Id: .19e8 or try: ~2s;kb – Kjell Gunnar Feb 23 '17 at 18:58

1 Answers1

1

The three first columns you see are

  • the WinDbg thread ID. You can e.g. use that in the ~xs command where x is the ID of the thread.
  • the CLR thread ID, which correlates to Thread objects on the .NET heap (try !dumpheap -type Thread and then !do on a thread object, look at m_ManagedThreadId). I never found a real use case for it.
  • the kernel thread ID, also shown by many other tools, e.g. task manager or Process Explorer

There are a few special cases and it seems that you ran into one of them. If the first column shows XXXX, .NET does not have a fixed physical OS thread assigned. This can happen for threads that are managed by the .NET runtime, e.g. threads from a thread pool. At some point in time, it might get a physical thread again.

Furthermore, there seem to be cases where .NET still remembers the OS thread (first line of the following example, OS ID f28) and when it doesn't (second and third line, where the OS ID is 0):

XXXX    3  f28 00000087c5f974c0 80030228 Preemptive  00000087C6033180:00000087C6033FD0 00000087c4213450 0     Ukn 
XXXX    4    0 00000087c5fa24b0    39820 Preemptive  0000000000000000:0000000000000000 00000087c4213450 0     MTA 
XXXX    5    0 00000087c5fd0eb0    39820 Preemptive  0000000000000000:0000000000000000 00000087c4213450 0     MTA

Typically the OS thread ID is helpful, because it correlates to the output of ~ (1098 is the process ID). However, in my dump file, there is no native thread with the ID f28:

0:009> ~
   0  Id: 1098.564 Suspend: 0 Teb: 000007f5`ffd3d000 Unfrozen
   1  Id: 1098.1e98 Suspend: 0 Teb: 000007f5`ffd3b000 Unfrozen
   2  Id: 1098.1d6c Suspend: 0 Teb: 000007f5`ffd39000 Unfrozen
   3  Id: 1098.458 Suspend: 0 Teb: 000007f5`ffd35000 Unfrozen
   4  Id: 1098.13d4 Suspend: 0 Teb: 000007f5`ffd33000 Unfrozen
   5  Id: 1098.1b20 Suspend: 0 Teb: 000007f5`ffb5e000 Unfrozen
   6  Id: 1098.80c Suspend: 0 Teb: 000007f5`ffb52000 Unfrozen
   7  Id: 1098.944 Suspend: 0 Teb: 000007f5`ffb5c000 Unfrozen
   8  Id: 1098.90 Suspend: 0 Teb: 000007f5`ffb5a000 Unfrozen
.  9  Id: 1098.1738 Suspend: 0 Teb: 000007f5`ffb58000 Unfrozen

One thing you can check is the thread state, reported as 80039220 in your case. This gives us:

0:009> !ThreadState 80039220
    Legal to Join
    Background
    CLR Owns
    In Multi Threaded Apartment
    Reported Dead
    Fully initialized
    Detached

Reported dead seems to confirm your sorrows.

Thomas Weller
  • 55,411
  • 20
  • 125
  • 222
  • Just for my understanding: the .NET finalizer thread `2` ran on OS thread `19e8`? If it's deadlocked, OP should still be able to get the stacktrace of `19e8` right? – Lieven Keersmaekers Feb 24 '17 at 06:18
  • @LievenKeersmaekers: IMHO not, because that physical thread has been reused to do something else. It may even happen that the listed OS thread does not exist any more (as shown in my example). – Thomas Weller Feb 24 '17 at 12:49
  • 1
    @LievenKeersmaekers: I have no idea yet on how to access the stack of such a .NET thread that has no physical thread any more. I'm trying to figure that out, because it has to be somewhere. Usually, registers and the instruction pointer are kept in a context structure as part of a kernel object, but that cannot apply here. – Thomas Weller Feb 24 '17 at 12:50
  • @ThomasWeller If the finalizer thread is dead, can I still see it's stack trace to find out why it died? – Dan H Feb 24 '17 at 14:59
  • @DanH: I'll try to figure out. The call stack should be somewhere :-) – Thomas Weller Feb 24 '17 at 15:02
  • @ThomasWeller I issued the ~*k 200 command and searched for the finalizer thread, but it wasn't in the list. Does that confirm the threadstate of Reported Dead is correct? – Dan H Mar 02 '17 at 19:16
  • @DanH: yes, that would match the other indicators. – Thomas Weller Mar 03 '17 at 00:22
  • @ThomasWeller Thanks for the help. Now, I have to figure out why it died. I have a feeling that's going to be difficult... – Dan H Mar 03 '17 at 13:39
  • @ThomasWeller I'm still dealing with this issue. I cannot figure out how to see the stack trace of the finalizer thread before it dies. Do you have any ideas? – Dan H May 03 '17 at 20:04
  • @DanH: Could you share the dump file? You should easily find my email not far from my profile – Thomas Weller May 03 '17 at 21:26