change log format

src/common/src/tglobal.c

@@ -200,7 +200,7 @@ int32_t tsNumOfLogLines = 10000000;
 int32_t mDebugFlag = 135;
 int32_t sdbDebugFlag = 135;
 int32_t dDebugFlag = 135;
-int32_t vDebugFlag = 131;
+int32_t vDebugFlag = 135;
 int32_t cDebugFlag = 131;
 int32_t jniDebugFlag = 131;
 int32_t odbcDebugFlag = 131;

src/sync/src/syncMain.c

@@ -541,7 +541,7 @@ static SSyncPeer *syncAddPeer(SSyncNode *pNode, const SNodeInfo *pInfo) {
   pPeer->ip = ip;
   pPeer->port = pInfo->nodePort;
   pPeer->fqdn[sizeof(pPeer->fqdn) - 1] = 0;
-  snprintf(pPeer->id, sizeof(pPeer->id), "vgId:%d, peer:%s:%u", pNode->vgId, pPeer->fqdn, pPeer->port);
+  snprintf(pPeer->id, sizeof(pPeer->id), "vgId:%d, nodeId:%d", pNode->vgId, pPeer->nodeId);
 
   pPeer->peerFd = -1;
   pPeer->syncFd = -1;
@@ -1144,8 +1144,7 @@ static void syncProcessIncommingConnection(int32_t connFd, uint32_t sourceIp) {
       pPeer->syncFd = connFd;
       syncCreateRestoreDataThread(pPeer);
     } else {
-      sDebug("%s, TCP connection is already up(pfd:%d), close one, new pfd:%d sfd:%d", pPeer->id, pPeer->peerFd, connFd,
+      sDebug("%s, TCP connection is up, pfd:%d sfd:%d, old pfd:%d", pPeer->id, connFd, pPeer->syncFd, pPeer->peerFd);
-             pPeer->syncFd);
       syncClosePeerConn(pPeer);
       pPeer->peerFd = connFd;
       pPeer->pConn = taosAllocateTcpConn(tsTcpPool, pPeer, connFd);

src/sync/src/syncRestore.c

@@ -134,7 +134,7 @@ static int32_t syncRestoreFile(SSyncPeer *pPeer, uint64_t *fversion) {
     // data file is changed, code shall be set to 1
     *fversion = minfo.fversion;
     code = 1;
-    sDebug("%s, file changed while restore file", pPeer->id);
+    sDebug("%s, file changed after restore file, fver:%" PRIu64, pPeer->id, *fversion);
   }
 
   if (code < 0) {
@@ -160,7 +160,7 @@ static int32_t syncRestoreWal(SSyncPeer *pPeer) {
     }
 
     if (pHead->len == 0) {
-      sDebug("%s, wal is synced over", pPeer->id);
+      sDebug("%s, wal is synced over, last wver:%" PRIu64, pPeer->id, lastVer);
       code = 0;
       break;
     }  // wal sync over

src/sync/src/syncRetrieve.c

@@ -58,6 +58,7 @@ static int32_t syncRetrieveFile(SSyncPeer *pPeer) {
     fileInfo.magic = (*pNode->getFileInfo)(pNode->vgId, fileInfo.name, &fileInfo.index, TAOS_SYNC_MAX_INDEX,
                                            &fileInfo.size, &fileInfo.fversion);
     // fileInfo.size = htonl(size);
+    sDebug("%s, file:%s info will be sent, size:%" PRId64, pPeer->id, fileInfo.name, fileInfo.size);
 
     // send the file info
     int32_t ret = taosWriteMsg(pPeer->syncFd, &(fileInfo), sizeof(fileInfo));
@@ -107,7 +108,7 @@ static int32_t syncRetrieveFile(SSyncPeer *pPeer) {
       break;
     }
 
-    sDebug("%s, %s is sent, size:%" PRId64, pPeer->id, name, fileInfo.size);
+    sDebug("%s, file:%s is sent, size:%" PRId64, pPeer->id, fileInfo.name, fileInfo.size);
     fileInfo.index++;
 
     // check if processed files are modified
@@ -419,18 +420,18 @@ static int32_t syncRetrieveDataStepByStep(SSyncPeer *pPeer) {
 
   pPeer->sversion = 0;
   pPeer->sstatus = TAOS_SYNC_STATUS_FILE;
-  sInfo("%s, start to retrieve file, set sstatus:%s", pPeer->id, syncStatus[pPeer->sstatus]);
+  sInfo("%s, start to retrieve files, set sstatus:%s", pPeer->id, syncStatus[pPeer->sstatus]);
   if (syncRetrieveFile(pPeer) < 0) {
-    sError("%s, failed to retrieve file", pPeer->id);
+    sError("%s, failed to retrieve files", pPeer->id);
     return -1;
   }
 
   // if no files are synced, there must be wal to sync, sversion must be larger than one
   if (pPeer->sversion == 0) pPeer->sversion = 1;
 
-  sInfo("%s, start to retrieve wal", pPeer->id);
+  sInfo("%s, start to retrieve wals", pPeer->id);
   if (syncRetrieveWal(pPeer) < 0) {
-    sError("%s, failed to retrieve wal", pPeer->id);
+    sError("%s, failed to retrieve wals", pPeer->id);
     return -1;
   }
 

src/vnode/src/vnodeMain.c

@@ -688,8 +688,10 @@ static void vnodeCtrlFlow(int32_t vgId, int32_t level) {
     return;
   }
 
-  pVnode->flowctrlLevel = level;
+  if (pVnode->flowctrlLevel != level) {
-  vDebug("vgId:%d, set flowctrl level:%d", pVnode->vgId, level);
+    vDebug("vgId:%d, set flowctrl level from %d to %d", pVnode->vgId, pVnode->flowctrlLevel, level);
+    pVnode->flowctrlLevel = level;
+  }
 
   vnodeRelease(pVnode);
 }
@@ -779,6 +781,7 @@ static int32_t vnodeGetFileVersion(int32_t vgId, uint64_t *fver) {
 
   int32_t code = 0;
   if (pVnode->isCommiting) {
+    vDebug("vgId:%d, vnode is commiting while get file version", vgId);
     code = -1;
   } else {
     *fver = pVnode->fversion;

src/vnode/src/vnodeWrite.c

@@ -282,13 +282,15 @@ static void vnodeFlowCtrlMsgToWQueue(void *param, void *tmrId) {
 
   pWrite->processedCount++;
   if (pWrite->processedCount > 100) {
-    vError("vgId:%d, msg:%p, failed to process since %s", pVnode->vgId, pWrite, tstrerror(code));
+    vError("vgId:%d, msg:%p, failed to process since %s, retry:%d", pVnode->vgId, pWrite, tstrerror(code),
+           pWrite->processedCount);
     pWrite->processedCount = 1;
     dnodeSendRpcVWriteRsp(pWrite->pVnode, pWrite, code);
   } else {
     code = vnodePerformFlowCtrl(pWrite);
     if (code == 0) {
-      vDebug("vgId:%d, write into vwqueue after flowctrl", pVnode->vgId);
+      vDebug("vgId:%d, msg:%p, write into vwqueue after flowctrl, retry:%d", pVnode->vgId, pWrite,
+             pWrite->processedCount);
       pWrite->processedCount = 0;
       taosWriteQitem(pVnode->wqueue, pWrite->qtype, pWrite);
     }
@@ -310,7 +312,7 @@ static int32_t vnodePerformFlowCtrl(SVWriteMsg *pWrite) {
     void *unUsed = NULL;
     taosTmrReset(vnodeFlowCtrlMsgToWQueue, 100, pWrite, tsDnodeTmr, &unUsed);
 
-    vTrace("vgId:%d, msg:%p, app:%p, perform flowctrl, count:%d", pVnode->vgId, pWrite, pWrite->rpcMsg.ahandle,
+    vTrace("vgId:%d, msg:%p, app:%p, perform flowctrl, retry:%d", pVnode->vgId, pWrite, pWrite->rpcMsg.ahandle,
            pWrite->processedCount);
     return TSDB_CODE_VND_ACTION_IN_PROGRESS;
   }

src/wal/src/walWrite.c

@@ -211,7 +211,7 @@ int32_t walGetWalFile(void *handle, char *fileName, int64_t *fileId) {
     code = (*fileId == pWal->fileId) ? 0 : 1;
   }
 
-  wTrace("vgId:%d, get wal file, code:%d curId:%" PRId64 " outId:%" PRId64, pWal->vgId, code, pWal->fileId, *fileId);
+  wDebug("vgId:%d, get wal file, code:%d curId:%" PRId64 " outId:%" PRId64, pWal->vgId, code, pWal->fileId, *fileId);
   pthread_mutex_unlock(&(pWal->mutex));
 
   return code;
@@ -325,7 +325,7 @@ static int32_t walRestoreWalFile(SWal *pWal, void *pVnode, FWalWrite writeFp, ch
 
     offset = offset + sizeof(SWalHead) + pHead->len;
 
-    wTrace("vgId:%d, restore wal, fileId:%" PRId64 " hver:%" PRIu64 " wver:%" PRIu64 " len:%d", pWal->vgId,
+    wDebug("vgId:%d, restore wal, fileId:%" PRId64 " hver:%" PRIu64 " wver:%" PRIu64 " len:%d", pWal->vgId,
            fileId, pHead->version, pWal->version, pHead->len);
 
     pWal->version = pHead->version;

tests/script/general/wal/sync.sim

@@ -82,6 +82,7 @@ restful d1 table_rest 1591772800 30000
 restful d1 table_rest 1591872800 30000
 restful d1 table_rest 1591972800 30000
 
+sleep 1000
 sql select * from table_rest;
 print rows: $rows
 if $rows != 300000 then

tests/script/tmp/mnodes.sim

@@ -20,6 +20,10 @@ system sh/cfg.sh -n dnode1 -c maxTablesPerVnode -v 20000
 system sh/cfg.sh -n dnode2 -c maxTablesPerVnode -v 20000
 system sh/cfg.sh -n dnode3 -c maxTablesPerVnode -v 20000
 
+system sh/cfg.sh -n dnode1 -c minTablesPerVnode -v 1000
+system sh/cfg.sh -n dnode2 -c minTablesPerVnode -v 1000
+system sh/cfg.sh -n dnode3 -c minTablesPerVnode -v 1000
+
 system sh/cfg.sh -n dnode1 -c maxVgroupsPerDb -v 20
 system sh/cfg.sh -n dnode2 -c maxVgroupsPerDb -v 20
 system sh/cfg.sh -n dnode3 -c maxVgroupsPerDb -v 20