fix(debug): 修复debug消息中耗时计算异常的问题

api/pom.xml

@@ -5,7 +5,7 @@
     <parent>
         <groupId>cc.carm.lib</groupId>
         <artifactId>easysql-parent</artifactId>
-        <version>0.3.17</version>
+        <version>0.3.18</version>
     </parent>
     <modelVersion>4.0.0</modelVersion>
 

api/src/main/java/cc/carm/lib/easysql/api/SQLAction.java

@@ -12,6 +12,7 @@ import java.sql.SQLException;
 import java.util.Collections;
 import java.util.List;
 import java.util.UUID;
+import java.util.concurrent.TimeUnit;
 
 /**
  * SQLAction 是用于承载SQL语句并进行处理、返回的基本类。
@@ -49,11 +50,23 @@ public interface SQLAction<T> {
     @NotNull String getShortID();
 
     /**
-     * 得到该Action的创建时间
+     * 得到该Action的创建时间。
+     * <br>注意，此处获得的时间非时间戳毫秒数，仅用于计算耗时。
      *
+     * @return 创建时间 (毫秒)
+     */
+    default long getCreateTime() {
+        return getCreateTime(TimeUnit.MILLISECONDS);
+    }
+
+    /**
+     * 得到该Action的创建时间
+     * <br>注意，此处获得的时间非时间戳毫秒数，仅用于计算耗时。
+     *
+     * @param unit 时间单位
      * @return 创建时间
      */
-    long getCreateTime();
+    long getCreateTime(TimeUnit unit);
 
     /**
      * 得到该Action所要执行的源SQL语句

api/src/main/java/cc/carm/lib/easysql/api/SQLQuery.java

@@ -6,6 +6,7 @@ import cc.carm.lib.easysql.api.action.query.QueryAction;
 import java.sql.Connection;
 import java.sql.ResultSet;
 import java.sql.Statement;
+import java.util.concurrent.TimeUnit;
 
 /**
  * SQLQuery 是一个查询中间接口，用于查询操作的封装。
@@ -16,10 +17,22 @@ public interface SQLQuery extends AutoCloseable {
 
     /**
      * 获取该查询创建的时间
+     * <br>注意，此处获得的时间非时间戳毫秒数，仅用于计算耗时。
      *
      * @return 创建时间
      */
-    long getExecuteTime();
+    default long getExecuteTime() {
+        return getExecuteTime(TimeUnit.MILLISECONDS);
+    }
+
+    /**
+     * 获取该查询创建的时间
+     * <br>注意，此处获得的时间非时间戳毫秒数，仅用于计算耗时。
+     *
+     * @param timeUnit 时间单位
+     * @return 创建时间
+     */
+    long getExecuteTime(TimeUnit timeUnit);
 
     /**
      * 得到承载该SQLQuery的对应{@link SQLManager}

api/src/main/java/cc/carm/lib/easysql/api/function/SQLDebugHandler.java

@@ -10,6 +10,7 @@ import org.slf4j.Logger;
 
 import java.util.ArrayList;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 
 /**
  * 异常处理器。
@@ -30,11 +31,11 @@ public interface SQLDebugHandler {
     /**
      * 该方法将在 {@link SQLQuery#close()} 执行后调用。
      *
-     * @param query       {@link SQLQuery} 对象
+     * @param query           {@link SQLQuery} 对象
-     * @param executeTime 该次查询开始执行的时间
+     * @param executeNanoTime 该次查询开始执行的时间 (单位：纳秒)
-     * @param closeTime   该次查询彻底关闭的时间
+     * @param closeNanoTime   该次查询彻底关闭的时间 (单位：纳秒)
      */
