JMX-SflowAgent stops collecting JVM metrics from aspectj instrumented WebSphere Application Server

Question

Project:

I use Sflow + Ganglia to monitor JVM metrics of Websphere Application Server (WAS). WAS is instrumented using AspectJ aspects. I have added an aspect to measure all application method runtimes.

I use Hsflowd as a JVM metrics collector. Hsflowd internally uses the JMX-SflowAgent javaagent to hook into the JVM to collect metrics using MXBeans (RuntimeMXBean, GarbageCollectorMXBean, CompilationMXBean and ThreadMXBean).

Issue:

When I run WAS without aspectjweaver hook I can see all metrics (CPU, desk, memory, process etc.) in Ganglia web continuously. But when aspectjweaver is added to JVM args and after restarting the server I can see the metrics for 10 mins, but after that it doesn't report JVM metrics in Ganglia web.

In the Aspectj weaving logs I can see that AspectJ is weaving the JMXsflowAgent code. Even though it is exclued via !call(* com.sflow.JMX.SFlowAgent(..)).

Aspect:

package com.foo.main;

import java.io.*;
import java.lang.reflect.Method;
import java.security.Signature;
import java.util.*;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.osgi.service.application.ApplicationAdminPermission;

@Aspect
public class ResponseTimeAspect {
    @Pointcut(
        "execution(* com.foo.*(..)) && " +
        "!within(com.foo.main.ResponseTimeAspect) && " + 
        "!within(ThreadLocal+) && " + 
        "!within(&& !within(*..*Aspect)) && " + 
        "!within(com.foo.main.AppInformationReader) && " + 
        "!within(@org.aspectj.lang.annotation.Aspect *) && " + 
        "!within(com.sflow.jmx.SFlowAgent) && " + 
        "!(call( * com.sflow.jmx.SFlowAgent(..)))"
    )
    public void loggingResponseTime() {}

    private static ThreadLocal<String> uuidContainer = new ThreadLocal<String>() {
        @Override
        protected String initialValue(){
            return UUID.randomUUID().toString();
        } 
    };

    AppInformationReader logWriter = AppInformationReader.getInstance();

    @Around("loggingResponseTime()")
    public Object tracing(ProceedingJoinPoint thisJoinPoint) throws Throwable {

        Long startTime= System.currentTimeMillis();
        Long startTotalMemory = Runtime.getRuntime().totalMemory();
        Long startFreeMemory = Runtime.getRuntime().freeMemory();

        Object ret = thisJoinPoint.proceed();

        Long elapsedTime=System.currentTimeMillis() - startTime;
        Long endTotalMemory = Runtime.getRuntime().totalMemory();
        Long endFreeMemory = Runtime.getRuntime().freeMemory(); 
        String methodSignature=thisJoinPoint.getSignature().toString();
        String classname=methodSignature.split("\\.")[thisJoinPoint.getSignature().toString().split("\\.").length-1];
        String methodName =thisJoinPoint.getSignature().getDeclaringType().getCanonicalName();
        logWriter.writeLog(uuidContainer.get().toString(), startTime, System.currentTimeMillis(), elapsedTime, classname, methodName);
        return ret;
     }
}

The JMX packages are under com.sflow.jmx.SFlowAgent.

Answer 1

Disclaimer: This is an answer, but not yet a solution. It does not make sense to write even more remarks , so I will rather refine my answer here as I gather more information from Vimlesh.

Okay, it is impossible to reproduce your problem with just the aspect and not a real SSCCE displaying the problematic behaviour. There are a lot of open questions:

• I do not know how many classes the aspect is being applied to,
• how many threads there are in the app server and
• what happens with memory consumption in the 10 minutes before and the time after the JMX results are no longer displayed.
• You said that the SFlow agent was running only once instead of every 10 seconds. How do you know? Can you please provide information explaining how you found out and how to reproduce the behaviour, optimally without an app server but with a plain Java SE VM?
• I also wonder why the aspect gathers information about free memory. Is that not what the other Java agent is expected to do? Why do it twice?
• It strikes me as odd that a variable named logWriter is an instance of AppInformationReader. So what is it, a reader or a writer? And what does the class do? The aspect uses it, but it is not shown.
• Why on earth do you create UUIDs per thread in the aspect and what are they used for? They seem to add no value, as I already said in the other question you posted earlier. You did not answer the question then, can you do it now? It looks like useless overhead.
• The pointcut is overkill. For example
  • execution(* com.foo.*(..)) only captures method executions in classes directly under package com.foo, but not in any sub-packages. So it is useless to exclude classes from sub-packages. Probably what you really want is execution(* com.foo..*(..)) - note the two dots in foo..* signifying subpackages.
  • You have misunderstood my answer in the other question because you did not choose one of my solutions to exclude the aspect and its internally used anonymous ThreadLocal subclass, but concatenated all of them with &&. That does not make it any better or more readable.
  • You try to exclude call( * com.sflow.jmx.SFlowAgent(..)), but for two reasons it is not necessary: Firstly, SFlowAgent is not in the targetted package com.foo. Secondly, an execution() joinpoint can never be a call() joinpoint at the same time, so the intersection set must be empty - no need to exclude the calls from the executions.
  • This syntax is invalid: !within(&& !within(*..*Aspect)) - maybe a copy & paste error concerning the nested within() clauses.

Having said that, you probably want this pointcut:

execution(* com.foo..*(..)) &&
!within(@org.aspectj.lang.annotation.Aspect *) &&
!within(com.foo.main.AppInformationReader)

That should be enough.

After having fixed your pointcut you can try to stop collecting and logging information in the aspect to make it more efficient. As for the other Java agent, there is no need to exclude it from aspect weaving, but maybe you need to exclude the aspect from being targetted by SFlowAgent. Maybe there is a problem in aspect code being instrumented by the SFlow agent, but that is just a guess. Maybe your configuration is wrong, maybe something else. It looks to me as though you are trying to wield two weapons (tools) you have never learned to use well enough. Without an SSCCE it is really hard to diagnose the problem's root cause.

Update: You can also try to list the AspectJ weaver as the first Java agent on the JVM command line, i.e. before the SFlow agent. Test if it makes any difference.