Merge pull request #16737 from taosdata/feature/3_liaohj

refactor(query): add some logs.

source/dnode/vnode/src/inc/tsdb.h

@@ -648,6 +648,8 @@ typedef struct SSttBlockLoadInfo {
     SArray    *aSttBlk;
     int32_t    blockIndex[2];  // to denote the loaded block in the corresponding position.
     int32_t    currentLoadBlockIndex;
+    int32_t    loadBlocks;
+    double     elapsedTime;
 } SSttBlockLoadInfo;
 
 typedef struct SMergeTree {
@@ -657,10 +659,11 @@ typedef struct SMergeTree {
   SLDataIter *pIter;
   bool        destroyLoadInfo;
   SSttBlockLoadInfo* pLoadInfo;
+  const char *idStr;
 } SMergeTree;
 
 int32_t tMergeTreeOpen(SMergeTree *pMTree, int8_t backward, SDataFReader *pFReader, uint64_t suid, uint64_t uid,
-                       STimeWindow *pTimeWindow, SVersionRange *pVerRange, void* pLoadInfo);
+                       STimeWindow *pTimeWindow, SVersionRange *pVerRange, void* pLoadInfo, const char* idStr);
 void    tMergeTreeAddIter(SMergeTree *pMTree, SLDataIter *pIter);
 bool    tMergeTreeNext(SMergeTree *pMTree);
 TSDBROW tMergeTreeGetRow(SMergeTree *pMTree);
@@ -668,6 +671,7 @@ void    tMergeTreeClose(SMergeTree *pMTree);
 
 SSttBlockLoadInfo* tCreateLastBlockLoadInfo();
 void  resetLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo);
+void  getLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo, int64_t* blocks, double* el);
 void* destroyLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo);
 
 // ========== inline functions ==========

source/dnode/vnode/src/tsdb/tsdbCache.c

@@ -457,7 +457,7 @@ static int32_t getNextRowFromFSLast(void *iter, TSDBROW **ppRow) {
 
       tMergeTreeOpen(&state->mergeTree, 1, state->pDataFReader, state->suid, state->uid,
                      &(STimeWindow){.skey = TSKEY_MIN, .ekey = TSKEY_MAX},
-                     &(SVersionRange){.minVer = 0, .maxVer = UINT64_MAX}, NULL);
+                     &(SVersionRange){.minVer = 0, .maxVer = UINT64_MAX}, NULL, NULL);
       bool hasVal = tMergeTreeNext(&state->mergeTree);
       if (!hasVal) {
         state->state = SFSLASTNEXTROW_FILESET;

source/dnode/vnode/src/tsdb/tsdbMergeTree.c

@@ -67,6 +67,16 @@ void resetLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo) {
     pLoadInfo[i].blockIndex[1] = -1;
 
     taosArrayClear(pLoadInfo[i].aSttBlk);
+
+    pLoadInfo[i].elapsedTime = 0;
+    pLoadInfo[i].loadBlocks = 0;
+  }
+}
+
+void getLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo, int64_t* blocks, double* el) {
+  for(int32_t i = 0; i < TSDB_DEFAULT_STT_FILE; ++i) {
+    *el += pLoadInfo[i].elapsedTime;
+    *blocks += pLoadInfo[i].loadBlocks;
   }
 }
 
@@ -86,7 +96,7 @@ void* destroyLastBlockLoadInfo(SSttBlockLoadInfo* pLoadInfo) {
   return NULL;
 }
 
