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?

Always assuming that your indirect way of limiting pointcuts to thread creation or execution is actually correct - as I said, you are not logging thread IDs, so I hope you already double-checked that while developing your aspect and are not falsely assuming that each message sent creates one and only one new thread - you could do two things if you wannt keep going with your "pertypewithin()" approach:

  • Either you use something like pertypewithin(business.security.tables.mq..*$endpoint*) or even pertypewithin(business.security.tables.mq..*Listener$$$endpoint*), relying of class naming schemes and get rid of some cruft in the actual pointcut,
  • or you add something like && MessageEndpoint+ to your pointcut's type pattern, narrowing down the existing pointcut further if you want to trade readability for type safety.

Either way, you said it is just a hacky debugging aspect, so probably not something you want to keep using in a production environment, so you should be fine. There might be a cleaner and more elegant way to do this, but in order to find out I would have to see some actual application code, not just the aspect.

Good luck!
--
Alexander Kriegisch
https://scrum-master.de
 

Eric B schrieb am 11.02.2019 10:05:

Hi Alex, thanks for interest.  Indeed, using some standard profiling tools would be helpful, but I don't have easy access to the environment.  Unfortunately, these performance issues are only showing up with a specific dataset that I can only find in a PreProd/Production Support Environment.  So I'm "cheating" a little by deploying my code with some additional logging to help me try to trace down where my bottlenecks are.  It's easier for me to deploy extra logging and search my logs than get a profiler agent installed in the environments or get access to JMX consoles/etc.
 
1. Yes - the strange class/package names are actually a cut & paste error on my side I think.  I just grabbed a quick subset of the logs, and must have pasted it incorrectly.  Execution log should read:
2019-02-10 13:19:44,523 DEBUG (Thread-19 (ActiveMQ-client-global-threads-1712540670)) [security.access.ListenerThreadLoggingAspect]   ID[1105118802]:  Start [business.security.tables.mq.SecurityAccessTableReadyListener$$$endpoint15].  MsgId:[ID:70c6fd2d-2d60-11e9-9a68-e3f05230c73d].  Concurrent Threads: 1
2019-02-10 13:19:44,523 DEBUG (Thread-19 (ActiveMQ-client-global-threads-1712540670)) [security.access.ListenerThreadLoggingAspect]   ID[1172392625]:  Start [business.security.tables.mq.SecurityAccessTableReadyListener$$$view13].  MsgId:[ID:70c6fd2d-2d60-11e9-9a68-e3f05230c73d].  Concurrent Threads: 2
 
2. I'm looking for a single log line - either the first or the second would be fine.  It's the fact that it is adding both lines which is throwing off my counter.  To be entirely honest, the fact that both lines come from some generated inner classes surprised me, but at the end of the day, it doesn't really matter to me what the class is called - just so long as there is a single execution.
 
3. I don't see any weaveinfo on the $$$view classes; the only place I see weaveinfo logs for this aspect are on the lines I pasted previously.  Any suggestions what else I can log to provide me with more insight as to where the $$$view class comes from?  I enabled the aj dumping (<dump within="*" beforeandafter="true"/>), to see the .class files generated, and indeed see references to a proxy inside the classes (both the $$$endpoint and the $$$view classes show the proxy).    The two classes are defined as:
 
public class SecurityAccessTableConsumeListener$$$endpoint12 extends SecurityAccessTableConsumeListener implements MessageEndpoint, MessageListener {


public class SecurityAccessTableConsumeListener$$$view76 extends SecurityAccessTableConsumeListener {


 
So, in both cases, the generated classes (proxy classes, it seems) extend the original class that I was targeting which extends my Abstract class.  So the Aspect and pointcut are clearly working, but too well.  Without knowing the inner workings of Wildfly/Weld/etc, how can I possibly write an effective pointcut not knowing how the container is going to handle this?  I realize that this likely wouldn't be an issue with CTW, but in the context of LTW, is there a way/switch to tell AJ to ignore any generated/inner classes?  My "hack" (see point #4 below) really does not seem like the correct approach.
 
4. I did add the messageId in the log output and see that it is the same message that is being counted twice, so clearly something I don't want.
 
I ended up manually excluding the $$$view class, but I see it as a really terrible solution.  Functional, sure, but not something that could possibly be maintainable.  My pointcut now becomes:
@Pointcut("!execution(* *..*$$$view*.*(..)) && execution(!synthetic * (*..mq.AbstractSecurityAccessTableListener+ && !*..mq.AbstractSecurityAccessTableListener).onMessage(..)) && args(msg)")

 
Thanks!
Eric
 
 
On Sun, Feb 10, 2019 at 8:13 PM Alexander Kriegisch <alexander@xxxxxxxxxxxxxx> wrote:

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.
_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/aspectj-users

Back to the top