Thursday, January 30, 2014

Aspect oriented programming with Java

I started working with AspectJ and Perf4J recently. I did not have any prior AOP experience. I was looking for an example which did not use Spring AOP but I did not find a good sample which I could use to get my work done. Therefore, once I completed my project, thought of writing this sample up. There are a lot of tutorials out there which describes what AOP is. Therefore, I’m not going to introduce it here. You can do a Google search and find it out.

What I wanted was to measure the method runtimes without doing any modifications to the existing source. AspectJ helped me to achieve that.

Following are my sample source code. Following is my test class which I'm using to measure method runtimes.
import org.apache.log4j.Logger;

public class TestTarget {

    static Logger logger = Logger.getLogger(TestTarget.class);

    public static void main(String[] args) throws Exception {
        // Test case 01
        testCountFast(1000);

        // Test case 02
        testCountSlow(1000);

    }

    public static void testCountSlow(int value) {
        count(value,5);
    }

    public static void testCountFast(int value) {
        count(value,0);
    }

    private static void count(int value, int delay) {
        for (int i=0;i<value;i++) {
            try {
                Thread.sleep(delay);
            } catch (Exception e) {
                logger.error("Error occurred while sleeping", e);
            }
        }
    }

}
Following is my Aspect class which uses AspectJ and Perf4J.
import org.apache.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.perf4j.StopWatch;
import org.perf4j.log4j.Log4JStopWatch;

@Aspect
public class Perf4JAspect {
    static Logger logger = Logger.getLogger(Perf4JAspect.class);

    @Around("execution (* com.company.molva.aspectj.TestTarget.test*(..))")
    public Object measureExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        logger.info(MolvaLoggingUtil.getCurrentDateTime()
                + " MainAspect.measureExecutionTime() called on " + joinPoint.getSignature());

        long startNanoTime = System.nanoTime();
        StopWatch stopWatch = new Log4JStopWatch();
        Object proceed = joinPoint.proceed();
        stopWatch.stop(joinPoint.getSignature().toLongString());

        long endNanoTime = System.nanoTime();
        long executionNanoTime = endNanoTime - startNanoTime;
        logger.info(MolvaLoggingUtil.getCurrentDateTime() + " "
                + joinPoint.getSignature()+" took "+ executionNanoTime/1000000.0 +"ms");
        return proceed;
    }
}
My aop.xml configuration is as follows.
<aspectj>
    <aspects>
        <aspect name="com.company.molva.aspectj.MainAspect"/>
        <aspect name="com.company.molva.aspectj.Perf4JAspect"/>
    </aspects>

    <weaver options="-verbose">
        <include within="com.aspectj.*"/>
    </weaver>
</aspectj>
My log4j.xml looks as follows.
 
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="aspectjFileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="aspectj_stats.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>
 
    <appender name="CoalescingStatistics"
              class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="10000"/>
        <appender-ref ref="fileAppender"/>
    </appender>

    <appender name="fileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="perf_stats.log"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%m%n"/>
        </layout>
    </appender>

     <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="CoalescingStatistics"/>
    </logger>

    <root>
        <level value="INFO"/>
        <appender-ref ref="aspectjFileAppender"/>
    </root>
    
</log4j:configuration>
Once the sample completes running, I get the following logs at my log files.
aspectj_stats.log:
2014-01-30 13:19:25 MainAspect.measureExecutionTime() called on void com.company.molva.aspectj.TestTarget.testCountFast(int)
2014-01-30 13:19:25 void com.company.molva.aspectj.TestTarget.testCountFast(int) took 0.904ms
2014-01-30 13:19:25 MainAspect.measureExecutionTime() called on void com.company.molva.aspectj.TestTarget.testCountSlow(int)
2014-01-30 13:19:31 void com.company.molva.aspectj.TestTarget.testCountSlow(int) took 5608.996ms
perf_stats.log:
Performance Statistics   2014-01-30 13:19:20 - 2014-01-30 13:19:30
Tag                                                                        Avg(ms)         Min         Max     Std Dev       Count
public static void com.company.molva.aspectj.TestTarget.testCountFast(int)     0.0           0           0         0.0           1
public static void com.company.molva.aspectj.TestTarget.testCountSlow(int)  5608.0        5608        5608         0.0           1
As you can see, we can use AspectJ and Perf4J to generate some nice statistics.

Java library to convert XML to JSON

Recently I wanted to convert some XMLs to JSON messages. I came across this library called JSON-Java and found it very useful.
import org.json.JSONException;
import org.json.JSONObject;
import org.json.XML;

public class Main {

    public static int PRETTY_PRINT_INDENT_FACTOR = 4;
    public static String TEST_XML_STRING =
            "\n" +
                    "\n" +
                    "Belgian Waffles\n" +
                    "$5.95\n" +
                    "\n" +
                    "Two of our famous Belgian Waffles with plenty of real maple syrup\n" +
                    "\n" +
                    "650\n" +
                    "\n" +
                    "\n" +
                    "Strawberry Belgian Waffles\n" +
                    "$7.95\n" +
                    "\n" +
                    "Light Belgian waffles covered with strawberries and whipped cream\n" +
                    "\n" +
                    "900\n" +
                    "\n" +
                    "";

    public static void main(String[] args) {
        try {
            JSONObject xmlJSONObj = XML.toJSONObject(TEST_XML_STRING);
            String jsonPrettyPrintString = xmlJSONObj.toString(PRETTY_PRINT_INDENT_FACTOR);
            System.out.println(jsonPrettyPrintString);
        } catch (JSONException je) {
            System.out.println(je.toString());
        }
    }
}
The XML:
<breakfast_menu>
<food>
<name>Belgian Waffles</name>
<price>$5.95</price>
<description>
Two of our famous Belgian Waffles with plenty of real maple syrup
</description>
<calories>650</calories>
</food>
<food>
<name>Strawberry Belgian Waffles</name>
<price>$7.95</price>
<description>
Light Belgian waffles covered with strawberries and whipped cream
</description>
<calories>900</calories>
</food>
</breakfast_menu>
JSON:
{"breakfast_menu": {"food": [
    {
        "price": "$5.95",
        "description": "Two of our famous Belgian Waffles with plenty of real maple syrup",
        "name": "Belgian Waffles",
        "calories": 650
    },
    {
        "price": "$7.95",
        "description": "Light Belgian waffles covered with strawberries and whipped cream",
        "name": "Strawberry Belgian Waffles",
        "calories": 900
    }
]}}