Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > comp.lang.java.programmer > #35422

Re: Logging database statement duration in a DRY way

Show all headers | View raw

On 8/19/2016 9:12 AM, Cecil Westerhof wrote:
> For this simple case I found a solution. The only part that really can
> change is the last part, so I now have:
>     startTime = System.nanoTime();
>     ps        = conn.prepareStatement(insertLine);
>     ps.setString(1, className);
>     ps.setLong(  2, pid);
>     ps.setLong(  3, free);
>     ps.setLong(  4, rt.maxMemory() / divideValue);
>     ps.setLong(  5, total);
>     ps.executeUpdate();
>     ps.close();
>     stopTime = System.nanoTime();
>     logDatabaseAction("preparedStatement saveMemoryLineNoGC", stopTime - startTime);
>
> And logDatabaseAction is:
>     private static void logDatabaseAction(String message, long duration) {
>         logMessage(String.format("%-40s took %e milliseconds",
>                                  message,
>                                  duration * 1E-6));
>      }

That is not a bad approach.

Probably the approach that you should go with.

But just in case you are interested in alternatives here a two ideas.

First some un timed code:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

public class Base {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             try(PreparedStatement pstmt = con.prepareCall("SELECT f1,f2 
FROM t1")) {
                 try(ResultSet rs = pstmt.executeQuery()) {
                     while(rs.next()) {
                         int f1 = rs.getInt("f1");
                         String f2 = rs.getString("f2");
                         System.out.printf("%d %s\n", f1, f2);
                     }
                 }
             }
         }
     }
}

Now the same code timed approx. the same way that you do:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

public class BaseTimed {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             long t1 = System.nanoTime();
             try(PreparedStatement pstmt = con.prepareCall("SELECT f1,f2 
FROM t1")) {
                 try(ResultSet rs = pstmt.executeQuery()) {
                     while(rs.next()) {
                         int f1 = rs.getInt("f1");
                         String f2 = rs.getString("f2");
                         System.out.printf("%d %s\n", f1, f2);
                     }
                 }
             }
             long t2 = System.nanoTime();
             System.out.printf("%s : %d\n", "main", t2 - t1);
         }
     }
}

And as I said then that is probably just fine.

But in case you want to decrease the amount of timing code each place,
then you could use a code block time measuring method.

Example:

package timerfun;

public class Timer {
     @FunctionalInterface
     public static interface CodeBlock {
         public void execute() throws Exception;
     }
     public static void time(String name, CodeBlock cb) throws Exception {
         long t1 = System.nanoTime();
         cb.execute();
         long t2 = System.nanoTime();
         System.out.printf("%s : %d\n", name, t2 - t1);
     }
}

And now the timed code looks like:

package timerfun;

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.PreparedStatement;
import java.sql.ResultSet;

import static timerfun.Timer.time;

public class Timed {
     public static void main(String[] args) throws Exception {
         try(Connection con = 
DriverManager.getConnection("jdbc:mysql://localhost/Test", "root", "")) {
             time("demo", () -> {
                 try(PreparedStatement pstmt = con.prepareCall("SELECT 
f1,f2 FROM t1")) {
                     try(ResultSet rs = pstmt.executeQuery()) {
                         while(rs.next()) {
                             int f1 = rs.getInt("f1");
                             String f2 = rs.getString("f2");
                             System.out.printf("%d %s\n", f1, f2);
                         }
                     }
                 }
             });
         }
     }
}

Just a method name and the context string. I think that is as short
as it is possible in pure Java.

But if we go outside of pure Java, then this is a text book case
for AOP!

We can do it with AspectJ without even touching the Java code.

package timerfun;

import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public class TimerAspect {
     private static Map<String,Long> store = new 
ConcurrentHashMap<String,Long>();
     @Pointcut("call(* java.sql.Connection.prepareCall(*)) && 
!within(TimerAspect)")
     public void start(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Pointcut("call(* java.sql.PreparedStatement.close()) && 
!within(TimerAspect)")
     public void end(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) {}
     @Around(value = "start(pjp, esp)")
     public Object startAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         String loc = esp.getSignature().toString();
         long t1 = System.nanoTime();
         store.put(loc, t1);
         Object res = pjp.proceed();
         return res;
     }
     @Around(value = "end(pjp, esp)")
     public Object endAround(ProceedingJoinPoint pjp, 
JoinPoint.EnclosingStaticPart esp) throws Throwable {
         Object res = pjp.proceed();
         long t2 = System.nanoTime();
         String loc = esp.getSignature().toString();
         long t1 = store.remove(loc);
         System.out.printf("%s : %d\n", loc, t2 - t1);
         return res;
     }
}

Arne

Back to comp.lang.java.programmer | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread

Thread

Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 14:32 +0200
  Re: Logging database statement duration in a DRY way Eric Sosman <esosman@comcast-dot-net.invalid> - 2016-08-19 09:05 -0400
    Re: Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 20:54 +0200
  Re: Logging database statement duration in a DRY way Cecil Westerhof <Cecil@decebal.nl> - 2016-08-19 15:12 +0200
    Re: Logging database statement duration in a DRY way Eric Sosman <esosman@comcast-dot-net.invalid> - 2016-08-19 10:01 -0400
    Re: Logging database statement duration in a DRY way Arne Vajhøj <arne@vajhoej.dk> - 2016-08-19 22:17 -0400
      Re: Logging database statement duration in a DRY way Arne Vajhøj <arne@vajhoej.dk> - 2016-08-19 22:37 -0400
  Re: Logging database statement duration in a DRY way Martin Gregorie <martin@address-in-sig.invalid> - 2016-08-19 16:05 +0000
    Re: Logging database statement duration in a DRY way Eric Douglas <e.d.programmer@gmail.com> - 2016-08-19 10:06 -0700
  Re: Logging database statement duration in a DRY way Steven Simpson <ss@my.domain.invalid> - 2016-08-19 22:34 +0100

csiph-web