none
Timer stops executing and huge threadpool queue RRS feed

  • Question

  • I have a problem on a Win2003SP2 .NET3.5SP1 box with a System.Timers.Timer in a Service no longer gets fired after some hours.

    So I attached windbg and found an idle threadpool but 30K work requests (AsyncTimerCallbackCompletion)?!?

    Strange... Any idea to proceed?

    Thank you
    Daniel

    0:025> !threadpool
    CPU utilization 17%
    Worker Thread: Total: 6 Running: 0 Idle: 6 MaxLimit: 1000 MinLimit: 4
    Work Request in Queue: 32465
    AsyncTimerCallbackCompletion TimerInfo@07ed8440
    AsyncTimerCallbackCompletion TimerInfo@4c181dd0
    AsyncTimerCallbackCompletion TimerInfo@057aa318
    AsyncTimerCallbackCompletion TimerInfo@082067b0
    AsyncTimerCallbackCompletion TimerInfo@4baf53c0
    ...
    AsyncTimerCallbackCompletion TimerInfo@0675f2a8
    AsyncTimerCallbackCompletion TimerInfo@001b2950
    AsyncTimerCallbackCompletion TimerInfo@4bae3d28
    AsyncTimerCallbackCompletion TimerInfo@0675f2a8
    AsyncTimerCallbackCompletion TimerInfo@001b2950
    AsyncTimerCallbackCompletion TimerInfo@4bae3d28
    AsyncTimerCallbackCompletion TimerInfo@0675f2a8
    AsyncTimerCallbackCompletion TimerInfo@001b2950
    AsyncTimerCallbackCompletion TimerInfo@4bae3d28
    AsyncTimerCallbackCompletion TimerInfo@0675f2a8
    AsyncTimerCallbackCompletion TimerInfo@001b2950
    AsyncTimerCallbackCompletion TimerInfo@4bae3d28
    AsyncTimerCallbackCompletion TimerInfo@0675f2a8
    AsyncTimerCallbackCompletion TimerInfo@4b7e09e0
    AsyncTimerCallbackCompletion TimerInfo@001b2950
    --------------------------------------
    Number of Timers: 5
    --------------------------------------
    Completion Port Thread:Total: 3 Free: 1 MaxFree: 8 CurrentLimit: 3 MaxLimit: 1000 MinLimit: 4

    0:025> !threads
    ThreadCount: 15
    UnstartedThread: 0
    BackgroundThread: 14
    PendingThread: 0
    DeadThread: 0
    Hosted Runtime: no
                                          PreEmptive   GC Alloc           Lock
           ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception
       0    1  854 00154cd0      a020 Enabled  00000000:00000000 001517d8     0 MTA
       6    2  7f8 0015e9d0      b220 Enabled  00000000:00000000 001517d8     0 MTA (Finalizer)
       8    5 11ec 001a1db8   880b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Completion Port)
       9    6 1f18 001a5438    80a220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Completion Port)
      10    8 1274 001ae7f0    80a220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Completion Port)
      13    7 1dfc 00182de0      1220 Enabled  00000000:00000000 001517d8     0 Ukn
      14    9 1db4 066f8498   a80b220 Enabled  a205e664:a2060008 001517d8     0 MTA (Threadpool Completion Port)
      15   1e 1e70 067146a8   200b220 Enabled  94020d3c:94022650 001517d8     1 MTA
      17   3f  788 0671ea60   880b220 Enabled  9e08a630:9e08c32c 001517d8     0 MTA (Threadpool Completion Port)
      18    b  72c 0668ec80   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)
      19   48 1010 06761220   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)
      20   4c 1b08 07fcc3d8   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)
      21   19 1490 067a1050   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)
      22   43 1ae8 066f0cf0   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)
      23   47 11dc 067a2448   180b220 Enabled  00000000:00000000 001517d8     0 MTA (Threadpool Worker)

    Tuesday, February 23, 2010 9:06 PM

