javamonitoringaopaspectjtrace

why the static variable value is printed before the system start message in the output


What specific sequence of events or method calls within the program execution led to the static variable's value being printed before the system start,thread start and type load message in the output log?

"main", "1", "Main.java:4", "Field Write", "staticVariable is updated to 1"
"main", "2", "SYSTEM", "System Start", " "

AspectJAspect.aj

import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.aspectj.lang.JoinPoint;

@Aspect
public class AspectJAspect 
{
private static long aspectStartTime; // Variable to store the start time of the aspect
    private static int serialNumber = 1;

    // Pointcut to capture the main method of any class across any package
    @Pointcut("execution(public static void main(String[]))")
    public void mainMethod() {}

    // Advice triggered before entering the main method
    @Before("mainMethod()")
    public void beforeMainMethodExecution(JoinPoint joinPoint) 
    {
       // Capture start time of the aspect
       aspectStartTime = System.currentTimeMillis(); 
       // Print system start and thread start messages
       System.out.println("\"main\"" + ", \"" + serialNumber++ + "\"" + ", \"SYSTEM\"" + ", \"System Start\", \" \"");
       System.out.println("\"main\"" + ", \"" + serialNumber++ + "\"" + ", \"SYSTEM\"" + ", \"Thread Start\", \"main\"");
       // Print type load messages for Object class and the declaring class of the main method
       System.out.println("\"main\"" + ", \"" + serialNumber++ + "\"" + ", \"SYSTEM\"" + ", \"Type Load\", \"class=java.lang.Object\"");
       System.out.println("\"main\"" + ", \"" + serialNumber++ + "\"" + ", \"SYSTEM\"" + ", \"Type Load\", \"class=" + joinPoint.getSignature().getDeclaringType().getName() + "\"");
    }

    // Pointcut to capture any method execution
    @Pointcut("execution(* *(..))")
    public void anyMethod() {}

    // Pointcut to capture any constructor execution
    @Pointcut("call(*.new(..))")
    public void anyConstructor() {}

    // Pointcut to capture field updates within methods
    @Pointcut("set(* *) && !within(AspectJAspect)")
    public void fieldUpdate() {}

    // Advice triggered before any method execution
    @Before("anyMethod()")
    public void beforeMethodExecution(JoinPoint joinPoint) 
    {
        // Get thread name, method name, and source information
       String threadName = Thread.currentThread().getName();
       MethodSignature signature = (MethodSignature) joinPoint.getSignature();
       String methodName = signature.getName();
       String sourceInfo = joinPoint.getSourceLocation().getFileName() + ":" + joinPoint.getSourceLocation().getLine();
       // Print method entry message
       System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Method Entry\", \"" + methodName + "\"");
    }

    // Advice triggered after a field update within a method
    @After("fieldUpdate()")
    public void afterFieldUpdate(JoinPoint joinPoint) 
    {
       // Get field name, new value, thread name, and source information
       String fieldName = joinPoint.getSignature().getName();
       Object newValue = joinPoint.getArgs()[0];
       String threadName = Thread.currentThread().getName();
       String sourceInfo = joinPoint.getSourceLocation().getFileName() + ":" + joinPoint.getSourceLocation().getLine();
    
       // Check if the method signature represents a constructor
       boolean isConstructor = joinPoint.getSignature() instanceof MethodSignature &&
                             ((MethodSignature) joinPoint.getSignature()).getMethod().getName().equals("<init>");
    
       // Print field write message
       if (isConstructor) 
       {
           System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Field Write\", \"" + fieldName + " is updated to " + newValue + "\"");
       } 
       else 
       {
           System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Field Write\", \"" + fieldName + " is updated to " + newValue + "\"");
        }
     }

     // Advice triggered after any method execution
     @After("anyMethod()")
     public void afterMethodExecution(JoinPoint joinPoint) 
     {
         // Get thread name, method name, and source information
         String threadName = Thread.currentThread().getName();
         MethodSignature signature = (MethodSignature) joinPoint.getSignature();
         String methodName = signature.getName();
         String sourceInfo = joinPoint.getSourceLocation().getFileName() + ":" + joinPoint.getSourceLocation().getLine();
         // Print method exit message
         System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Method Exit\", \"" + methodName + "\"");
      }

     // Advice triggered before any constructor execution
     @Before("anyConstructor()")
     public void beforeConstructorExecution(JoinPoint joinPoint) 
     {
         // Get thread name, constructor name, and source information
         String threadName = Thread.currentThread().getName();
         String constructorName = joinPoint.getSignature().getName();
         String sourceInfo = joinPoint.getSourceLocation().getFileName() + ":" + joinPoint.getSourceLocation().getLine();
         // Print constructor entry message
         System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Constructor Entry\", \"" + constructorName + "\"");
     }

     // Advice triggered after any constructor execution
     @After("anyConstructor()")
     public void afterConstructorExecution(JoinPoint joinPoint) 
     {
         // Get thread name, constructor name, and source information
         String threadName = Thread.currentThread().getName();
         String constructorName = joinPoint.getSignature().getName();
         String sourceInfo = joinPoint.getSourceLocation().getFileName() + ":" + joinPoint.getSourceLocation().getLine();
         // Print constructor exit message
         System.out.println("\"" + threadName + "\"" + ", \"" + serialNumber++ + "\"" + ", \"" + sourceInfo + "\"" + ", \"Constructor Exit\", \"" + constructorName + "\"");
     }  

    // Advice triggered after the main method exits of any class across any package
    @After("execution(public static void main(String[]))")
    public void afterMainMethod(JoinPoint joinPoint) 
    {
         // Capture end time of the aspect
         long aspectEndTime = System.currentTimeMillis();
         // Calculate aspect execution time
         long aspectExecutionTime = aspectEndTime - aspectStartTime;
         // Print aspect execution time
        System.out.println("Aspect execution time: " + aspectExecutionTime + " milliseconds");
    }

}

