fixes issue 37431: increased time measurement precision
authorAsier Lostalé <asier.lostale@openbravo.com>
Fri, 01 Dec 2017 15:04:12 +0100
changeset 77 ae532a483a9a
parent 76 f2c0e0c54c9a
child 78 298e1d8f5033
fixes issue 37431: increased time measurement precision

Before it logged up to millisiconds, now microseconds (as decimals of millis
are logged).
src/org/openbravo/util/db/StatementInvocationHandler.java
src/org/openbravo/util/db/jmx/DBPoolLoggerConfigurator.java
--- a/src/org/openbravo/util/db/StatementInvocationHandler.java	Tue Jun 20 16:05:19 2017 +0200
+++ b/src/org/openbravo/util/db/StatementInvocationHandler.java	Fri Dec 01 15:04:12 2017 +0100
@@ -38,7 +38,10 @@
   private static final Logger log = LoggerFactory.getLogger(StatementInvocationHandler.class);
 
   private static final String SQL_NEW = " --- SQL: \n";
-  private static final String SQL_TIME = "\n  t:";
+  private static final String SQL_TIME = "\n  t: ";
+  private static final String MS = " ms";
+  private static final String FMT = "%.3f";
+  private static final double NANOS_IN_MS = 1_000_000d;
 
   private static final String PARAM_NEW = "\n     $";
   private static final String PARAM_SEPARATOR = ": ";
@@ -66,11 +69,11 @@
       params.add(PARAM_NEW + args[0] + PARAM_SEPARATOR + args[1]);
     }
 
-    long t = System.currentTimeMillis();
+    long t = System.nanoTime();
 
     Object obj = method.invoke(ps, args);
 
-    long totalTime = System.currentTimeMillis() - t;
+    long totalTime = System.nanoTime() - t;
 
     if (totalTime >= DBPoolLogger.getMinDurationStatements() && methodName.startsWith(EXECUTE)) {
       logStatement(methodName, totalTime);
@@ -81,7 +84,8 @@
 
   private void logStatement(String methodName, long totalTime) {
     StringBuilder logMsg = new StringBuilder();
-    logMsg.append(methodName).append(SQL_NEW).append(sql).append(SQL_TIME).append(totalTime);
+    logMsg.append(methodName).append(SQL_NEW).append(sql).append(SQL_TIME)
+        .append(String.format(FMT, totalTime / NANOS_IN_MS)).append(MS);
 
     if (params != null) {
       for (String param : params) {
--- a/src/org/openbravo/util/db/jmx/DBPoolLoggerConfigurator.java	Tue Jun 20 16:05:19 2017 +0200
+++ b/src/org/openbravo/util/db/jmx/DBPoolLoggerConfigurator.java	Fri Dec 01 15:04:12 2017 +0100
@@ -19,6 +19,9 @@
 
 package org.openbravo.util.db.jmx;
 
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.util.Arrays;
@@ -87,13 +90,20 @@
 
   @Override
   public long getMinDurationStatements() {
-    return DBPoolLogger.getMinDurationStatements();
+    // using milliseconds externally but nanoseconds internally
+    long durationNanos = DBPoolLogger.getMinDurationStatements();
+    return durationNanos <= 0 ? durationNanos : NANOSECONDS.toMillis(durationNanos);
   }
 
   @Override
   public void setMinDurationStatements(long minDurationStatements) {
     log.info("Min duration statements set to {} ", minDurationStatements);
-    DBPoolLogger.setMinDurationStatements(minDurationStatements);
+
+    // using milliseconds externally but nanoseconds internally
+    long durationNanos = minDurationStatements > 0 ? MILLISECONDS.toNanos(minDurationStatements)
+        : minDurationStatements;
+
+    DBPoolLogger.setMinDurationStatements(durationNanos);
   }
 
   @Override