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