enh: add perf debug info
This commit is contained in:
parent
cd22be63a4
commit
7c7c452bbc
|
@ -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;
|
||||
|
|
|
@ -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
|
||||
}
|
||||
|
|
|
@ -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);
|
||||
}
|
||||
|
||||
|
|
|
@ -839,6 +839,8 @@ void schedulerExecCb(SExecResult* pResult, void* param, int32_t code) {
|
|||
}
|
||||
|
||||
schedulerFreeJob(&pRequest->body.queryJob, 0);
|
||||
|
||||
pRequest->metric.execEnd = taosGetTimestampUs();
|
||||
}
|
||||
|
||||
taosMemoryFree(pResult);
|
||||
|
|
|
@ -683,6 +683,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;
|
||||
|
@ -691,6 +693,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);
|
||||
|
@ -782,12 +786,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;
|
||||
|
@ -814,6 +822,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;
|
||||
|
|
Loading…
Reference in New Issue