-static SBlockData* loadBlockIfMissing(SLDataIter *pIter) {
+static SBlockData* loadLastBlock(SLDataIter *pIter, const char* idStr) {
   int32_t code = 0;
 
   SSttBlockLoadInfo* pInfo = pIter->pBlockLoadInfo;
@@ -100,8 +110,13 @@ static SBlockData* loadBlockIfMissing(SLDataIter *pIter) {
 
   pInfo->currentLoadBlockIndex ^= 1;
   if (pIter->pSttBlk != NULL) {  // current block not loaded yet
+    int64_t st = taosGetTimestampUs();
     code = tsdbReadSttBlock(pIter->pReader, pIter->iStt, pIter->pSttBlk, &pInfo->blockData[pInfo->currentLoadBlockIndex]);
-    tsdbDebug("read last block, index:%d, last file index:%d", pIter->iSttBlk, pIter->iStt);
+    double el = (taosGetTimestampUs() - st)/ 1000.0;
+    pInfo->elapsedTime += el;
+    pInfo->loadBlocks += 1;
+
+    tsdbDebug("read last block, index:%d, last file index:%d, elapsed time:%.2f ms, %s", pIter->iSttBlk, pIter->iStt, el, idStr);
     if (code != TSDB_CODE_SUCCESS) {
       goto _exit;
     }
@@ -245,9 +260,8 @@ int32_t tLDataIterOpen(struct SLDataIter **pIter, SDataFReader *pReader, int32_t
   size_t size = taosArrayGetSize(pBlockLoadInfo->aSttBlk);
 
   // find the start block
-  int32_t index = binarySearchForStartBlock(pBlockLoadInfo->aSttBlk->pData, size, uid, backward);
-  (*pIter)->iSttBlk = index;
-  if (index != -1) {
+  (*pIter)->iSttBlk = binarySearchForStartBlock(pBlockLoadInfo->aSttBlk->pData, size, uid, backward);
+  if ((*pIter)->iSttBlk != -1) {
     (*pIter)->pSttBlk = taosArrayGet(pBlockLoadInfo->aSttBlk, (*pIter)->iSttBlk);
     (*pIter)->iRow = ((*pIter)->backward) ? (*pIter)->pSttBlk->nRow : -1;
   }
@@ -265,7 +279,7 @@ void tLDataIterNextBlock(SLDataIter *pIter) {
   pIter->iSttBlk += step;
 
   int32_t index = -1;
-  size_t  size = pIter->pBlockLoadInfo->aSttBlk->size;//taosArrayGetSize(pIter->pBlockLoadInfo->aSttBlk);
+  size_t  size = pIter->pBlockLoadInfo->aSttBlk->size;
   for (int32_t i = pIter->iSttBlk; i < size && i >= 0; i += step) {
     SSttBlk *p = taosArrayGet(pIter->pBlockLoadInfo->aSttBlk, i);
     if ((!pIter->backward) && p->minUid > pIter->uid) {
@@ -310,13 +324,13 @@ void tLDataIterNextBlock(SLDataIter *pIter) {
   }
 }
 
-static void findNextValidRow(SLDataIter *pIter) {
+static void findNextValidRow(SLDataIter *pIter, const char* idStr) {
   int32_t step = pIter->backward ? -1 : 1;
 
   bool        hasVal = false;
   int32_t     i = pIter->iRow;
 
-  SBlockData *pBlockData = loadBlockIfMissing(pIter);
+  SBlockData *pBlockData = loadLastBlock(pIter, idStr);
 
   // mostly we only need to find the start position for a given table
   if ((((i == 0) && (!pIter->backward)) || (i == pBlockData->nRow - 1 && pIter->backward)) && pBlockData->aUid != NULL) {
@@ -376,7 +390,7 @@ static void findNextValidRow(SLDataIter *pIter) {
   pIter->iRow = (hasVal) ? i : -1;
 }
 
-bool tLDataIterNextRow(SLDataIter *pIter) {
+bool tLDataIterNextRow(SLDataIter *pIter, const char* idStr) {
   int32_t code = 0;
   int32_t step = pIter->backward ? -1 : 1;
 
@@ -386,11 +400,11 @@ bool tLDataIterNextRow(SLDataIter *pIter) {
   }
 
   int32_t iBlockL = pIter->iSttBlk;
-  SBlockData *pBlockData = loadBlockIfMissing(pIter);
+  SBlockData *pBlockData = loadLastBlock(pIter, idStr);
   pIter->iRow += step;
 
   while (1) {
-    findNextValidRow(pIter);
+    findNextValidRow(pIter, idStr);
 
     if (pIter->iRow >= pBlockData->nRow || pIter->iRow < 0) {
       tLDataIterNextBlock(pIter);
@@ -402,7 +416,7 @@ bool tLDataIterNextRow(SLDataIter *pIter) {
     }
 
     if (iBlockL != pIter->iSttBlk) {
-      pBlockData = loadBlockIfMissing(pIter);
+      pBlockData = loadLastBlock(pIter, idStr);
       pIter->iRow += step;
     }
   }
@@ -445,7 +459,7 @@ static FORCE_INLINE int32_t tLDataIterCmprFn(const void *p1, const void *p2) {
 }
 
 int32_t tMergeTreeOpen(SMergeTree *pMTree, int8_t backward, SDataFReader *pFReader, uint64_t suid, uint64_t uid,
-                       STimeWindow *pTimeWindow, SVersionRange *pVerRange, void* pBlockLoadInfo) {
+                       STimeWindow *pTimeWindow, SVersionRange *pVerRange, void* pBlockLoadInfo, const char* idStr) {
   pMTree->backward = backward;
   pMTree->pIter = NULL;
   pMTree->pIterList = taosArrayInit(4, POINTER_BYTES);
@@ -453,6 +467,8 @@ int32_t tMergeTreeOpen(SMergeTree *pMTree, int8_t backward, SDataFReader *pFRead
     return TSDB_CODE_OUT_OF_MEMORY;
   }
 
+  pMTree->idStr = idStr;
+
   tRBTreeCreate(&pMTree->rbt, tLDataIterCmprFn);
   int32_t code = TSDB_CODE_SUCCESS;
 
@@ -475,7 +491,7 @@ int32_t tMergeTreeOpen(SMergeTree *pMTree, int8_t backward, SDataFReader *pFRead
       goto _end;
     }
 
-    bool hasVal = tLDataIterNextRow(pIter);
+    bool hasVal = tLDataIterNextRow(pIter, pMTree->idStr);
     if (hasVal) {
       taosArrayPush(pMTree->pIterList, &pIter);
       tMergeTreeAddIter(pMTree, pIter);
@@ -498,7 +514,7 @@ bool tMergeTreeNext(SMergeTree *pMTree) {
   if (pMTree->pIter) {
     SLDataIter *pIter = pMTree->pIter;
 
-    bool hasVal = tLDataIterNextRow(pIter);
+    bool hasVal = tLDataIterNextRow(pIter, pMTree->idStr);
     if (!hasVal) {
       pMTree->pIter = NULL;
     }

source/dnode/vnode/src/tsdb/tsdbRead.c

@@ -70,6 +70,8 @@ typedef struct SIOCostSummary {
   double  smaLoadTime;
   int64_t lastBlockLoad;
   double  lastBlockLoadTime;
+  int64_t composedBlocks;
+  double  buildComposedBlockTime;
 } SIOCostSummary;
 
 typedef struct SBlockLoadSuppInfo {
@@ -365,6 +367,9 @@ static bool filesetIteratorNext(SFilesetIter* pIter, STsdbReader* pReader) {
     return false;
   }
 
+  SIOCostSummary* pSum = &pReader->cost;
+  getLastBlockLoadInfo(pIter->pLastBlockReader->pInfo, &pSum->lastBlockLoad, &pReader->cost.lastBlockLoadTime);
+
   pIter->pLastBlockReader->uid = 0;
   tMergeTreeClose(&pIter->pLastBlockReader->mergeTree);
   resetLastBlockLoadInfo(pIter->pLastBlockReader->pInfo);
@@ -1434,11 +1439,6 @@ static int32_t doMergeFileBlockAndLastBlock(SLastBlockReader* pLastBlockReader,
       tRowMerge(&merge, &fRow1);
       doMergeRowsInLastBlock(pLastBlockReader, pBlockScanInfo, tsLastBlock, &merge);
 
-      // merge with block data if ts == key
-      if (mergeBlockData && (tsLastBlock == pBlockData->aTSKEY[pDumpInfo->rowIndex])) {
-        doMergeRowsInFileBlocks(pBlockData, pBlockScanInfo, pReader, &merge);
-      }
-
       int32_t code = tRowMergerGetRow(&merge, &pTSRow);
       if (code != TSDB_CODE_SUCCESS) {
         return code;
@@ -1452,9 +1452,10 @@ static int32_t doMergeFileBlockAndLastBlock(SLastBlockReader* pLastBlockReader,
   } else {  // not merge block data
     tRowMergerInit(&merge, &fRow, pReader->pSchema);
     doMergeRowsInLastBlock(pLastBlockReader, pBlockScanInfo, tsLastBlock, &merge);
+    ASSERT(mergeBlockData);
 
     // merge with block data if ts == key
-    if (mergeBlockData && (tsLastBlock == pBlockData->aTSKEY[pDumpInfo->rowIndex])) {
+    if (tsLastBlock == pBlockData->aTSKEY[pDumpInfo->rowIndex]) {
       doMergeRowsInFileBlocks(pBlockData, pBlockScanInfo, pReader, &merge);
     }
 
@@ -1942,7 +1943,7 @@ static bool initLastBlockReader(SLastBlockReader* pLBlockReader, STableBlockScan
 
   int32_t code =
       tMergeTreeOpen(&pLBlockReader->mergeTree, (pLBlockReader->order == TSDB_ORDER_DESC), pReader->pFileReader,
-                     pReader->suid, pScanInfo->uid, &w, &pLBlockReader->verRange, pLBlockReader->pInfo);
+                     pReader->suid, pScanInfo->uid, &w, &pLBlockReader->verRange, pLBlockReader->pInfo, pReader->idStr);
   if (code != TSDB_CODE_SUCCESS) {
     return false;
   }
@@ -1982,8 +1983,6 @@ int32_t mergeRowsInFileBlocks(SBlockData* pBlockData, STableBlockScanInfo* pBloc
     tRowMergerClear(&merge);
     return TSDB_CODE_SUCCESS;
   }
-
-  return TSDB_CODE_SUCCESS;
 }
 
 static int32_t buildComposedDataBlockImpl(STsdbReader* pReader, STableBlockScanInfo* pBlockScanInfo,
@@ -2076,13 +2075,16 @@ static int32_t buildComposedDataBlock(STsdbReader* pReader) {
   blockDataUpdateTsWindow(pResBlock, 0);
 
   setComposedBlockFlag(pReader, true);
-  int64_t et = taosGetTimestampUs();
+  double el = (taosGetTimestampUs() - st)/1000.0;
+
+  pReader->cost.composedBlocks += 1;
+  pReader->cost.buildComposedBlockTime += el;
 
   if (pResBlock->info.rows > 0) {
     tsdbDebug("%p uid:%" PRIu64 ", composed data block created, brange:%" PRIu64 "-%" PRIu64
               " rows:%d, elapsed time:%.2f ms %s",
               pReader, pBlockScanInfo->uid, pResBlock->info.window.skey, pResBlock->info.window.ekey,
-              pResBlock->info.rows, (et - st) / 1000.0, pReader->idStr);
+              pResBlock->info.rows, el, pReader->idStr);
   }
 
   return TSDB_CODE_SUCCESS;
@@ -3364,24 +3366,27 @@ void tsdbReaderClose(STsdbReader* pReader) {
   tsdbUntakeReadSnap(pReader->pTsdb, pReader->pReadSnap);
 
   taosMemoryFree(pReader->status.uidCheckInfo.tableUidList);
+  SIOCostSummary* pCost = &pReader->cost;
 
   SFilesetIter* pFilesetIter = &pReader->status.fileIter;
   if (pFilesetIter->pLastBlockReader != NULL) {
-    tMergeTreeClose(&pFilesetIter->pLastBlockReader->mergeTree);
-    pFilesetIter->pLastBlockReader->pInfo = destroyLastBlockLoadInfo(pFilesetIter->pLastBlockReader->pInfo);
-    taosMemoryFree(pFilesetIter->pLastBlockReader);
-  }
+    SLastBlockReader* pLReader = pFilesetIter->pLastBlockReader;
+    tMergeTreeClose(&pLReader->mergeTree);
 
-  SIOCostSummary* pCost = &pReader->cost;
+    getLastBlockLoadInfo(pLReader->pInfo, &pCost->lastBlockLoad, &pCost->lastBlockLoadTime);
 
-  tsdbDebug("%p :io-cost summary: head-file:%" PRIu64 ", head-file time:%.2f ms, SMA:%" PRId64
-            " SMA-time:%.2f ms, fileBlocks:%" PRId64
-            ", fileBlocks-time:%.2f ms, "
-            "build in-memory-block-time:%.2f ms, lastBlocks:%" PRId64
-            ", lastBlocks-time:%.2f ms, STableBlockScanInfo size:%.2f Kb %s",
-            pReader, pCost->headFileLoad, pCost->headFileLoadTime, pCost->smaDataLoad, pCost->smaLoadTime,
-            pCost->numOfBlocks, pCost->blockLoadTime, pCost->buildmemBlock, pCost->lastBlockLoad,
-            pCost->lastBlockLoadTime, numOfTables * sizeof(STableBlockScanInfo) / 1000.0, pReader->idStr);
+    pLReader->pInfo = destroyLastBlockLoadInfo(pLReader->pInfo);
+    taosMemoryFree(pLReader);
+  }
+
+  tsdbDebug(
+      "%p :io-cost summary: head-file:%" PRIu64 ", head-file time:%.2f ms, SMA:%" PRId64
+      " SMA-time:%.2f ms, fileBlocks:%" PRId64 ", fileBlocks-load-time:%.2f ms, "
+      "build in-memory-block-time:%.2f ms, lastBlocks:%" PRId64 ", lastBlocks-time:%.2f ms, composed-blocks:%" PRId64
+      ", composed-blocks-time:%.2fms, STableBlockScanInfo size:%.2f Kb %s",
+      pReader, pCost->headFileLoad, pCost->headFileLoadTime, pCost->smaDataLoad, pCost->smaLoadTime, pCost->numOfBlocks,
+      pCost->blockLoadTime, pCost->buildmemBlock, pCost->lastBlockLoad, pCost->lastBlockLoadTime, pCost->composedBlocks,
+      pCost->buildComposedBlockTime, numOfTables * sizeof(STableBlockScanInfo) / 1000.0, pReader->idStr);
 
   taosMemoryFree(pReader->idStr);
   taosMemoryFree(pReader->pSchema);

tests/script/tsim/column/table.sim

@@ -159,6 +159,7 @@ if $data01 != 10 then
   return -1
 endi
 if $data02 != 4.500000000 then
+  print expect 4.500000000, actual: $data02
   return -1
 endi
 if $data03 != 4.500000000 then