AspectJ Used to profile query execution making aplicaiont too slow

Question

I am using AspecJ to capture the query being executed in each of the form and show the time each query takes to execute. We are using spring jdbc and my aspect look as below: @Aspect public class QueryProfilerAspect {

@Pointcut("call(* org.springframework.jdbc.core.simple.SimpleJdbcTemplate.query*  (..))")
public void profileQuery() {
}

@Around("profileQuery()")
public Object profile(ProceedingJoinPoint thisJoinPoint) throws Throwable {
    // System.out.println("Inside join point execution");
    SimpleJdbcTemplate template = (SimpleJdbcTemplate) thisJoinPoint
            .getTarget();
    JdbcTemplate jdbcTemplate = (JdbcTemplate) template
            .getNamedParameterJdbcOperations().getJdbcOperations();
    DataSource ds = jdbcTemplate.getDataSource();
    // System.out.println("Datasource name URL =="
    // + ds.getConnection().getMetaData().getURL());
    // System.out.println("Datasource name  ==" + schemaName);

    String sqlQuery = thisJoinPoint.getArgs()[0].toString();
    final long start, end;
    start = System.nanoTime();
    Object ll = thisJoinPoint.proceed();
    end = System.nanoTime();
    long executionTime = ((end - start) / 1000) / 1000;
    System.out.println("execution_time=" +executionTime  + sqlquery="+sqlQuery );
    return ll;

}

Functionality wise this works however if i put this i my application it makes the application too slow. I am using compile time weaving. And the aspect finds 1683 query* method calls within the application.

Is there anything I can do to optimize this. Any suggestion/help will be really appreciated.

score 0 · Answer 1 · edited May 23 '17 at 12:16

0

First I would advice against using System.nanoTime(). It's precision using cold like that is atrocious and pretty much useless for measuring timespans. Certainly not better than System.currentTimeMillies() if you divide the result anyway.

What probably slows you down most though, are the the String operations performed at various places in your aspect. If you have to concatenate Strings, at least use a StringBuilder to do so before outputting it. That might be done by the optimizer already, but you can never be too sure. ;)

And... Sysout isn't exactly the way to go if you want logging - looking into one of the various logging implementations (slf4j with logback is my personal favourite, but there are others as well) will be worth your time.

Especially if you want to use the fact that Spring has the feature you are trying to build (, as asked and answered here before: Seeing the underlying SQL in the Spring JdbcTemplate? (Edit: I know it's only the query, not the time measuring, but not having to worry about that should shave some time off your overhead as well.)

edited May 23 '17 at 12:16

Community

1
1

answered Jul 24 '13 at 17:43

sheltem

3,754
1
34
39

Thanks for the response. I need both query and the execution time. And the system.out are just for my testing purpose. In real senario my requirement is to create a object which has sqlquery and execution time as its parameters. I am using AspectJ and my web application is on JSF. So, I am thinking to use Spring AOP now. Do you think that will help? – milan Jul 24 '13 at 18:29
Well, yes. Aside from the object to hold both informations, you are already doing what you said you wanted, albeit a bit unoptimized. Weaving an aspect around the method to both capture the query and measure execution time is the way to go here. You just have to be careful what you do in the aspect, minimize how many operations you do and how many objects you create. – sheltem Jul 24 '13 at 18:54
Why do you think System.nanoTime() precision is atrocious? It's accuracy is orders of magnitude better than System.currentTimeMillis() and isn't affected by changes to the system clock on the machine. – tddmonkey Sep 11 '13 at 10:06
I should have phrased that better: It's precision is atrocious for what it's name implies - especially if used cold. https://blogs.oracle.com/dholmes/entry/inside_the_hotspot_vm_clocks and http://www.oracle.com/technetwork/java/hotspotfaq-138619.html have more info on the topic. My main gripe with it's use here though, is the 'long executionTime = ((end - start) / 1000) / 1000;'-line. If you convert to millis anyway, why bother with nano? In this case you get no added benefit from a method that actually takes longer to execute. – sheltem Sep 11 '13 at 10:25
The document you just linked document says: "The update resolution of [currentTimeMillis] is often the same as the timer interrupt (eg. 10ms) [...] You should always try to use nanoTime to do timing measurement [...], in the hope that it will have a better resolution than currentTimeMillis." It may very well be that some measurement takes less than 10ms, but you still want to track its time in ms. – orsg Jun 21 '16 at 06:53

AspectJ Used to profile query execution making aplicaiont too slow

1 Answers1