Main.java

public class Main 
{
    public static int staticVariable = 1;
    public int a;
    public int b;
    public int c;
    public int d;
    public int e;

    public Main(int d, int e) 
    {
       this.d = d;
       this.e = e;
    }

    public static void main(String[] args) 
    {
       Main aop = new Main(5, 10);
       aop.methodA(5);
       aop.methodB(6);
       aop.methodC(7);
       Main.updateStaticVariable(8);
    }

    public void methodA(int value) 
    {
       a = value;
       a = 20;
    }

    public void methodB(int value)  
    {
       b = value;
       c = 15;
    }

    public void methodC(int value) 
    {
       d = value;
       e = 25;
    }

    public static void updateStaticVariable(int value) 
    {
       staticVariable = value;
     }
}

OUTPUT

"main", "1", "Main.java:4", "Field Write", "staticVariable is updated to 1"
"main", "2", "SYSTEM", "System Start", " "
"main", "3", "SYSTEM", "Thread Start", "main"
"main", "4", "SYSTEM", "Type Load", "class=java.lang.Object"
"main", "5", "SYSTEM", "Type Load", "class=org.mazouz.aop.Main"
"main", "6", "Main.java:16", "Method Entry", "main"
"main", "7", "Main.java:17", "Constructor Entry", "<init>"
"main", "8", "Main.java:12", "Field Write", "d is updated to 5"
"main", "9", "Main.java:13", "Field Write", "e is updated to 10"
"main", "10", "Main.java:17", "Constructor Exit", "<init>"
"main", "11", "Main.java:24", "Method Entry", "methodA"
"main", "12", "Main.java:25", "Field Write", "a is updated to 5"
"main", "13", "Main.java:26", "Field Write", "a is updated to 20"
"main", "14", "Main.java:24", "Method Exit", "methodA"
"main", "15", "Main.java:29", "Method Entry", "methodB"
"main", "16", "Main.java:30", "Field Write", "b is updated to 6"
"main", "17", "Main.java:31", "Field Write", "c is updated to 15"
"main", "18", "Main.java:29", "Method Exit", "methodB"
"main", "19", "Main.java:34", "Method Entry", "methodC"
"main", "20", "Main.java:35", "Field Write", "d is updated to 7"
"main", "21", "Main.java:36", "Field Write", "e is updated to 25"
"main", "22", "Main.java:34", "Method Exit", "methodC"
"main", "23", "Main.java:39", "Method Entry", "updateStaticVariable"
"main", "24", "Main.java:40", "Field Write", "staticVariable is updated to 8"
"main", "25", "Main.java:39", "Method Exit", "updateStaticVariable"
"main", "26", "Main.java:16", "Method Exit", "main"
 Aspect execution time: 45 milliseconds

What made the static variable value to appear before the system start message in the output log

"main", "1", "Main.java:4", "Field Write", "staticVariable is updated to 1"
"main", "2", "SYSTEM", "System Start", " "

Is there any way to capture the value assignment of the static variable within the Main class after the type load in the output?


Solution

  • What you call "system start" is the execution of a static method. Before that happens, the target class containing that method has been initialised already, as explained by user85421.

    What you want to intercept is static class initialisation:

    @Before("staticinitialization(Main)")
    

    Then, the log output will be something like this:

    "main", "1", "SYSTEM", "System Start", " "
    "main", "2", "SYSTEM", "Thread Start", "main"
    "main", "3", "SYSTEM", "Type Load", "class=java.lang.Object"
    "main", "4", "SYSTEM", "Type Load", "class=Main"
    "main", "5", "Main.java:2", "Field Write", "staticVariable is updated to 1"
    "main", "6", "Main.java:14", "Method Entry", "main"
    "main", "7", "Main.java:15", "Constructor Entry", "<init>"
    "main", "8", "Main.java:10", "Field Write", "d is updated to 5"
    "main", "9", "Main.java:11", "Field Write", "e is updated to 10"
    ...
    

    See https://eclipse.dev/aspectj/doc/latest/progguide/progguide.html#quick-pointcuts. I already pointed you to the programming guide in this answer to your previous question.