Merge pull request #16362 from taosdata/enh/insertPerf

enh: add client performance trace

source/client/inc/clientInt.h

@@ -96,7 +96,12 @@ typedef struct {
 
 typedef struct SQueryExecMetric {
   int64_t start;   // start timestamp, us
-  int64_t parsed;  // start to parse, 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 execEnd;
   int64_t send;    // start to send to server, us
   int64_t rsp;     // receive response from server, us
 } SQueryExecMetric;

source/client/inc/clientLog.h

@@ -29,6 +29,7 @@ extern "C" {
 #define tscDebug(...)  do { if (cDebugFlag & DEBUG_DEBUG) { taosPrintLog("TSC ", DEBUG_DEBUG, cDebugFlag, __VA_ARGS__); }} while(0)
 #define tscTrace(...)  do { if (cDebugFlag & DEBUG_TRACE) { taosPrintLog("TSC ", DEBUG_TRACE, cDebugFlag, __VA_ARGS__); }} while(0)
 #define tscDebugL(...) do { if (cDebugFlag & DEBUG_DEBUG) { taosPrintLongString("TSC ", DEBUG_DEBUG, cDebugFlag, __VA_ARGS__); }} while(0)
+#define tscPerf(...)   do { taosPrintLog("TSC ", 0, cDebugFlag, __VA_ARGS__); } while(0)
 
 #ifdef __cplusplus
 }

source/client/src/clientEnv.c

@@ -69,14 +69,25 @@ static void deregisterRequest(SRequestObj *pRequest) {
   int32_t currentInst = atomic_sub_fetch_64((int64_t *)&pActivity->currentRequests, 1);
   int32_t num = atomic_sub_fetch_32(&pTscObj->numOfReqs, 1);
 
-  int64_t duration = taosGetTimestampUs() - pRequest->metric.start;
+  int64_t nowUs = taosGetTimestampUs();
+  int64_t duration = nowUs - pRequest->metric.start;
   tscDebug("0x%" PRIx64 " free Request from connObj: 0x%" PRIx64 ", reqId:0x%" PRIx64 " elapsed:%" PRIu64
            " ms, current:%d, app current:%d",
            pRequest->self, pTscObj->id, pRequest->requestId, duration / 1000, 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, 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->queryElapsedTime, duration);
   }
 
@@ -330,7 +341,6 @@ void doDestroyRequest(void *p) {
   schedulerFreeJob(&pRequest->body.queryJob, 0);
 
   taosMemoryFreeClear(pRequest->msgBuf);
-  taosMemoryFreeClear(pRequest->sqlstr);
   taosMemoryFreeClear(pRequest->pDb);
 
   doFreeReqResultInfo(&pRequest->body.resInfo);
@@ -349,6 +359,7 @@ void doDestroyRequest(void *p) {
     taosMemoryFree(pRequest->body.param);
   }
 
+  taosMemoryFreeClear(pRequest->sqlstr);
   taosMemoryFree(pRequest);
   tscTrace("end to destroy request %" PRIx64 " p:%p", reqId, pRequest);
 }

source/client/src/clientImpl.c

@@ -842,6 +842,8 @@ void schedulerExecCb(SExecResult* pResult, void* param, int32_t code) {
     }
 
     schedulerFreeJob(&pRequest->body.queryJob, 0);
+
+    pRequest->metric.execEnd = taosGetTimestampUs();
   }
 
   taosMemoryFree(pResult);

source/client/src/clientMain.c

@@ -685,6 +685,8 @@ void retrieveMetaCallback(SMetaData *pResultMeta, void *param, int32_t code) {
   SQuery          *pQuery = pWrapper->pQuery;
   SRequestObj     *pRequest = pWrapper->pRequest;
 
+  pRequest->metric.ctgEnd = taosGetTimestampUs();
+
   if (code == TSDB_CODE_SUCCESS) {
     code = qAnalyseSqlSemantic(pWrapper->pCtx, &pWrapper->catalogReq, pResultMeta, pQuery);
     pRequest->stableQuery = pQuery->stableQuery;
@@ -693,6 +695,8 @@ void retrieveMetaCallback(SMetaData *pResultMeta, void *param, int32_t code) {
     }
   }
 
+  pRequest->metric.semanticEnd = taosGetTimestampUs();
+
   if (code == TSDB_CODE_SUCCESS) {
     if (pQuery->haveResultSet) {
       setResSchemaInfo(&pRequest->body.resInfo, pQuery->pResSchema, pQuery->numOfResCols);
@@ -784,12 +788,16 @@ void doAsyncQuery(SRequestObj *pRequest, bool updateMetaForce) {
 
   SQuery *pQuery = NULL;
 
+  pRequest->metric.syntaxStart = taosGetTimestampUs();
+
   SCatalogReq catalogReq = {.forceUpdate = updateMetaForce, .qNodeRequired = qnodeRequired(pRequest)};
   code = qParseSqlSyntax(pCxt, &pQuery, &catalogReq);
   if (code != TSDB_CODE_SUCCESS) {
     goto _error;
   }
 
+  pRequest->metric.syntaxEnd = taosGetTimestampUs();
+
   if (!updateMetaForce) {
     STscObj            *pTscObj = pRequest->pTscObj;
     SAppClusterSummary *pActivity = &pTscObj->pAppInfo->summary;
@@ -816,6 +824,8 @@ void doAsyncQuery(SRequestObj *pRequest, bool updateMetaForce) {
                            .requestObjRefId = pCxt->requestRid,
                            .mgmtEps = pCxt->mgmtEpSet};
 
+  pRequest->metric.ctgStart = taosGetTimestampUs();
+
   code = catalogAsyncGetAllMeta(pCxt->pCatalog, &conn, &catalogReq, retrieveMetaCallback, pWrapper,
                                 &pRequest->body.queryJob);
   pCxt = NULL;