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

    CallbackItem.changeCallback() very expensive due to context tracking

    Kabir Khan Master

      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
          Kabir Khan Master

          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
            Kabir Khan Master
            This might not be super important, does anybody have any numbers for how frequently callbacks are being used in AS?
            • 3. Re: CallbackItem.changeCallback() very expensive due to context tracking
              Ales Justin Master

              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)

              • 4. Re: CallbackItem.changeCallback() very expensive due to context tracking
                Ales Justin Master
                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.

                • 5. Re: CallbackItem.changeCallback() very expensive due to context tracking
                  Kabir Khan Master

                  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.