Merge pull request #3859 from actiontech/3.22.01.99/lts_2082

[inner-2082] fix: the commit time statistics in the slow log are incorrect
actiontech · Feb 26, 2024 · 316e070 · 316e070
2 parents e80d3f8 + e6f6f94
commit 316e070
Show file tree

Hide file tree

Showing 5 changed files with 44 additions and 13 deletions.
diff --git a/src/main/java/com/actiontech/dble/server/NonBlockingSession.java b/src/main/java/com/actiontech/dble/server/NonBlockingSession.java
@@ -180,6 +180,13 @@ public void startProcess() {
         provider.startProcess(shardingService.getConnection().getId());
     }
 
+    public void endParseTCL() {
+        if (traceEnable || SlowQueryLog.getInstance().isEnableSlowLog()) {
+            traceResult.ready();
+            traceResult.setTCL();
+        }
+    }
+
     public void endParse() {
         sessionStage = SessionStage.Route_Calculation;
         if (traceEnable || SlowQueryLog.getInstance().isEnableSlowLog()) {

diff --git a/src/main/java/com/actiontech/dble/server/handler/BeginHandler.java b/src/main/java/com/actiontech/dble/server/handler/BeginHandler.java
@@ -14,13 +14,15 @@ private BeginHandler() {
     }
 
     public static void handle(String stmt, ShardingService service) {
+        service.getSession2().endParseTCL();
         if (service.isTxStart() || !service.isAutocommit()) {
             service.beginInTx(stmt);
         } else {
             service.setTxStart(true);
             StatisticListener.getInstance().record(service, r -> r.onTxStart(service));
             TxnLogHelper.putTxnLog(service, stmt);
             service.writeOkPacket();
+            service.getSession2().setResponseTime(true);
         }
     }
 }
diff --git a/src/main/java/com/actiontech/dble/server/handler/CommitHandler.java b/src/main/java/com/actiontech/dble/server/handler/CommitHandler.java
@@ -12,6 +12,7 @@ private CommitHandler() {
     }
 
     public static void handle(String stmt, ShardingService service) {
+        service.getSession2().endParseTCL();
         service.transactionsCount();
         service.commit(stmt);
     }

diff --git a/src/main/java/com/actiontech/dble/server/handler/RollBackHandler.java b/src/main/java/com/actiontech/dble/server/handler/RollBackHandler.java
@@ -14,6 +14,7 @@ private RollBackHandler() {
     }
 
     public static void handle(String stmt, ShardingService service) {
+        service.getSession2().endParseTCL();
         if (service.isTxStart() || !service.isAutocommit()) {
             StatisticListener.getInstance().record(service, r -> r.onTxEnd());
             TxnLogHelper.putTxnLog(service, stmt);

diff --git a/src/main/java/com/actiontech/dble/server/trace/TraceResult.java b/src/main/java/com/actiontech/dble/server/trace/TraceResult.java
@@ -24,7 +24,7 @@ public class TraceResult implements Cloneable {
 
 
     public enum SqlTraceType {
-        SINGLE_NODE_QUERY, MULTI_NODE_QUERY, MULTI_NODE_GROUP, COMPLEX_QUERY;
+        SINGLE_NODE_QUERY, MULTI_NODE_QUERY, MULTI_NODE_GROUP, COMPLEX_QUERY, SIMPLE_QUERY;
     }
 
     private static final Logger LOGGER = LoggerFactory.getLogger(TraceResult.class);
@@ -53,11 +53,17 @@ public enum SqlTraceType {
     private long veryEnd;
     private SqlTraceType type;
     private boolean subQuery = false;
+    private volatile boolean isTCL = false;
 
     public void setVeryStartPrepare(long veryStartPrepare) {
         prepareFinished = false;
         this.veryStartPrepare = veryStartPrepare;
         this.requestStartPrepare = new TraceRecord(veryStartPrepare);
+        this.isTCL = false;
+    }
+
+    public void setTCL() {
+        this.isTCL = true;
     }
 
     public void setRouteStart(TraceRecord routeStart) {
@@ -260,26 +266,31 @@ public List<String[]> genTraceResult() {
         if (LOGGER.isDebugEnabled()) {
             LOGGER.debug("start genTraceResult");
         }
+        List<String[]> lst = new ArrayList<>();
         if (!isCompleted()) {
             if (LOGGER.isDebugEnabled()) {
                 LOGGER.debug("collect info not in pairs,veryEnd:" + veryEnd + ",connFlagMap.size:" + connFlagMap.size() +
                         ",connReceivedMap.size:" + connReceivedMap.size() + ",connFinishedMap.size:" + connFinishedMap.size() +
                         ",recordStartMap.size:" + recordStartMap.size() + ",recordEndMap.size:" + recordEndMap.size());
             }
             return null;
-        }
-        List<String[]> lst = new ArrayList<>();
-        lst.add(genTraceRecord("Read_SQL", requestStart.getTimestamp(), parseStart.getTimestamp()));
-        lst.add(genTraceRecord("Parse_SQL", parseStart.getTimestamp(), routeStart.getTimestamp()));
-        if (simpleHandler != null) {
-            if (genSimpleResults(lst)) return null;
-        } else if (builder != null) {
-            if (genComplexQueryResults(lst)) return null;
+        } else if (isTCL) {
+            lst.add(genTraceRecord("Read_SQL", requestStart.getTimestamp(), parseStart.getTimestamp()));
+            lst.add(genTraceRecord("Parse_SQL", parseStart.getTimestamp(), routeStart.getTimestamp()));
+            lst.add(genTraceRecord("Write_to_Client", routeStart.getTimestamp(), veryEnd));
         } else {
-            if (LOGGER.isDebugEnabled()) {
-                LOGGER.debug("not support trace this query");
+            lst.add(genTraceRecord("Read_SQL", requestStart.getTimestamp(), parseStart.getTimestamp()));
+            lst.add(genTraceRecord("Parse_SQL", parseStart.getTimestamp(), routeStart.getTimestamp()));
+            if (simpleHandler != null) {
+                if (genSimpleResults(lst)) return null;
+            } else if (builder != null) {
+                if (genComplexQueryResults(lst)) return null;
+            } else {
+                if (LOGGER.isDebugEnabled()) {
+                    LOGGER.debug("not support trace this query");
+                }
+                return null;
             }
-            return null;
         }
         lst.add(genTraceRecord("Over_All", veryStart, veryEnd));
         if (LOGGER.isDebugEnabled()) {
@@ -572,10 +583,13 @@ private String nanoToMilliSecond(long nano) {
     }
 
     public boolean isCompleted() {
-        return veryStart != 0 && veryEnd != 0 && connFlagMap.size() != 0 && connReceivedMap.size() == connFinishedMap.size() && recordStartMap.size() == recordEndMap.size();
+        return veryStart != 0 && veryEnd != 0 && (isTCL) || (connFlagMap.size() != 0 && connReceivedMap.size() == connFinishedMap.size() && recordStartMap.size() == recordEndMap.size());
     }
 
     public SqlTraceType getType() {
+        if (this.type == null) {
+            return SqlTraceType.SIMPLE_QUERY;
+        }
         return this.type;
     }
 
@@ -590,6 +604,12 @@ public List<String[]> genLogResult() {
                         ",recordStartMap.size:" + connReceivedMap.size() + ",recordEndMap.size:" + connFinishedMap.size());
             }
             return null;
+        } else if (isTCL) {
+            List<String[]> lst = new ArrayList<>();
+            lst.add(genLogRecord("Read_SQL", requestStart.getTimestamp(), parseStart.getTimestamp()));
+            lst.add(genLogRecord("Inner_Execute", parseStart.getTimestamp(), veryEnd));
+            lst.add(genLogRecord("Write_Client", veryEnd, veryEnd));
+            return lst;
         }
         List<String[]> lst = new ArrayList<>();
         lst.add(genLogRecord("Read_SQL", requestStart.getTimestamp(), parseStart.getTimestamp()));