552.aspx

COM+ Call Timers: the official way

As the title suggests, there are more than one way to get access to the COM+ call timers. This post gives and overview of how to get the call times using the official Microsoft COM+ Instrumentation APIs.

Why mess with the COM+ call timers?
I had a serious problem with components accessing an Oracle DB using OLEDB. In certain cases we queries never ended. Query timeouts are not supported in the Oracle OLEDB nor Microsoft OLEDB provider and changing the resource constraints in Oracle did not improve the situation. If the query went in tilt, it stayed in tilt -forever-. That is a bad, bad, thing in a system with hundreds of calls per second.. We tracked down the problem to a specific case: the Oracle stored procedure never returned if the stored procedure "header" was OK but the stored procedure "body" was invalid. The stored procedure call waited forever for the the stored procedure to get recompiled. In normal situation it recompiled by itself but there were cases with linked DBs etc where the Oracle stored procedure body stayed invalid until someone recompiled it by hand.

We tried asynchronous queries but they did not fix the situation. If the query was stuck, it stayed stuck and the abort method hung as well. We found one way that did work: use a separate thread for the query and kill the thread if it took to much time. The query did not timeout anymore but the memory leaks were enormous when we brutally terminated the thread.

The only fix I found was to implement COM+ recycling on steroids. Monitor the call times and shut down (recycle on Win2k3) the com+ package if the call times got too high. The stored procedure was still broken but the rest of the system continued working. No memory leak problems either as the com+ process was shut down in an orderly manner.

How to get the com+ call timers - the official way
The Component Services Console displays all sort of useful information like the number of objects in call, average call time etc. But, there is no official way to get the com+ call timers directly. You have to do the dirty work yourself and calculate the average call times.

The COM+ Spy example in the \Samples\Com\Administration\Spy in the Platform SDK shows how to get all the COM+ information you desire. Below I show the basic steps but please download the Platform SDK for a complete working example.

The COM+ internal information is made available via Loosely Coupled Events. You subscribe to one or more COM+ events and implement the corresponding interface to get notified. There are a whole set of COM+ Instrumentation Interfaces. The important ones for COM+ call tracking are:

• IComAppEvents:  OnAppActivation, OnAppShutdown, OnAppForceShutdown
  
• IComMethodEvents : OnMethodCall, OnMethodReturn, OnMethodException

They allow you to monitor COM+ application activation/shutdown and method call/return and provide you with all you need to calculate the call time. I used COM+ Spy as a skeleton and choose the following approach to tracking the call times:

• Implement a tracking object (CMethodMon in the example below)  for each com+ application you want to monitor. The class:
  
  
  
  • Implements the IComMethodsEvent interface to track call times
    
  • Implements the IComAppEvents interface to clear the current calls when an application shuts down
    
  • Subscribes to the IComMethodsEvent and IComAppEvents
    
  • Has one timer that fires every X seconds (configurable). The timer:
    
    
    
    • Calculates the average call time (highestCalltimes below)
      
    • Take appropriate action if the call times are too high (shut down component etc)

IComMethodsEvents
This is THE interface for call time tracking. It is called when a method is called or returns and when an exception occurs. You get a lot of information in the COMSVCSEVENTINFO structure like the process ID, current time stamp etc.

Keeping track is quite simple:

• Create a stack for each activate object (OID stack):
  
• Push call information on the OID stack in OnMethodCall. In my case I only care about the call time so I only push the performance counter
  
• Pop from the OID stack in OnMethodReturn

// Stack definition (only contains the time stamp as that's all I care about in this app)

typedef map TimeMap;

imeMap m_map;

 

STDMETHODIMP CMethodMon::OnMethodCall (COMSVCSEVENTINFO * pInfo, ULONG64 oid, REFCLSID cid, REFIID rid, ULONG iMeth)

