Merge pull request #20033 from taosdata/fix/TD-22556

fix: refact client statistics collection

source/client/inc/clientInt.h

@@ -97,16 +97,14 @@ typedef struct {
 
 typedef struct SQueryExecMetric {
   int64_t start;        // start timestamp, us
-  int64_t syntaxStart;  // start to parse, us
-  int64_t syntaxEnd;    // end to parse, us
   int64_t ctgStart;     // start to parse, us
-  int64_t ctgEnd;       // end to parse, us
-  int64_t semanticEnd;
-  int64_t planEnd;
-  int64_t resultReady;
-  int64_t execEnd;
-  int64_t send;  // start to send to server, us
-  int64_t rsp;   // receive response from server, us
+  int64_t execStart;     // start to parse, us
+
+  int64_t parseCostUs;   
+  int64_t ctgCostUs;
+  int64_t analyseCostUs;
+  int64_t planCostUs;
+  int64_t execCostUs;
 } SQueryExecMetric;
 
 struct SAppInstInfo {

source/client/src/clientEnv.c

@@ -79,22 +79,21 @@ static void deregisterRequest(SRequestObj *pRequest) {
            "current:%d, app current:%d",
            pRequest->self, pTscObj->id, pRequest->requestId, duration / 1000.0, num, currentInst);
 
-  if (QUERY_NODE_VNODE_MODIF_STMT == pRequest->stmtType) {
-    //    tscPerf("insert duration %" PRId64 "us: syntax:%" PRId64 "us, ctg:%" PRId64 "us, semantic:%" PRId64
-    //            "us, exec:%" PRId64 "us",
-    //            duration, pRequest->metric.syntaxEnd - pRequest->metric.syntaxStart,
-    //            pRequest->metric.ctgEnd - pRequest->metric.ctgStart, pRequest->metric.semanticEnd -
-    //            pRequest->metric.ctgEnd, pRequest->metric.execEnd - pRequest->metric.semanticEnd);
-    atomic_add_fetch_64((int64_t *)&pActivity->insertElapsedTime, duration);
-  } else if (QUERY_NODE_SELECT_STMT == pRequest->stmtType) {
-    //    tscPerf("select duration %" PRId64 "us: syntax:%" PRId64 "us, ctg:%" PRId64 "us, semantic:%" PRId64
-    //            "us, planner:%" PRId64 "us, exec:%" PRId64 "us, reqId:0x%" PRIx64,
-    //            duration, pRequest->metric.syntaxEnd - pRequest->metric.syntaxStart,
-    //            pRequest->metric.ctgEnd - pRequest->metric.ctgStart, pRequest->metric.semanticEnd -
-    //            pRequest->metric.ctgEnd, pRequest->metric.planEnd - pRequest->metric.semanticEnd,
-    //            pRequest->metric.resultReady - pRequest->metric.planEnd, pRequest->requestId);
-
-    atomic_add_fetch_64((int64_t *)&pActivity->queryElapsedTime, duration);
+  if (pRequest->pQuery && pRequest->pQuery->pRoot) {
+    if (QUERY_NODE_VNODE_MODIF_STMT == pRequest->pQuery->pRoot->type && (0 == ((SVnodeModifOpStmt*)pRequest->pQuery->pRoot)->sqlNodeType)) {
+      tscDebug("insert duration %" PRId64 "us: parseCost:%" PRId64 "us, ctgCost:%" PRId64 "us, analyseCost:%" PRId64
+              "us, planCost:%" PRId64 "us, exec:%" PRId64 "us",
+              duration, pRequest->metric.parseCostUs, pRequest->metric.ctgCostUs, pRequest->metric.analyseCostUs, 
+              pRequest->metric.planCostUs, pRequest->metric.execCostUs);
+      atomic_add_fetch_64((int64_t *)&pActivity->insertElapsedTime, duration);
+    } else if (QUERY_NODE_SELECT_STMT == pRequest->stmtType) {
+      tscDebug("query duration %" PRId64 "us: parseCost:%" PRId64 "us, ctgCost:%" PRId64 "us, analyseCost:%" PRId64
+              "us, planCost:%" PRId64 "us, exec:%" PRId64 "us",
+              duration, pRequest->metric.parseCostUs, pRequest->metric.ctgCostUs, pRequest->metric.analyseCostUs, 
+              pRequest->metric.planCostUs, pRequest->metric.execCostUs);
+
+      atomic_add_fetch_64((int64_t *)&pActivity->queryElapsedTime, duration);
+    }
   }
 
   if (duration >= SLOW_QUERY_INTERVAL) {
@@ -362,8 +361,6 @@ void doDestroyRequest(void *p) {
   taosArrayDestroy(pRequest->tableList);
   taosArrayDestroy(pRequest->dbList);
   taosArrayDestroy(pRequest->targetTableList);
-  qDestroyQuery(pRequest->pQuery);
-  nodesDestroyAllocator(pRequest->allocatorRefId);
 
   destroyQueryExecRes(&pRequest->body.resInfo.execRes);
 
@@ -378,6 +375,9 @@ void doDestroyRequest(void *p) {
     taosMemoryFree(pRequest->body.param);
   }
 
+  qDestroyQuery(pRequest->pQuery);
+  nodesDestroyAllocator(pRequest->allocatorRefId);
+
   taosMemoryFreeClear(pRequest->sqlstr);
   taosMemoryFree(pRequest);
   tscTrace("end to destroy request %" PRIx64 " p:%p", reqId, pRequest);

source/client/src/clientImpl.c

@@ -946,7 +946,7 @@ void schedulerExecCb(SExecResult* pResult, void* param, int32_t code) {
     removeMeta(pTscObj, pRequest->targetTableList);
   }
 
-  pRequest->metric.execEnd = taosGetTimestampUs();
+  pRequest->metric.execCostUs = taosGetTimestampUs() - pRequest->metric.execStart;
   int32_t code1 = handleQueryExecRsp(pRequest);
   if (pRequest->code == TSDB_CODE_SUCCESS && pRequest->code != code1) {
     pRequest->code = code1;
@@ -1072,11 +1072,10 @@ static int32_t asyncExecSchQuery(SRequestObj* pRequest, SQuery* pQuery, SMetaDat
     pRequest->body.subplanNum = pDag->numOfSubplans;
   }
 
-  pRequest->metric.planEnd = taosGetTimestampUs();
-  if (code == TSDB_CODE_SUCCESS) {
-    tscDebug("0x%" PRIx64 " create query plan success, elapsed time:%.2f ms, 0x%" PRIx64, pRequest->self,
-             (pRequest->metric.planEnd - st) / 1000.0, pRequest->requestId);
-  }
+  pRequest->metric.execStart = taosGetTimestampUs();
+
+  pRequest->metric.planCostUs = pRequest->metric.execStart - st;
+
   if (TSDB_CODE_SUCCESS == code && !pRequest->validateOnly) {
     SArray* pNodeList = NULL;
     if (QUERY_NODE_VNODE_MODIF_STMT != nodeType(pQuery->pRoot)) {
@@ -1124,6 +1123,16 @@ void launchAsyncQuery(SRequestObj* pRequest, SQuery* pQuery, SMetaData* pResultM
     destorySqlCallbackWrapper(pWrapper);
   }
 
+  if (pQuery->pRoot && !pRequest->inRetry) {
+    STscObj*            pTscObj = pRequest->pTscObj;
+    SAppClusterSummary* pActivity = &pTscObj->pAppInfo->summary;
+    if (QUERY_NODE_VNODE_MODIF_STMT == pQuery->pRoot->type && (0 == ((SVnodeModifOpStmt*)pQuery->pRoot)->sqlNodeType)) {
+      atomic_add_fetch_64((int64_t*)&pActivity->numOfInsertsReq, 1);
+    } else if (QUERY_NODE_SELECT_STMT == pQuery->pRoot->type) {
+      atomic_add_fetch_64((int64_t*)&pActivity->numOfQueryReq, 1);
+    }
+  }
+
   switch (pQuery->execMode) {
     case QUERY_EXEC_MODE_LOCAL:
       asyncExecLocalCmd(pRequest, pQuery);
@@ -1393,21 +1402,7 @@ int32_t doProcessMsgFromServer(void* param) {
     SRequestObj* pRequest = (SRequestObj*)taosAcquireRef(clientReqRefPool, pSendInfo->requestObjRefId);
     if (pRequest) {
       assert(pRequest->self == pSendInfo->requestObjRefId);
-
-      pRequest->metric.rsp = taosGetTimestampUs();
       pTscObj = pRequest->pTscObj;
-      /*
-       * There is not response callback function for submit response.
-       * The actual inserted number of points is the first number.
-       */
-      int32_t elapsed = pRequest->metric.rsp - pRequest->metric.start;
-      if (pMsg->code == TSDB_CODE_SUCCESS) {
-        tscDebug("0x%" PRIx64 " rsp msg:%s, code:%s rspLen:%d, elapsed:%d ms, reqId:0x%" PRIx64, pRequest->self,
-                 TMSG_INFO(pMsg->msgType), tstrerror(pMsg->code), pMsg->contLen, elapsed / 1000, pRequest->requestId);
-      } else {
-        tscError("0x%" PRIx64 " rsp msg:%s, code:%s rspLen:%d, elapsed time:%d ms, reqId:0x%" PRIx64, pRequest->self,
-                 TMSG_INFO(pMsg->msgType), tstrerror(pMsg->code), pMsg->contLen, elapsed / 1000, pRequest->requestId);
-      }
     }
   }
 

source/client/src/clientMain.c

@@ -707,7 +707,8 @@ static void doAsyncQueryFromAnalyse(SMetaData *pResultMeta, void *param, int32_t
   SRequestObj         *pRequest = pWrapper->pRequest;
   SQuery              *pQuery = pRequest->pQuery;
 
-  pRequest->metric.ctgEnd = taosGetTimestampUs();
+  int64_t analyseStart = taosGetTimestampUs();
+  pRequest->metric.ctgCostUs = analyseStart - pRequest->metric.ctgStart;
   qDebug("0x%" PRIx64 " start to semantic analysis, reqId:0x%" PRIx64, pRequest->self, pRequest->requestId);
 
   if (code == TSDB_CODE_SUCCESS) {
@@ -718,7 +719,7 @@ static void doAsyncQueryFromAnalyse(SMetaData *pResultMeta, void *param, int32_t
     }
   }
 
-  pRequest->metric.semanticEnd = taosGetTimestampUs();
+  pRequest->metric.analyseCostUs = taosGetTimestampUs() - analyseStart;
 
   if (code == TSDB_CODE_SUCCESS) {
     if (pQuery->haveResultSet) {
@@ -730,10 +731,6 @@ static void doAsyncQueryFromAnalyse(SMetaData *pResultMeta, void *param, int32_t
     TSWAP(pRequest->tableList, (pQuery)->pTableList);
     TSWAP(pRequest->targetTableList, (pQuery)->pTargetTableList);
 
-    double el = (pRequest->metric.semanticEnd - pRequest->metric.ctgEnd) / 1000.0;
-    tscDebug("0x%" PRIx64 " analysis semantics completed, start async query, elapsed time:%.2f ms, reqId:0x%" PRIx64,
-             pRequest->self, el, pRequest->requestId);
-
     launchAsyncQuery(pRequest, pQuery, pResultMeta, pWrapper);
   } else {
     destorySqlCallbackWrapper(pWrapper);
@@ -798,7 +795,7 @@ static void doAsyncQueryFromParse(SMetaData *pResultMeta, void *param, int32_t c
   SRequestObj         *pRequest = pWrapper->pRequest;
   SQuery              *pQuery = pRequest->pQuery;
 
-  pRequest->metric.ctgEnd = taosGetTimestampUs();
+  pRequest->metric.ctgCostUs += taosGetTimestampUs() - pRequest->metric.ctgStart;
   qDebug("0x%" PRIx64 " start to continue parse, reqId:0x%" PRIx64 ", code:%s", pRequest->self, pRequest->requestId,
          tstrerror(code));
 
@@ -910,7 +907,7 @@ void doAsyncQuery(SRequestObj *pRequest, bool updateMetaForce) {
   }
 
   if (TSDB_CODE_SUCCESS == code) {
-    pRequest->metric.syntaxStart = taosGetTimestampUs();
+    int64_t syntaxStart = taosGetTimestampUs();
 
     pWrapper->pCatalogReq = taosMemoryCalloc(1, sizeof(SCatalogReq));
     if (pWrapper->pCatalogReq == NULL) {
@@ -921,16 +918,7 @@ void doAsyncQuery(SRequestObj *pRequest, bool updateMetaForce) {
       code = qParseSqlSyntax(pWrapper->pParseCtx, &pRequest->pQuery, pWrapper->pCatalogReq);
     }
 
-    pRequest->metric.syntaxEnd = taosGetTimestampUs();
-  }
-
-  if (TSDB_CODE_SUCCESS == code && !updateMetaForce) {
-    SAppClusterSummary *pActivity = &pTscObj->pAppInfo->summary;
-    if (QUERY_NODE_INSERT_STMT == nodeType(pRequest->pQuery->pRoot)) {
-      atomic_add_fetch_64((int64_t *)&pActivity->numOfInsertsReq, 1);
-    } else if (QUERY_NODE_SELECT_STMT == nodeType(pRequest->pQuery->pRoot)) {
-      atomic_add_fetch_64((int64_t *)&pActivity->numOfQueryReq, 1);
-    }
+    pRequest->metric.parseCostUs += taosGetTimestampUs() - syntaxStart;
   }
 
   if (TSDB_CODE_SUCCESS == code) {
@@ -961,7 +949,6 @@ static void fetchCallback(void *pResult, void *param, int32_t code) {
   SRequestObj *pRequest = (SRequestObj *)param;
 
   SReqResultInfo *pResultInfo = &pRequest->body.resInfo;
-  pRequest->metric.resultReady = taosGetTimestampUs();
 
   tscDebug("0x%" PRIx64 " enter scheduler fetch cb, code:%d - %s, reqId:0x%" PRIx64, pRequest->self, code,
            tstrerror(code), pRequest->requestId);