5 Replies Latest reply on Feb 23, 2010 6:09 AM by kabirkhan

CallbackItem.changeCallback() very expensive due to context tracking

kabirkhan Feb 22, 2010 8:51 AM

I'm running a benchmark with 10 callbacks installed and 990 beans matching those callbacks, so I end up with 9,900 calls to SingleCallbackItem.changeCallback().

Relevant part of stacktrace along with number of calls and %cpu time taken

Thread [main] (Suspended)

(19,800 calls, 46.9% cpu) AbstractKernelControllerContext(AbstractControllerContext).getContextTracker() line: 389

(9,900 calls, 47.3% cpu) AbstractKernelControllerContext(AbstractControllerContext).getTarget(ControllerContext) line: 474

(9,900 calls, 47.6% cpu) ClassSingleCallbackItem(OwnerCallbackItem<T,C>).getTarget(ControllerContext, boolean) line: 68

ClassSingleCallbackItem(SingleCallbackItem<T>).changeCallback(ControllerContext, boolean) line: 62

ClassSingleCallbackItem(AbstractCallbackItem<T>).changeCallback(Controller, ControllerContext, boolean) line: 80

ClassSingleCallbackItem(OwnerCallbackItem<T,C>).changeCallback(Controller, ControllerContext, boolean) line: 116

What is really heavy inside ACC.getContextTracker() are:

A - 138,600 callls, 34% cpu

B - 19,800 calls 10.3% cpu

   public ContextTracker getContextTracker()
   {
      if (tracker == null || tracker == NOOP)
      {
         synchronized (this)
         {
            // since we got through, we must be the same caller
            if (tracker == NOOP)
               return null;
            // we waited, got through, but it's now changed
            if (tracker != null && tracker != NOOP)
               return tracker;
            tracker = NOOP; // mark that we're initializing
            ContextTracker ct = null;
            MetaData metaData = scopeInfo.getMetaData(); //B
            if (metaData != null)
            {
               ct = metaData.getMetaData(ContextTracker.class); //C
               if (ct == null)
               {
                  List<ScopeLevel> levels = CommonLevelsUtil.getSubLevels(DEFAULT_MINIMAL);
                  int instanceIndex = levels.indexOf(CommonLevels.INSTANCE);
                  for (int i = instanceIndex; i >= 0 && ct == null; i--)
                  {
                     MetaData md = metaData.getScopeMetaData(levels.get(i));  //A
                     if (md != null)
                        ct = md.getMetaData(ContextTracker.class);
                  }
               }
            }
            tracker = ct; // should we care if it's still null?
         }
      }
      return tracker;
   }

For A, maybe scopeInfo could keep a reference to the MetaData to avoid having to access the repository every time we call scopeInfo.getMetaData()?

For B I don't really understand exactly why this is being done? It looks like we check for ContextTracker in each metadata level at INSTANCE level and above, up to JVM. Wouldn't that be handled by the call to metaData.getMetaData() in C anyway?

1. Re: CallbackItem.changeCallback() very expensive due to context tracking

kabirkhan Feb 22, 2010 9:04 AM (in response to kabirkhan)

kabir.khan@jboss.com wrote:

For B I don't really understand exactly why this is being done? It looks like we check for ContextTracker in each metadata level at INSTANCE level and above, up to JVM. Wouldn't that be handled by the call to metaData.getMetaData() in C anyway?I

Changing this to the following works, but maybe we aren't using context tracking in the kernel tests?

   public ContextTracker getContextTracker()
   {
      if (tracker == null || tracker == NOOP)
      {
         synchronized (this)
         {
            // since we got through, we must be the same caller
            if (tracker == NOOP)
               return null;

            // we waited, got through, but it's now changed
            if (tracker != null && tracker != NOOP)
               return tracker;

            tracker = NOOP; // mark that we're initializing

            ContextTracker ct = null;
            MetaData metaData = scopeInfo.getMetaData();
            if (metaData != null)
            {
               ct = metaData.getMetaData(ContextTracker.class);
//               if (ct == null)
//               {
//                  List<ScopeLevel> levels = CommonLevelsUtil.getSubLevels(DEFAULT_MINIMAL);
//                  int instanceIndex = levels.indexOf(CommonLevels.INSTANCE);
//                  for (int i = instanceIndex; i >= 0 && ct == null; i--)
//                  {
//                     MetaData md = metaData.getScopeMetaData(levels.get(i));
//                     if (md != null)
//                        ct = md.getMetaData(ContextTracker.class);
//                  }
//               }
            }
            tracker = ct; // should we care if it's still null?
         }
      }
      return tracker;
   }

In turn about 60% of the time taken by calling ScopeKey.getScopeLevel(). If the above fix is not ok, I'll need to look at optimizing that.

2. Re: CallbackItem.changeCallback() very expensive due to context tracking

kabirkhan Feb 22, 2010 9:16 AM (in response to kabirkhan)

This might not be super important, does anybody have any numbers for how frequently callbacks are being used in AS?
Actions
3. Re: CallbackItem.changeCallback() very expensive due to context tracking

alesj Feb 22, 2010 11:59 AM (in response to kabirkhan)

For B I don't really understand exactly why this is being done? It looks like we check for ContextTracker in each metadata level at INSTANCE level and above, up to JVM. Wouldn't that be handled by the call to metaData.getMetaData() in C anyway?
Yeah, I think it you're right.
Since, if the context/scopeInfo's scope key doesn't include certain scope level,
looking additioanlly with C doesn't really help -- same result as with B.
e.g. B's MetaData is just a collection of Cs
For A, maybe scopeInfo could keep a reference to the MetaData to avoid having to access the repository every time we call scopeInfo.getMetaData()?

How many times do we invoke this?
For ContextTracker retrieval, this should only be called once, as we should get the CT on the first call.
(CT is setup in AS -- see kernel.xml, but not by default for MC tests)
Actions
4. Re: CallbackItem.changeCallback() very expensive due to context tracking

alesj Feb 22, 2010 12:03 PM (in response to kabirkhan)

This might not be super important, does anybody have any numbers for how frequently callbacks are being used in AS?
I would say a lot, as it's quite handy feature.
e.g. Deployers are picked up this way

Other usage includes AnnotationPlugins, some Management objects, some JMS destinations, ...
Apart from Deployers I doubt there are many instances that are picked up this way,
but the feature makes sure they are transparently picked, not needing explicit install calls.
Actions
5. Re: CallbackItem.changeCallback() very expensive due to context tracking

kabirkhan Feb 23, 2010 6:09 AM (in response to alesj)

alesj wrote:
Yeah, I think it you're right.
Since, if the context/scopeInfo's scope key doesn't include certain scope level,
looking additioanlly with C doesn't really help -- same result as with B.
e.g. B's MetaData is just a collection of Cs

I tried in AS and it does not go through to the expensive bit after the first few beans of the bootstrap (probably the ones installed before the context tracker). I've removed that code anyway and committed against https://jira.jboss.org/jira/browse/JBKERNEL-102

alesj wrote:

For ContextTracker retrieval, this should only be called once, as we should get the CT on the first call.
(CT is setup in AS -- see kernel.xml, but not by default for MC tests)

It looks like the initial call is expensive, but necessary, so my benchmarks are not realistic in this case. I put in some log statements and we do get some multiple calls to scopeInfo.getMetaData() instances but the overhead is low, total of 6ms on AS startup so there is no point in caching.
Actions

Go to original post