{

      EnterCriticalSection(&m_csMapLock);

      TimeStack * pStack = m_map[oid];

      if (!pStack)

      {

            pStack = new TimeStack;

            m_map[oid] = pStack;

      }

      pStack -> push_front(pInfo->perfCount);

      LeaveCriticalSection(&m_csMapLock); 

      return S_OK;

}

 

STDMETHODIMP CMethodMon::OnMethodReturn (COMSVCSEVENTINFO * pInfo, ULONG64 oid, REFCLSID cid, REFIID rid, ULONG iMeth, HRESULT hr)

{

      TimeStack * pStack = m_map[oid];

      pStack -> pop_front();

     

      // Remove the entry for the oid if it's call stack is empty

      if (pStack -> empty())

      {    

            delete pStack;

            m_map.erase(oid);

      }

      return S_OK;

}

 

IComAppEvents
Only the OnAppShutdown event is of interest in the  IComAppEvents:

STDMETHODIMP CMethodMon::OnAppShutdown(COMSVCSEVENTINFO * pInfo, GUID guidApp)

{

      ClearCallTimes();

      return S_OK;

}

void CMethodMon::ClearCallTimes()

{

      EnterCriticalSection(&m_csMapLock);

     

      // Clear all the call times

      TimeMap::iterator iter;

      for (iter = m_map.begin( ); iter != m_map.end( ); iter++ )

      {

            TimeStack *pStack = (TimeStack *) (*iter).second;

 

            while (!pStack->empty())

            {

                  pStack -> pop_front();

            }

      }

      m_map.clear();

      LeaveCriticalSection(&m_csMapLock);

}

Calculating the highest call time is straightforward:

unsigned long CMethodMon::highestCallTime(void)

{

     

      long lHighestCallTime = 0;

      LONGLONG PerformanceFrequency;

      QueryPerformanceFrequency((LARGE_INTEGER *)&PerformanceFrequency);

 

      LONGLONG lNow;               

      QueryPerformanceCounter((LARGE_INTEGER *) &lNow);

 

      EnterCriticalSection(&m_csMapLock);

 

      // Step through all the oid's currently in call

      TimeMap::iterator iter;

      for (iter = m_map.begin( ); iter != m_map.end( ); iter++ )

      {

            TimeStack *pStack = (TimeStack *) (*iter).second;

 

            // Get the LAST element in the call stack as it will be the oldest element

            if (pStack)

            {

                  LONGLONG lOldest = pStack->back();

                  unsigned long lThisCallTime = (unsigned long)((1000*(lNow - lOldest))/

                                                                 PerformanceFrequency);

 

                  if (lThisCallTime > lHighestCallTime)

                  {

                        lHighestCallTime = lThisCallTime;

                  }

            }

      }          

     

      LeaveCriticalSection(&m_csMapLock);

     

      return lHighestCallTime;

}

 

There are known issues with the implementation above. Some error handling code has been removed and it does not take into account the fact that the PerformanceCounter will wrap sooner or later.

 

Issues with the official approach
The component gets called for each COM+ call (in the applications you monitor). Interesting in itself but you have to be a 110% sure you don't introduce deadlocks, memory leaks or anything else that affects the stability of the system.

I used the official approach for more than a year. It worked like a charm for weeks on end, but at random times I would get an enormous memory leak (>1GB) in the Windows RPC sub system on Win2k (I have not tried it on Win2k3). The leak may have been due to another process making heavy use of using COM+ notifications, a bug in my code or something else. It only happened when the machine was under heavy stress (100% CPU, and more than 1000 notifications per second for a few hours) so my -wild- guess is that other tasks got higher priority and the notifications continued to queue up until the system went in tilt.

The solution is not trivial to implement and requires the developer to know C++, ATL, COM admin APIs as well as Loosely Coupled Events. Finding skilled C++ COM+ programmers is hard so I decided to look for an easier to maintain solution. I will post the unofficial way I found tomorrow. It is a lot simpler and drops the source code from 1.500 lines of C++ to less than 150.