[td-225] add query cost statistics.

src/client/src/tscProfile.c

@@ -100,7 +100,7 @@ void tscSaveSlowQuery(SSqlObj *pSql) {
   
   char *sql = malloc(sqlSize);
   if (sql == NULL) {
-    tscError("%p failed to allocate memory to sent slow to dnode", pSql);
+    tscError("%p failed to allocate memory to sent slow query to dnode", pSql);
     return;
   }
   
@@ -112,8 +112,8 @@ void tscSaveSlowQuery(SSqlObj *pSql) {
   } else {
     sqlLen += len;
   }
+  
   strcpy(sql + sqlLen, "')");
-
   taosTmrStart(tscSaveSlowQueryFp, 200, sql, tscTmr);
 }
 

src/query/inc/qExecutor.h

@@ -116,11 +116,14 @@ typedef struct SQueryCostInfo {
   uint64_t loadDataInCacheSize;
   
   uint64_t loadDataTime;
-  uint64_t dataInRows;
-  uint64_t checkRows;
-  uint32_t dataBlocks;
+  uint64_t totalRows;
+  uint64_t totalCheckedRows;
+  uint32_t totalBlocks;
+  uint32_t loadBlocks;
   uint32_t loadBlockStatis;
   uint32_t discardBlocks;
+  uint64_t elapsedTime;
+  uint64_t computTime;
 } SQueryCostInfo;
 
 typedef struct SGroupItem {
@@ -168,7 +171,7 @@ typedef struct SQueryRuntimeEnv {
   SWindowResInfo       windowResInfo;
   STSBuf*              pTSBuf;
   STSCursor            cur;
-  SQueryCostInfo    summary;
+  SQueryCostInfo       summary;
   bool                 stableQuery;  // super table query or not
   void*                pQueryHandle;
   void*                pSecQueryHandle;  // another thread for
@@ -177,8 +180,6 @@ typedef struct SQueryRuntimeEnv {
 
 typedef struct SQInfo {
   void*   signature;
-  TSKEY   startTime;
-  TSKEY   elapsedTime;
   int32_t pointsInterpo;
   int32_t code;  // error code to returned to client
   sem_t   dataReady;

src/query/src/qExecutor.c

@@ -1183,6 +1183,7 @@ static int32_t tableApplyFunctionsOnBlock(SQueryRuntimeEnv *pRuntimeEnv, SDataBl
   
   STableQueryInfo* pTableQInfo = pQuery->current;
   SWindowResInfo*  pWindowResInfo = &pRuntimeEnv->windowResInfo;
+  pQuery->pos = QUERY_IS_ASC_QUERY(pQuery)? 0 : pDataBlockInfo->rows - 1;
   
   if (pQuery->numOfFilterCols > 0 || pRuntimeEnv->pTSBuf != NULL || isGroupbyNormalCol(pQuery->pGroupbyExpr)) {
     rowwiseApplyFunctions(pRuntimeEnv, pStatis, pDataBlockInfo, pWindowResInfo, pDataBlock);
@@ -1190,10 +1191,10 @@ static int32_t tableApplyFunctionsOnBlock(SQueryRuntimeEnv *pRuntimeEnv, SDataBl
     blockwiseApplyFunctions(pRuntimeEnv, pStatis, pDataBlockInfo, pWindowResInfo, searchFn, pDataBlock);
   }
 
+  // update the lastkey of current table
   TSKEY lastKey = QUERY_IS_ASC_QUERY(pQuery) ? pDataBlockInfo->window.ekey : pDataBlockInfo->window.skey;
   pTableQInfo->lastKey = lastKey + GET_FORWARD_DIRECTION_FACTOR(pQuery->order.order);
 
-
   // interval query with limit applied
   int32_t numOfRes = 0;
   
@@ -2013,7 +2014,7 @@ SArray *loadDataBlockOnDemand(SQueryRuntimeEnv *pRuntimeEnv, void* pQueryHandle,
   
     if (*pStatis == NULL) { // data block statistics does not exist, load data block
       pDataBlock = tsdbRetrieveDataBlock(pQueryHandle, NULL);
-      pRuntimeEnv->summary.checkRows += pBlockInfo->rows;
+      pRuntimeEnv->summary.totalCheckedRows += pBlockInfo->rows;
     }
   } else {
     assert(r == BLK_DATA_ALL_NEEDED);
@@ -2032,7 +2033,7 @@ SArray *loadDataBlockOnDemand(SQueryRuntimeEnv *pRuntimeEnv, void* pQueryHandle,
       //        return DISK_DATA_DISCARDED;
     }
   
-    pRuntimeEnv->summary.checkRows += pBlockInfo->rows;
+    pRuntimeEnv->summary.totalCheckedRows += pBlockInfo->rows;
     pDataBlock = tsdbRetrieveDataBlock(pQueryHandle, NULL);
   }
 
@@ -2149,7 +2150,7 @@ static int64_t doScanAllDataBlocks(SQueryRuntimeEnv *pRuntimeEnv) {
 
   TsdbQueryHandleT pQueryHandle = IS_MASTER_SCAN(pRuntimeEnv)? pRuntimeEnv->pQueryHandle : pRuntimeEnv->pSecQueryHandle;
   while (tsdbNextDataBlock(pQueryHandle)) {
-    pRuntimeEnv->summary.dataBlocks += 1;
+    pRuntimeEnv->summary.totalBlocks += 1;
     if (isQueryKilled(GET_QINFO_ADDR(pRuntimeEnv))) {
       return 0;
     }
@@ -2185,12 +2186,10 @@ static int64_t doScanAllDataBlocks(SQueryRuntimeEnv *pRuntimeEnv) {
     ensureOutputBuffer(pRuntimeEnv, &blockInfo);
 
     SDataStatis *pStatis = NULL;
-    pQuery->pos = QUERY_IS_ASC_QUERY(pQuery)? 0 : blockInfo.rows - 1;
-    
     SArray *pDataBlock = loadDataBlockOnDemand(pRuntimeEnv, pQueryHandle, &blockInfo, &pStatis);
     int32_t numOfRes = tableApplyFunctionsOnBlock(pRuntimeEnv, &blockInfo, pStatis, binarySearchForKey, pDataBlock);
 
-    pRuntimeEnv->summary.dataInRows += blockInfo.rows;
+    pRuntimeEnv->summary.totalRows += blockInfo.rows;
     qTrace("QInfo:%p check data block, brange:%" PRId64 "-%" PRId64 ", numOfRows:%d, numOfRes:%d, lastKey:%"PRId64, GET_QINFO_ADDR(pRuntimeEnv),
            blockInfo.window.skey, blockInfo.window.ekey, blockInfo.rows, numOfRes, pQuery->current->lastKey);
 
@@ -3247,7 +3246,7 @@ void destroyTableQueryInfo(STableQueryInfo *pTableQueryInfo, int32_t numOfCols)
   free(pTableQueryInfo);
 }
 
-void restoreIntervalQueryRange(SQueryRuntimeEnv *pRuntimeEnv, STableQueryInfo *pTableQueryInfo) {
+void setCurrentQueryTable(SQueryRuntimeEnv *pRuntimeEnv, STableQueryInfo *pTableQueryInfo) {
   SQuery *pQuery = pRuntimeEnv->pQuery;
   pQuery->current = pTableQueryInfo;
   
@@ -3316,7 +3315,7 @@ static void setWindowResOutputBuf(SQueryRuntimeEnv *pRuntimeEnv, SWindowResult *
 
 int32_t setAdditionalInfo(SQInfo *pQInfo, STableId* pTableId, STableQueryInfo *pTableQueryInfo) {
   SQueryRuntimeEnv *pRuntimeEnv = &pQInfo->runtimeEnv;
-  assert(pTableQueryInfo->lastKey >= 0);
+  assert(pTableQueryInfo->lastKey >= TSKEY_INITIAL_VAL);
 
   setTagVal(pRuntimeEnv, pTableId, pQInfo->tsdb);
 
@@ -3528,10 +3527,11 @@ static void updateWindowResNumOfRes(SQueryRuntimeEnv *pRuntimeEnv, STableQueryIn
   }
 }
 
-void stableApplyFunctionsOnBlock(SQueryRuntimeEnv *pRuntimeEnv, STableQueryInfo *pTableQueryInfo,
-                                 SDataBlockInfo *pDataBlockInfo, SDataStatis *pStatis, SArray *pDataBlock,
-                                 __block_search_fn_t searchFn) {
+void stableApplyFunctionsOnBlock(SQueryRuntimeEnv *pRuntimeEnv, SDataBlockInfo *pDataBlockInfo, SDataStatis *pStatis,
+    SArray *pDataBlock, __block_search_fn_t searchFn) {
   SQuery *         pQuery = pRuntimeEnv->pQuery;
+  STableQueryInfo* pTableQueryInfo = pQuery->current;
+  
   SWindowResInfo * pWindowResInfo = &pTableQueryInfo->windowResInfo;
   pQuery->pos = QUERY_IS_ASC_QUERY(pQuery)? 0 : pDataBlockInfo->rows - 1;
 
@@ -3685,8 +3685,9 @@ static void queryCostStatis(SQInfo *pQInfo) {
 //      pQInfo, pSummary->readDiskBlocks, pSummary->totalBlockSize, pSummary->loadBlocksUs / 1000.0,
 //      pSummary->skippedFileBlocks, pSummary->totalGenData);
   
-  qTrace("QInfo:%p cost: check blocks:%d, statis:%d, rows:%"PRId64", check rows:%"PRId64, pQInfo, pSummary->dataBlocks,
-         pSummary->loadBlockStatis, pSummary->dataInRows, pSummary->checkRows);
+  qTrace("QInfo:%p :cost summary: elpased time:%"PRId64" us, total blocks:%d, use block statis:%d, use block data:%d, "
+         "total rows:%"PRId64 ", check rows:%"PRId64, pQInfo, pSummary->elapsedTime, pSummary->totalBlocks,
+         pSummary->loadBlockStatis, pSummary->loadBlocks, pSummary->totalRows, pSummary->totalCheckedRows);
 
 //  qTrace("QInfo:%p cost: temp file:%d Bytes", pQInfo, pSummary->tmpBufferInDisk);
 //
@@ -4082,12 +4083,13 @@ static void enableExecutionForNextTable(SQueryRuntimeEnv *pRuntimeEnv) {
 static int64_t queryOnDataBlocks(SQInfo *pQInfo) {
   SQueryRuntimeEnv *pRuntimeEnv = &pQInfo->runtimeEnv;
   SQuery *          pQuery = pRuntimeEnv->pQuery;
-
+  SQueryCostInfo* summary  = &pRuntimeEnv->summary;
+  
   int64_t st = taosGetTimestampMs();
 
   TsdbQueryHandleT pQueryHandle = IS_MASTER_SCAN(pRuntimeEnv)? pRuntimeEnv->pQueryHandle : pRuntimeEnv->pSecQueryHandle;
-  
   while (tsdbNextDataBlock(pQueryHandle)) {
+    summary->totalBlocks += 1;
     if (isQueryKilled(pQInfo)) {
       break;
     }
@@ -4119,11 +4121,9 @@ static int64_t queryOnDataBlocks(SQInfo *pQInfo) {
     }
   
     assert(pTableQueryInfo != NULL);
-    restoreIntervalQueryRange(pRuntimeEnv, pTableQueryInfo);
-    printf("table:%d, groupIndex:%d, rows:%d\n", pTableQueryInfo->id.tid, pTableQueryInfo->groupIndex, blockInfo.tid);
+    setCurrentQueryTable(pRuntimeEnv, pTableQueryInfo);
 
     SDataStatis *pStatis = NULL;
-    
     SArray *pDataBlock = loadDataBlockOnDemand(pRuntimeEnv, pQueryHandle, &blockInfo, &pStatis);
 
     if (!isIntervalQuery(pQuery)) {
@@ -4132,15 +4132,14 @@ static int64_t queryOnDataBlocks(SQInfo *pQInfo) {
     } else {  // interval query
       TSKEY nextKey = blockInfo.window.skey;
       setIntervalQueryRange(pQInfo, nextKey);
-      int32_t ret = setAdditionalInfo(pQInfo, &pTableQueryInfo->id, pTableQueryInfo);
-
-      if (ret != TSDB_CODE_SUCCESS) {
-        pQInfo->code = ret;
-        return taosGetTimestampMs() - st;
-      }
+      /*int32_t ret = */setAdditionalInfo(pQInfo, &pTableQueryInfo->id, pTableQueryInfo);
     }
 
-    stableApplyFunctionsOnBlock(pRuntimeEnv, pTableQueryInfo, &blockInfo, pStatis, pDataBlock, binarySearchForKey);
+    summary->totalRows += blockInfo.rows;
+    stableApplyFunctionsOnBlock(pRuntimeEnv, &blockInfo, pStatis, pDataBlock, binarySearchForKey);
+  
+    qTrace("QInfo:%p check data block, brange:%" PRId64 "-%" PRId64 ", numOfRows:%d, lastKey:%"PRId64, GET_QINFO_ADDR(pRuntimeEnv),
+           blockInfo.window.skey, blockInfo.window.ekey, blockInfo.rows, pQuery->current->lastKey);
   }
 
   int64_t et = taosGetTimestampMs();
@@ -4502,10 +4501,6 @@ static void multiTableQueryProcess(SQInfo *pQInfo) {
       copyFromWindowResToSData(pQInfo, pRuntimeEnv->windowResInfo.pResult);
     }
 
-    if (pQuery->rec.rows == 0) {
-      //      queryCostStatis(pSupporter);
-    }
-
     qTrace("QInfo:%p current:%lld, total:%lld", pQInfo, pQuery->rec.rows, pQuery->rec.total);
     return;
   }
@@ -4810,7 +4805,7 @@ static void tableQueryImpl(SQInfo *pQInfo) {
   }
 
   // record the total elapsed time
-  pQInfo->elapsedTime += (taosGetTimestampUs() - st);
+  pRuntimeEnv->summary.elapsedTime += (taosGetTimestampUs() - st);
   assert(pQInfo->groupInfo.numOfTables == 1);
 
   /* check if query is killed or not */
@@ -4840,13 +4835,10 @@ static void stableQueryImpl(SQInfo *pQInfo) {
   }
 
   // record the total elapsed time
-  pQInfo->elapsedTime += (taosGetTimestampUs() - st);
-  //  taosFillSetStartInfo(&pQInfo->runtimeEnv.pFillInfo, pQuery->size, pQInfo->query.fillType);
-
+  pQInfo->runtimeEnv.summary.elapsedTime += (taosGetTimestampUs() - st);
+  
   if (pQuery->rec.rows == 0) {
-    qTrace("QInfo:%p over, %d tables queried, %d points are returned", pQInfo, pQInfo->groupInfo.numOfTables,
-           pQuery->rec.total);
-    //    queryCostStatis(pSupporter);
+    qTrace("QInfo:%p over, %d tables queried, %d rows are returned", pQInfo, pQInfo->groupInfo.numOfTables, pQuery->rec.total);
   }
 }
 
@@ -5949,6 +5941,7 @@ int32_t qDumpRetrieveResult(qinfo_t qinfo, SRetrieveTableRsp **pRsp, int32_t *co
     return TSDB_CODE_INVALID_QHANDLE;
   }
 
+  SQueryRuntimeEnv* pRuntimeEnv = &pQInfo->runtimeEnv;
   SQuery *pQuery = pQInfo->runtimeEnv.pQuery;
   size_t  size = getResultSize(pQInfo, &pQuery->rec.rows);
   size += sizeof(int32_t);
@@ -5962,7 +5955,7 @@ int32_t qDumpRetrieveResult(qinfo_t qinfo, SRetrieveTableRsp **pRsp, int32_t *co
   int32_t code = pQInfo->code;
   if (code == TSDB_CODE_SUCCESS) {
     (*pRsp)->offset = htobe64(pQuery->limit.offset);
-    (*pRsp)->useconds = htobe64(pQInfo->elapsedTime);
+    (*pRsp)->useconds = htobe64(pRuntimeEnv->summary.elapsedTime);
   } else {
     (*pRsp)->offset = 0;
     (*pRsp)->useconds = 0;