-    void afterQuery(@NotNull SQLQuery query, long executeTime, long closeTime);
+    void afterQuery(@NotNull SQLQuery query, long executeNanoTime, long closeNanoTime);
 
     default String parseParams(@Nullable Object[] params) {
         if (params == null) return "<#NULL>";
@@ -51,40 +52,46 @@ public interface SQLDebugHandler {
     @SuppressWarnings("DuplicatedCode")
     static SQLDebugHandler defaultHandler(Logger logger) {
         return new SQLDebugHandler() {
+
             @Override
             public void beforeExecute(@NotNull SQLAction<?> action, @NotNull List<@Nullable Object[]> params) {
                 logger.info("┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━");
                 logger.info("┣# ActionUUID: {}", action.getActionUUID());
-                logger.info("┣# ActionType: {}", action.getClass().getName());
+                logger.info("┣# ActionType: {}", action.getClass().getSimpleName());
                 if (action.getSQLContents().size() == 1) {
                     logger.info("┣# SQLContent: {}", action.getSQLContents().get(0));
                 } else {
                     logger.info("┣# SQLContents: ");
                     int i = 0;
                     for (String sqlContent : action.getSQLContents()) {
-                        logger.info("┃ [{}] {}", ++i, sqlContent);
+                        logger.info("┃ - [{}] {}", ++i, sqlContent);
                     }
                 }
                 if (params.size() == 1) {
                     Object[] param = params.get(0);
-                    logger.info("┣# SQLParams: {}", parseParams(param));
+                    if (param != null) {
+                        logger.info("┣# SQLParam: {}", parseParams(param));
+                    }
                 } else if (params.size() > 1) {
                     logger.info("┣# SQLParams: ");
                     int i = 0;
                     for (Object[] param : params) {
-                        logger.info("┃ [{}] {}", ++i, parseParams(param));
+                        logger.info("┃ - [{}] {}", ++i, parseParams(param));
                     }
                 }
-                logger.info("┣# createTime: {}", action.getCreateTime());
+                logger.info("┣# CreateTime: {}", action.getCreateTime(TimeUnit.MILLISECONDS));
                 logger.info("┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━");
             }
 
             @Override
-            public void afterQuery(@NotNull SQLQuery query, long executeTime, long closeTime) {
+            public void afterQuery(@NotNull SQLQuery query, long executeNanoTime, long closeNanoTime) {
                 logger.info("┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━");
                 logger.info("┣# ActionUUID: {}", query.getAction().getActionUUID());
                 logger.info("┣# SQLContent: {}", query.getSQLContent());
-                logger.info("┣# executeCost: {} ms", (closeTime - executeTime));
+                logger.info("┣# CloseTime: {}  (cost {} ms)",
+                        TimeUnit.NANOSECONDS.toMillis(closeNanoTime),
+                        ((double) (closeNanoTime - executeNanoTime) / 1000000)
+                );
                 logger.info("┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━");
             }
         };

demo/pom.xml

@@ -5,7 +5,7 @@
     <parent>
         <artifactId>easysql-parent</artifactId>
         <groupId>cc.carm.lib</groupId>
-        <version>0.3.17</version>
+        <version>0.3.18</version>
     </parent>
     <modelVersion>4.0.0</modelVersion>
 

demo/src/test/java/cc/carm/lib/easysql/EasySQLTest.java

@@ -34,7 +34,7 @@ public class EasySQLTest {
         tests.add(new SQLUpdateBatchTests());
         tests.add(new SQLUpdateReturnKeysTest());
         tests.add(new QueryFunctionTest());
-        tests.add(new DeleteTest());
+//        tests.add(new DeleteTest());
 
         print("准备进行测试...");
 

demo/src/test/java/cc/carm/lib/easysql/tests/QueryCloseTest.java

@@ -1,8 +1,8 @@
 package cc.carm.lib.easysql.tests;
 
+import cc.carm.lib.easysql.TestHandler;
 import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.api.SQLQuery;
-import cc.carm.lib.easysql.TestHandler;
 
 import java.sql.ResultSet;
 import java.sql.SQLException;
@@ -29,6 +29,12 @@ public class QueryCloseTest extends TestHandler {
                 );
 
             }
+
+            try {
+                Thread.sleep(500L);
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
         }
 
     }

demo/src/test/java/cc/carm/lib/easysql/tests/QueryFunctionTest.java

@@ -16,6 +16,11 @@ public class QueryFunctionTest extends TestHandler {
                 .orderBy("id", false)
                 .setLimit(1)
                 .build().executeFunction(query -> {
+                    try {
+                        Thread.sleep(1000L);
+                    } catch (InterruptedException e) {
+                        throw new RuntimeException(e);
+                    }
                     if (!query.getResultSet().next()) return -1;
                     else return query.getResultSet().getInt("id");
                 });

demo/src/test/java/cc/carm/lib/easysql/tests/QueryNotCloseTest.java

@@ -1,8 +1,8 @@
 package cc.carm.lib.easysql.tests;
 
+import cc.carm.lib.easysql.TestHandler;
 import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.api.SQLQuery;
-import cc.carm.lib.easysql.TestHandler;
 
 import java.sql.ResultSet;
 import java.sql.SQLException;

demo/src/test/java/cc/carm/lib/easysql/tests/SQLUpdateBatchTests.java

@@ -1,7 +1,7 @@
 package cc.carm.lib.easysql.tests;
 
-import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.TestHandler;
+import cc.carm.lib.easysql.api.SQLManager;
 
 import java.sql.SQLException;
 import java.util.Arrays;

demo/src/test/java/cc/carm/lib/easysql/tests/TableAlterTest.java

@@ -1,8 +1,8 @@
 package cc.carm.lib.easysql.tests;
 
+import cc.carm.lib.easysql.TestHandler;
 import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.api.enums.NumberType;
-import cc.carm.lib.easysql.TestHandler;
 
 import java.sql.SQLException;
 

demo/src/test/java/cc/carm/lib/easysql/tests/TableCreateTest.java

@@ -1,9 +1,9 @@
 package cc.carm.lib.easysql.tests;
 
+import cc.carm.lib.easysql.TestHandler;
 import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.api.enums.ForeignKeyRule;
 import cc.carm.lib.easysql.api.enums.IndexType;
-import cc.carm.lib.easysql.TestHandler;
 
 import java.sql.SQLException;
 

demo/src/test/java/cc/carm/lib/easysql/tests/TableRenameTest.java

@@ -1,7 +1,7 @@
 package cc.carm.lib.easysql.tests;
 
-import cc.carm.lib.easysql.api.SQLManager;
 import cc.carm.lib.easysql.TestHandler;
+import cc.carm.lib.easysql.api.SQLManager;
 
 import java.sql.SQLException;
 

demo/src/test/resources/log4j2.xml

@@ -0,0 +1,26 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<Configuration status="WARN" packages="cc.carm.lib.easysql.EasySQLTest">
+    <Appenders>
+        <console name="Console" target="SYSTEM_OUT">
+            <PatternLayout pattern="[%d{HH:mm:ss} %level]: %msg%n"/>
+        </console>
+        <RollingRandomAccessFile name="File" fileName="logs/latest.log" filePattern="logs/%d{yyyy-MM-dd}-%i.log.gz">
+            <PatternLayout pattern="[%d{HH:mm:ss}] [%t/%level]: %msg{nolookups}%n"/>
+            <Policies>
+                <TimeBasedTriggeringPolicy/>
+                <OnStartupTriggeringPolicy/>
+            </Policies>
+        </RollingRandomAccessFile>
+    </Appenders>
+    <Loggers>
+        <Root level="info">
+            <filters>
+                <MarkerFilter marker="NETWORK_PACKETS" onMatch="DENY" onMismatch="NEUTRAL"/>
+                <RegexFilter regex=".*\$\{[^}]*\}.*" onMatch="DENY" onMismatch="NEUTRAL"/>
+            </filters>
+            <AppenderRef ref="File"/>
+            <appender-ref ref="Console"/>
+        </Root>
+    </Loggers>
+</Configuration>
+

impl/pom.xml

@@ -5,7 +5,7 @@
     <parent>
         <artifactId>easysql-parent</artifactId>
         <groupId>cc.carm.lib</groupId>
-        <version>0.3.17</version>
+        <version>0.3.18</version>
     </parent>
     <modelVersion>4.0.0</modelVersion>
 

impl/src/main/java/cc/carm/lib/easysql/action/AbstractSQLAction.java

@@ -10,35 +10,36 @@ import java.sql.SQLException;
 import java.util.List;
 import java.util.Objects;
 import java.util.UUID;
+import java.util.concurrent.TimeUnit;
 
 public abstract class AbstractSQLAction<T> implements SQLAction<T> {
 
     protected final @NotNull String sqlContent;
     private final @NotNull SQLManagerImpl sqlManager;
     private final @NotNull UUID uuid;
-    private final long createTime;
+    private final long createNanoTime;
 
     public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql) {
-        this(manager, sql, System.currentTimeMillis());
+        this(manager, sql, System.nanoTime());
     }
 
     public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql, @NotNull UUID uuid) {
-        this(manager, sql, uuid, System.currentTimeMillis());
+        this(manager, sql, uuid, System.nanoTime());
     }
 
-    public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql, long createTime) {
+    public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql, long createNanoTime) {
-        this(manager, sql, UUID.randomUUID(), createTime);
+        this(manager, sql, UUID.randomUUID(), createNanoTime);
     }
 
     public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql,
-                             @NotNull UUID uuid, long createTime) {
+                             @NotNull UUID uuid, long createNanoTime) {
         Objects.requireNonNull(manager);
         Objects.requireNonNull(sql);
         Objects.requireNonNull(uuid);
         this.sqlManager = manager;
         this.sqlContent = sql;
         this.uuid = uuid;
-        this.createTime = createTime;
+        this.createNanoTime = createNanoTime;
     }
 
 
@@ -53,8 +54,8 @@ public abstract class AbstractSQLAction<T> implements SQLAction<T> {
     }
 
     @Override
-    public long getCreateTime() {
+    public long getCreateTime(TimeUnit unit) {
-        return this.createTime;
+        return unit.convert(createNanoTime, TimeUnit.NANOSECONDS);
     }
 
     @Override

impl/src/main/java/cc/carm/lib/easysql/action/query/PreparedQueryActionImpl.java

@@ -67,12 +67,10 @@ public class PreparedQueryActionImpl extends QueryActionImpl implements Prepared
         }
 
         try {
-            long executeTime = System.currentTimeMillis();
             SQLQueryImpl query = new SQLQueryImpl(
                     getManager(), this,
                     connection, preparedStatement,
-                    preparedStatement.executeQuery(),
+                    preparedStatement.executeQuery()
-                    executeTime
             );
             getManager().getActiveQuery().put(getActionUUID(), query);
             return query;

impl/src/main/java/cc/carm/lib/easysql/action/query/QueryActionImpl.java

@@ -35,12 +35,10 @@ public class QueryActionImpl extends AbstractSQLAction<SQLQuery> implements Quer
         }
 
         try {
-            long executeTime = System.currentTimeMillis();
             SQLQueryImpl query = new SQLQueryImpl(
                     getManager(), this,
                     connection, statement,
-                    statement.executeQuery(getSQLContent()),
+                    statement.executeQuery(getSQLContent())
-                    executeTime
             );
             getManager().getActiveQuery().put(getActionUUID(), query);
 

impl/src/main/java/cc/carm/lib/easysql/query/SQLQueryImpl.java

@@ -8,22 +8,23 @@ import java.sql.Connection;
 import java.sql.ResultSet;
 import java.sql.SQLException;
 import java.sql.Statement;
+import java.util.concurrent.TimeUnit;
 
 public class SQLQueryImpl implements SQLQuery {
 
     protected final long executeTime;
 
     protected final SQLManagerImpl sqlManager;
-    final Connection connection;
+    protected final Connection connection;
-    final Statement statement;
+    protected final Statement statement;
-    final ResultSet resultSet;
+    protected final ResultSet resultSet;
     protected QueryActionImpl queryAction;
 
     public SQLQueryImpl(
             SQLManagerImpl sqlManager, QueryActionImpl queryAction,
             Connection connection, Statement statement, ResultSet resultSet
     ) {
-        this(sqlManager, queryAction, connection, statement, resultSet, System.currentTimeMillis());
+        this(sqlManager, queryAction, connection, statement, resultSet, System.nanoTime());
     }
 
     public SQLQueryImpl(
@@ -40,8 +41,8 @@ public class SQLQueryImpl implements SQLQuery {
     }
 
     @Override
-    public long getExecuteTime() {
+    public long getExecuteTime(TimeUnit timeUnit) {
-        return this.executeTime;
+        return timeUnit.convert(this.executeTime, TimeUnit.NANOSECONDS);
     }
 
     @Override
@@ -73,7 +74,7 @@ public class SQLQueryImpl implements SQLQuery {
 
             if (getManager().isDebugMode()) {
                 try {
-                    getManager().getDebugHandler().afterQuery(this, getExecuteTime(), System.currentTimeMillis());
+                    getManager().getDebugHandler().afterQuery(this, getExecuteTime(TimeUnit.NANOSECONDS), System.nanoTime());
                 } catch (Exception ex) {
                     ex.printStackTrace();
                 }

pom.xml

@@ -19,7 +19,7 @@
     <groupId>cc.carm.lib</groupId>
     <artifactId>easysql-parent</artifactId>
     <packaging>pom</packaging>
-    <version>0.3.17</version>
+    <version>0.3.18</version>
 
     <modules>
         <module>api</module>

with-pool/beecp/pom.xml

@@ -5,7 +5,7 @@
     <parent>
         <artifactId>easysql-parent</artifactId>
         <groupId>cc.carm.lib</groupId>
-        <version>0.3.17</version>
+        <version>0.3.18</version>
         <relativePath>../../pom.xml</relativePath>
     </parent>
     <modelVersion>4.0.0</modelVersion>

with-pool/hikaricp/pom.xml

@@ -5,7 +5,7 @@
     <parent>
         <artifactId>easysql-parent</artifactId>
         <groupId>cc.carm.lib</groupId>
-        <version>0.3.17</version>
+        <version>0.3.18</version>
         <relativePath>../../pom.xml</relativePath>
     </parent>
     <modelVersion>4.0.0</modelVersion>