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