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

CarmJos · Jun 6, 2022 · 9b4460f · 9b4460f
1 parent f16b5f2
commit 9b4460f
Show file tree

Hide file tree

Showing 22 changed files with 117 additions and 49 deletions.
diff --git a/api/pom.xml b/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>
 

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

diff --git a/api/src/main/java/cc/carm/lib/easysql/api/SQLQuery.java b/api/src/main/java/cc/carm/lib/easysql/api/SQLQuery.java
@@ -6,6 +6,7 @@
 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}

diff --git a/api/src/main/java/cc/carm/lib/easysql/api/function/SQLDebugHandler.java b/api/src/main/java/cc/carm/lib/easysql/api/function/SQLDebugHandler.java
@@ -10,6 +10,7 @@
 
 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 executeTime 该次查询开始执行的时间
-     * @param closeTime   该次查询彻底关闭的时间
+     * @param query           {@link SQLQuery} 对象
+     * @param executeNanoTime 该次查询开始执行的时间 (单位：纳秒)
+     * @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 @@ default String parseParams(@Nullable Object[] params) {
     @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("┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━");
             }
         };

diff --git a/demo/pom.xml b/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>
 

diff --git a/demo/src/test/java/cc/carm/lib/easysql/EasySQLTest.java b/demo/src/test/java/cc/carm/lib/easysql/EasySQLTest.java
@@ -34,7 +34,7 @@ public void onTest() {
         tests.add(new SQLUpdateBatchTests());
         tests.add(new SQLUpdateReturnKeysTest());
         tests.add(new QueryFunctionTest());
-        tests.add(new DeleteTest());
+//        tests.add(new DeleteTest());
 
         print("准备进行测试...");
 

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/QueryCloseTest.java b/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 void onTest(SQLManager sqlManager) throws SQLException {
                 );
 
             }
+
+            try {
+                Thread.sleep(500L);
+            } catch (InterruptedException e) {
+                throw new RuntimeException(e);
+            }
         }
 
     }

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/QueryFunctionTest.java b/demo/src/test/java/cc/carm/lib/easysql/tests/QueryFunctionTest.java
@@ -16,6 +16,11 @@ public void onTest(SQLManager sqlManager) throws SQLException {
                 .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");
                 });

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/QueryNotCloseTest.java b/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;

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/SQLUpdateBatchTests.java b/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;

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/TableAlterTest.java b/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;
 

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/TableCreateTest.java b/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;
 

diff --git a/demo/src/test/java/cc/carm/lib/easysql/tests/TableRenameTest.java b/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;
 

diff --git a/demo/src/test/resources/log4j2.xml b/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>
+
diff --git a/impl/pom.xml b/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>
 

diff --git a/impl/src/main/java/cc/carm/lib/easysql/action/AbstractSQLAction.java b/impl/src/main/java/cc/carm/lib/easysql/action/AbstractSQLAction.java
@@ -10,35 +10,36 @@
 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) {
-        this(manager, sql, UUID.randomUUID(), createTime);
+    public AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql, long createNanoTime) {
+        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 AbstractSQLAction(@NotNull SQLManagerImpl manager, @NotNull String sql,
     }
 
     @Override
-    public long getCreateTime() {
-        return this.createTime;
+    public long getCreateTime(TimeUnit unit) {
+        return unit.convert(createNanoTime, TimeUnit.NANOSECONDS);
     }
 
     @Override

diff --git a/impl/src/main/java/cc/carm/lib/easysql/action/query/PreparedQueryActionImpl.java b/impl/src/main/java/cc/carm/lib/easysql/action/query/PreparedQueryActionImpl.java
@@ -51,7 +51,7 @@ public PreparedQueryActionImpl handleStatement(@Nullable Consumer<PreparedStatem
     @Override
     public @NotNull SQLQueryImpl execute() throws SQLException {
         debugMessage(Collections.singletonList(params));
-        
+
         Connection connection = getManager().getConnection();
         PreparedStatement preparedStatement;
         try {
@@ -67,12 +67,10 @@ public PreparedQueryActionImpl handleStatement(@Nullable Consumer<PreparedStatem
         }
 
         try {
-            long executeTime = System.currentTimeMillis();
             SQLQueryImpl query = new SQLQueryImpl(
                     getManager(), this,
                     connection, preparedStatement,
-                    preparedStatement.executeQuery(),
-                    executeTime
+                    preparedStatement.executeQuery()
             );
             getManager().getActiveQuery().put(getActionUUID(), query);
             return query;

diff --git a/impl/src/main/java/cc/carm/lib/easysql/action/query/QueryActionImpl.java b/impl/src/main/java/cc/carm/lib/easysql/action/query/QueryActionImpl.java
@@ -35,12 +35,10 @@ public QueryActionImpl(@NotNull SQLManagerImpl manager, @NotNull String sql) {
         }
 
         try {
-            long executeTime = System.currentTimeMillis();
             SQLQueryImpl query = new SQLQueryImpl(
                     getManager(), this,
                     connection, statement,
-                    statement.executeQuery(getSQLContent()),
-                    executeTime
+                    statement.executeQuery(getSQLContent())
             );
             getManager().getActiveQuery().put(getActionUUID(), query);