From e2bc0383f2b011fcb81ce97229ffa3f2757b1ae6 Mon Sep 17 00:00:00 2001 From: dapan1121 Date: Fri, 17 Feb 2023 16:30:14 +0800 Subject: [PATCH] fix: refact client statistics collection --- source/client/inc/clientInt.h | 16 +++++++-------- source/client/src/clientEnv.c | 36 +++++++++++++++++----------------- source/client/src/clientImpl.c | 35 ++++++++++++++------------------- source/client/src/clientMain.c | 25 ++++++----------------- 4 files changed, 46 insertions(+), 66 deletions(-) diff --git a/source/client/inc/clientInt.h b/source/client/inc/clientInt.h index 903a6a22ca..fb011ce3e4 100644 --- a/source/client/inc/clientInt.h +++ b/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 { diff --git a/source/client/src/clientEnv.c b/source/client/src/clientEnv.c index 593a8fd20a..06ef7b7c9c 100644 --- a/source/client/src/clientEnv.c +++ b/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); diff --git a/source/client/src/clientImpl.c b/source/client/src/clientImpl.c index 67fa1e7781..079edcd667 100644 --- a/source/client/src/clientImpl.c +++ b/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); - } } } diff --git a/source/client/src/clientMain.c b/source/client/src/clientMain.c index 2042ff141c..53efff023d 100644 --- a/source/client/src/clientMain.c +++ b/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); -- GitLab