All replies

  • Can you run this process on a virtual, maybe different OS/maybe same, to determine if the problem is localized to the target machine or not?
    William Wegerson (www.OmegaCoder.Com)
    Tuesday, February 23, 2010 9:31 PM
    Moderator
  • Hi, GC_Daniel_:
        How is your problem going on?
    Please mark the right answer at right time.
    Thanks,
    Sam
    Wednesday, March 3, 2010 10:01 AM
  • Hi GC_Daniel_,

    Did you figure out what was the problem? It seems that I have exactly the same issue. The process consumes 100 CPU and when I investigate crush dumps I see the same picture in threadpool. Does anybody know what "AsyncTimerCallbackCompletion TimerInfo@..." record in the queue means and where they come from? 

     

    Thanks!

    Alexei


    Friday, July 9, 2010 1:03 PM
  • Do you see the same problem on more than one computer? If yes, try to create a small repro (as few lines of code as possible).

    -Karel

    Monday, July 12, 2010 4:10 PM
    Moderator
  • Hello Karel,

     

    Yes, I see this problem on more than one computer. The application is big and it's not easy to make a small repro but I'm working on it. But what those records mean? I asked this question w/ full windbg output on another forums and asked guys from windows server escalation team, but so far no luck. It seems that nobody knows what it is.

    http://stackoverflow.com/questions/3208875/what-does-asynctimercallbackcompletion-timerinfo-in-threadpool-output-mean

    http://groups.google.com/group/microsoft.public.dotnet.framework.clr/browse_thread/thread/bd747331770a9c1b#

    http://groups.google.com/group/microsoft.public.windbg/browse_thread/thread/b2e0d44a80d5c3f2#

     

    Thanks,

    Alexei

     

    Wednesday, July 14, 2010 7:47 PM
  • Do you happen to be unloading AppDomains in this application?  If so, this may be relevant: http://support.microsoft.com/kb/979744
    Thursday, July 22, 2010 6:24 PM
  • Does anybody know what "AsyncTimerCallbackCompletion TimerInfo@..." record in the queue means and where they come from?

    Alexei,

    AsyncTimerCallbackCompletion refers to ThreadpoolMgr::AsyncTimerCallbackCompletion(PVOID pArgs) defined in sscli20\clr\src\vm\win32threadpool.cpp on line 3917 in Rotor. In TimeInfo@xxxxxxxx the xxxxxxxx is the address of TimerInfo structure defined in sscli20\clr\src\vm\win32threadpool.h on line 442.

    The TimeInfo is defined as:

        typedef struct {
            LIST_ENTRY  link;
            HANDLE      Handle;
        } WaitEvent ;
    
        // Timer 
        typedef struct {
            LIST_ENTRY  link;           // doubly linked list of timers
            ULONG FiringTime;           // TickCount of when to fire next
            PVOID Function;             // Function to call when timer fires
            PVOID Context;              // Context to pass to function when timer fires
            ULONG Period;
            DWORD flag;                 // How do we deal with the context
            DWORD state;
            LONG refCount;
            HANDLE ExternalCompletionEvent;     // only one of this is used, but cant do a union since CLREvent has a non-default constructor
            CLREvent InternalCompletionEvent;   // flags indicates which one is being used
            OBJECTHANDLE    ExternalEventSafeHandle;
            ADID    handleOwningAD;
            BOOL    bReleaseEventIfADUnloaded;
        } TimerInfo;
    


    If you dump its memory, as in:

    0:015> !ThreadPool
    CPU utilization 3%
    Worker Thread: Total: 10 Running: 8 Idle: 2 MaxLimit: 1000 MinLimit: 4
    Work Request in Queue: 8
    AsyncTimerCallbackCompletion TimerInfo@003df9c0
    AsyncTimerCallbackCompletion TimerInfo@003dfa08
    --------------------------------------
    Number of Timers: 10
    --------------------------------------
    Completion Port Thread:Total: 0 Free: 0 MaxFree: 8 CurrentLimit: 0 MaxLimit: 1000 MinLimit: 4
    0:015> dp 003df9c0
    003df9c0  003dfa08 003df978 2f0c85f2 7423e098
    003df9d0  004047d0 0000000a 00000000 00000003
    .....


    You'll see that the 4th pointer (TimeInfo.Function), in my case 7423e098, is the address of umnanaged callback function AddTimerCallback defined in sscli20\clr\src\vm\comthreadpool.cpp on line 949:

    0:015> ln 7423e098
    (7423e098)   mscorwks!AddTimerCallback   |  (7423e0ac)   mscorwks!AddTimerCallback_Worker
    Exact matches:
        mscorwks!AddTimerCallback = <no type information>
    

    The 5th pointer (in my case 004047d0) points to an instance of DelegateInfo structure defined in sscli20\clr\src\vm\delegateinfo.h, let's dump its memory:

    0:015> dp 004047d0
    004047d0  00000001 00181170 00000000 00000000
    004047e0  00000000 00000000 7d69b9a1 88000000
    .....

    Here the first value is the AppDomain ID, but the second (in my case 00181170) is a indirect pointer to the managed object the holds the timer callback delegate, let's dump it:

    0:015> !do poi(00181170)
    Name: System.Threading._TimerCallback
    MethodTable: 6a7b7444
    EEClass: 6a5e9a2c
    Size: 20(0x14) bytes
     (C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    6a7b72d8  400067d        4 ...ing.TimerCallback  0 instance 024d3b9c _timerCallback
    6a7cda1c  400067e        8 ....ExecutionContext  0 instance 024d3bf8 _executionContext
    6a7d0944  400067f        c        System.Object  0 instance 00000000 _state
    6a7cac70  4000680      184 ...g.ContextCallback  0   shared   static _ccb
        >> Domain:Value  003e7410:024d5ff4 <<
    


    Now as you can guess the _timeCallback field value (in my case 024d3b9c) is the actual user specified delegate pending execution in the thread pool queue, something like:

    0:015> !do 024d3b9c
    Name: System.Threading.TimerCallback
    MethodTable: 6a7b72d8
    EEClass: 6a562ab8
    Size: 32(0x20) bytes
     (C:\Windows\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    6a7d0944  40000ff        4        System.Object  0 instance 024d3b90 _target
    6a7d019c  4000100        8 ...ection.MethodBase  0 instance 00000000 _methodBase
    6a7d35f0  4000101        c        System.IntPtr  1 instance   32c058 _methodPtr
    6a7d35f0  4000102       10        System.IntPtr  1 instance        0 _methodPtrAux
    6a7d0944  400010c       14        System.Object  0 instance 00000000 _invocationList
    6a7d35f0  400010d       18        System.IntPtr  1 instance        0 _invocationCount
    


    Here, as with any delegate _target is the object instance on which to call method the delegate points to (can be null if the method is static), in my example it's a instance of ThreadPoolTimers.Worker class:

    0:015> !do 024d3b90
    Name: ThreadPoolTimers.Worker
    MethodTable: 00323b58
    EEClass: 003213e8
    Size: 12(0xc) bytes
     (C:\Work\Fun\ThreadPoolTimers\bin\Debug\ThreadPoolTimers.exe)
    Fields:
    None
    


    And _methodPtr field can used to find the method name. Now, in the likely case that the method has been already JITTED the first insruction at the address will be a jump to the actual JITTED method, as it is in my case:

    0:015> u 32c058
    0032c058 e92b412d00      jmp     00600188
    

    In my example it's ThreadPoolTimers.Worker.DoSomething(System.Object), let's see:

    0:015> !ip2md 00600188
    MethodDesc: 00323b44
    Method Name: ThreadPoolTimers.Worker.DoSomething(System.Object)
    Class: 003213e8
    MethodTable: 00323b58
    mdToken: 06000003
    Module: 00322f2c
    IsJitted: yes
    CodeAddr: 00600188
    

    If however the first instruction at the _methodPtr address is a call to something like clr!PrecodeFixupThunk, you can still get the method name by dumping memory at the address and using !DumpMD on the 3rd pointer-sized value in the dump. More info on that can be found at: http://stackoverflow.com/questions/3668642/get-method-name-from-delegate-with-windbg

    Hope this helps (or at least is interesting ;)
     - Levi

    Sunday, November 25, 2012 9:59 PM
  • Levi, 

    Thanks for perfect reply !

    Tuesday, July 15, 2014 7:24 AM