Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [aspectj-users] What is the correct pointcut expression to use with Proxied EJB classes?

Hi Eric, just a few follow-up questions:

  1. Am I understanding correctly that the classnames logged are just contracted versions cut off in the middle to have a maximum length, i.e. the strange class/package names are an artifact of logging itself?
  2. Am I understanding correctly that the first logged line is what you want, but not the second one?
  3. If so, do you see any weave info for the "view76" class? Because if you don't, it probably is just a subclass (maybe a proxy as you assume) of "endpoint14" inheriting the "onMessage(..)" method. Maybe you can verify this assumption with some more logging.
  4. Before you exclude "*..*$view*" from "pertypewithin", maybe you could also log actual thread IDs and check if you are really counting/logging the right thing. Maybe there is a new thread for "view76" which you want to count, maybe not. I have no idea about JEE and application servers and how WildFly works internally.
BTW and slightly off-topic, have you also tried to use internal application server logging/monitoring/reporting tools in order to check your assumptions? Or profiling tools like VisualVM? Anyway, this one is interesting purely from an AOP perspective. ;-)
 
Kind regards
--
Alexander Kriegisch
https://scrum-master.de
 

Eric B schrieb am 11.02.2019 00:13:

I've got a JEE application with some performance issues.  I suspect that it is due to MQ listeners (MessageDrivenBeans) that are not executing enough threads concurrently and figured that an easy way to validate my theory would be to write a quick Aspect to profile the number of threads being triggered at the same time.
 
I'm using LTW in the rest of my application, so trying to use LTW for this aspect as well.
 
While my Aspect works in theory, it seems to be advising the "wrong" beans; that is- it is picking out what seem to be container generated beans instead of my primary beans, and consequently, it is providing false information.  The 5 listeners that I want to advise extend a common Abstract class which implements the onMessage() method.  I'm trying to advise this method for all beans.
 
My Aspect is as follows:
 
@Aspect("pertypewithin(business.security.tables.mq.*)")

public class ListenerThreadLoggingAspect {
    // get a static slf4j logger for the class
    protected static final Logger logger = getLogger(ListenerThreadLoggingAspect.class);

    private static AtomicInteger concurrentThreadCount = new AtomicInteger(0);

    // pointcut to pick out the onMessage() method
    @Pointcut("execution(!synthetic * (*..mq.AbstractSecurityAccessTableListener+ && !*..mq.AbstractSecurityAccessTableListener).onMessage(..))")
    public void onMessagePointcut() {
    }


    @Around("onMessagePointcut()")
    public Object logThreadCount(ProceedingJoinPoint pjp) throws Throwable {

        // entering message handler, so increment threads and log
        int concurrentThreads = concurrentThreadCount.incrementAndGet();
        logger.debug("ID[{}]:  Start [{}].  Concurrent Threads: {}", System.identityHashCode(this), pjp.getTarget().getClass().getName(), concurrentThreads);

        // execute the listener
        Object result = pjp.proceed();

        // done so decrement number of threads
        concurrentThreads = concurrentThreadCount.decrementAndGet();
        logger.trace("ID[{}]: Stop  [{}].  Concurrent Threads: {}", System.identityHashCode(this), pjp.getTarget().getClass().getName(), concurrentThreads);

        return result;
    }

}
While the weaver indicates that the correct classes are being woven, the execution shows a different trace:
2019-02-10 11:59:33,036 ERROR (default-threads - 5) [stderr]   [ModuleClassLoader@572dc861] weaveinfo Join point 'method-execution(void business.security.tables.mq.SecurityAccessTablePurgeListener$$$endpoint11.onMessage(javax.jms.Message))' in Type 'business.security.tables.mq.SecurityAccessTablePurgeListener$$$endpoint11' (no debug info available) advised by around advice from 'izone.common.security.access.ListenerThreadLoggingAspect' (ListenerThreadLoggingAspect.java)
2019-02-10 11:59:33,124 ERROR (default-threads - 4) [stderr]   [ModuleClassLoader@572dc861] weaveinfo Join point 'method-execution(void business.security.tables.mq.SecurityAccessTableConsumeListener$$$endpoint14.onMessage(javax.jms.Message))' in Type 'business.security.tables.mq.SecurityAccessTableConsumeListener$$$endpoint14' (no debug info available) advised by around advice from 'izone.common.security.access.ListenerThreadLoggingAspect' (ListenerThreadLoggingAspect.java)
2019-02-10 11:59:33,187 ERROR (default-threads - 10) [stderr]   [ModuleClassLoader@572dc861] weaveinfo Join point 'method-execution(void business.security.tables.mq.SecurityAccessTableRequestListener$$$endpoint12.onMessage(javax.jms.Message))' in Type 'business.security.tables.mq.SecurityAccessTableRequestListener$$$endpoint12' (no debug info available) advised by around advice from 'izone.common.security.access.ListenerThreadLoggingAspect' (ListenerThreadLoggingAspect.java)
2019-02-10 11:59:33,296 ERROR (default-threads - 7) [stderr]   [ModuleClassLoader@572dc861] weaveinfo Join point 'method-execution(void business.security.tables.mq.SecurityAccessTableReadyListener$$$endpoint9.onMessage(javax.jms.Message))' in Type 'business.security.tables.mq.SecurityAccessTableReadyListener$$$endpoint9' (no debug info available) advised by around advice from 'izone.common.security.access.ListenerThreadLoggingAspect' (ListenerThreadLoggingAspect.java)
2019-02-10 11:59:33,432 ERROR (default-threads - 6) [stderr]   [ModuleClassLoader@572dc861] weaveinfo Join point 'method-execution(void business.security.tables.mq.SecurityAccessTableStatisticsListener$$$endpoint8.onMessage(javax.jms.Message))' in Type 'business.security.tables.mq.SecurityAccessTableStatisticsListener$$$endpoint8' (no debug info available) advised by around advice from 'izone.common.security.access.ListenerThreadLoggingAspect' (ListenerThreadLoggingAspect.java)
 
 
Execution Log:
12:00:19,585 DEBUG [common.security.access.ListenerThreadLoggingAspect] (Thread-30 (ActiveMQ-client-global-threads-508854362)) ID[1049816548]:  Start [business.securitytyAccessTableConsumeListener$$$endpoint14].  Concurrent Threads: 1
12:00:19,586 DEBUG [common.security.access.ListenerThreadLoggingAspect] (Thread-30 (ActiveMQ-client-global-threads-508854362)) ID[984444654]:  Start [business.security.yAccessTableConsumeListener$$$view76].  Concurrent Threads: 2
 
 
As you can see, in the Execution Log, I have 2 advised points which are triggering the aspect:
business.securitytyAccessTableConsumeListener$$$endpoint14 
business.security.yAccessTableConsumeListener$$$view76
 
 
I suspect this is due to the way Wildfly creates proxies for the EJB/MDBs when instantiating them.  However, I am not sure how to avoid this.  I _thought_ that was what the synthetic keyword would avoid, but it has made no difference to the pointcut.
 
Is there a "correct" way to write this pointcut to avoid this issue and only advise the "$$endpointXX" bean and not the "$$viewXX" bean?  Excluding it explicitly seems like an ugly hack.

Back to the top