From 98e380be51fe8c5d471b84affe8a17bae419e14d Mon Sep 17 00:00:00 2001 From: Shengliang Guan Date: Mon, 9 Nov 2020 05:41:58 +0000 Subject: [PATCH] add log for wal --- src/common/src/tglobal.c | 2 ++ src/dnode/src/dnodeVWrite.c | 4 ++-- src/inc/taosdef.h | 2 ++ src/sync/src/syncMain.c | 4 ++-- src/sync/src/syncRestore.c | 2 +- src/sync/src/syncRetrieve.c | 4 ++-- src/vnode/src/vnodeMain.c | 5 ++++- src/vnode/src/vnodeVersion.c | 4 ++-- src/vnode/src/vnodeWrite.c | 14 +++++++++----- src/wal/src/walWrite.c | 10 +++++----- 10 files changed, 31 insertions(+), 20 deletions(-) diff --git a/src/common/src/tglobal.c b/src/common/src/tglobal.c index 75c8f93a82..3bc1e4d0cc 100644 --- a/src/common/src/tglobal.c +++ b/src/common/src/tglobal.c @@ -218,6 +218,8 @@ int32_t (*monitorStartSystemFp)() = NULL; void (*monitorStopSystemFp)() = NULL; void (*monitorExecuteSQLFp)(char *sql) = NULL; +char *qtypeStr[] = {"rpc", "fwd", "wal", "cq", "query"}; + static pthread_once_t tsInitGlobalCfgOnce = PTHREAD_ONCE_INIT; void taosSetAllDebugFlag() { diff --git a/src/dnode/src/dnodeVWrite.c b/src/dnode/src/dnodeVWrite.c index 9b7497d3ec..e0345eb1f6 100644 --- a/src/dnode/src/dnodeVWrite.c +++ b/src/dnode/src/dnodeVWrite.c @@ -207,8 +207,8 @@ static void *dnodeProcessVWriteQueue(void *param) { bool forceFsync = false; for (int32_t i = 0; i < numOfMsgs; ++i) { taosGetQitem(pWorker->qall, &qtype, (void **)&pWrite); - dTrace("%p, msg:%p:%s will be processed in vwrite queue, qtype:%d version:%" PRIu64, pWrite->rpcAhandle, pWrite, - taosMsg[pWrite->pHead->msgType], qtype, pWrite->pHead->version); + dTrace("%p, msg:%p:%s will be processed in vwrite queue, qtype:%s hver:%" PRIu64, pWrite->rpcAhandle, pWrite, + taosMsg[pWrite->pHead->msgType], qtypeStr[qtype], pWrite->pHead->version); pWrite->code = vnodeProcessWrite(pVnode, pWrite->pHead, qtype, &pWrite->rspRet); if (pWrite->code <= 0) pWrite->processedCount = 1; diff --git a/src/inc/taosdef.h b/src/inc/taosdef.h index 6ee2567322..fa8af2c67e 100644 --- a/src/inc/taosdef.h +++ b/src/inc/taosdef.h @@ -467,6 +467,8 @@ typedef enum { TSDB_CHECK_ITEM_MAX } ECheckItemType; +extern char *qtypeStr[]; + #ifdef __cplusplus } #endif diff --git a/src/sync/src/syncMain.c b/src/sync/src/syncMain.c index eee8af7bcd..3d860f8bbb 100644 --- a/src/sync/src/syncMain.c +++ b/src/sync/src/syncMain.c @@ -1221,8 +1221,8 @@ static int32_t syncForwardToPeerImpl(SSyncNode *pNode, void *data, void *mhandle // always update version nodeVersion = pWalHead->version; - sDebug("vgId:%d, replica:%d nodeRole:%s qtype:%d ver:%" PRIu64, pNode->vgId, pNode->replica, syncRole[nodeRole], - qtype, pWalHead->version); + sDebug("vgId:%d, forward to peer, replica:%d role:%s qtype:%s hver:%" PRIu64, pNode->vgId, pNode->replica, + syncRole[nodeRole], qtypeStr[qtype], pWalHead->version); if (pNode->replica == 1 || nodeRole != TAOS_SYNC_ROLE_MASTER) return 0; diff --git a/src/sync/src/syncRestore.c b/src/sync/src/syncRestore.c index 9216567bc5..b35388db35 100644 --- a/src/sync/src/syncRestore.c +++ b/src/sync/src/syncRestore.c @@ -153,7 +153,7 @@ static int syncRestoreWal(SSyncPeer *pPeer) { ret = taosReadMsg(pPeer->syncFd, pHead->cont, pHead->len); if (ret < 0) break; - sDebug("%s, restore a record, ver:%" PRIu64, pPeer->id, pHead->version); + sDebug("%s, restore a record, qtype:wal hver:%" PRIu64, pPeer->id, pHead->version); (*pNode->writeToCache)(pNode->ahandle, pHead, TAOS_QTYPE_WAL, NULL); } diff --git a/src/sync/src/syncRetrieve.c b/src/sync/src/syncRetrieve.c index 0fe189db7a..d77587f227 100644 --- a/src/sync/src/syncRetrieve.c +++ b/src/sync/src/syncRetrieve.c @@ -256,7 +256,7 @@ static int syncRetrieveLastWal(SSyncPeer *pPeer, char *name, uint64_t fversion, } (void)lseek(sfd, offset, SEEK_SET); - sDebug("%s, retrieve last wal, offset:%" PRId64 " fversion:%" PRIu64, pPeer->id, offset, fversion); + sDebug("%s, retrieve last wal, offset:%" PRId64 " fver:%" PRIu64, pPeer->id, offset, fversion); while (1) { int wsize = syncReadOneWalRecord(sfd, pHead, pEvent); @@ -325,7 +325,7 @@ static int syncProcessLastWal(SSyncPeer *pPeer, char *wname, int64_t index) { // if all data up to fversion is read out, it is over if (pPeer->sversion >= fversion && fversion > 0) { code = 0; - sDebug("%s, data up to fversion:%" PRId64 " has been read out, bytes:%d", pPeer->id, fversion, bytes); + sDebug("%s, data up to fver:%" PRIu64 " has been read out, bytes:%d", pPeer->id, fversion, bytes); break; } diff --git a/src/vnode/src/vnodeMain.c b/src/vnode/src/vnodeMain.c index 4cdf9f898a..f90b9701fe 100644 --- a/src/vnode/src/vnodeMain.c +++ b/src/vnode/src/vnodeMain.c @@ -577,10 +577,12 @@ static int vnodeProcessTsdbStatus(void *arg, int status) { if (status == TSDB_STATUS_COMMIT_START) { pVnode->fversion = pVnode->version; + vDebug("vgId:%d, start commit, fver:%" PRIu64 " vver:%" PRIu64, pVnode->vgId, pVnode->fversion, pVnode->version); return walRenew(pVnode->wal); } if (status == TSDB_STATUS_COMMIT_OVER) { + vDebug("vgId:%d, commit over, fver:%" PRIu64 " vver:%" PRIu64, pVnode->vgId, pVnode->fversion, pVnode->version); return vnodeSaveVersion(pVnode); } @@ -656,11 +658,12 @@ static int vnodeResetTsdb(SVnodeObj *pVnode) { static int vnodeNotifyFileSynced(void *ahandle, uint64_t fversion) { SVnodeObj *pVnode = ahandle; - vDebug("vgId:%d, data file is synced, fversion:%" PRId64, pVnode->vgId, fversion); pVnode->fversion = fversion; pVnode->version = fversion; vnodeSaveVersion(pVnode); + vDebug("vgId:%d, data file is synced, fver:%" PRIu64 " vver:%" PRIu64, pVnode->vgId, pVnode->fversion, + pVnode->version); return vnodeResetTsdb(pVnode); } diff --git a/src/vnode/src/vnodeVersion.c b/src/vnode/src/vnodeVersion.c index 51f9ac8f3a..8f6360b4f9 100644 --- a/src/vnode/src/vnodeVersion.c +++ b/src/vnode/src/vnodeVersion.c @@ -64,7 +64,7 @@ int32_t vnodeReadVersion(SVnodeObj *pVnode) { pVnode->version = (uint64_t)ver->valueint; terrno = TSDB_CODE_SUCCESS; - vInfo("vgId:%d, read %s successfully, version:%" PRIu64, pVnode->vgId, file, pVnode->version); + vInfo("vgId:%d, read %s successfully, fver:%" PRIu64, pVnode->vgId, file, pVnode->version); PARSE_VER_ERROR: if (content != NULL) free(content); @@ -98,6 +98,6 @@ int32_t vnodeSaveVersion(SVnodeObj *pVnode) { free(content); terrno = 0; - vInfo("vgId:%d, successed to write %s, version:%" PRIu64, pVnode->vgId, file, pVnode->fversion); + vInfo("vgId:%d, successed to write %s, fver:%" PRIu64, pVnode->vgId, file, pVnode->fversion); return TSDB_CODE_SUCCESS; } \ No newline at end of file diff --git a/src/vnode/src/vnodeWrite.c b/src/vnode/src/vnodeWrite.c index f42b359b26..99594607ac 100644 --- a/src/vnode/src/vnodeWrite.c +++ b/src/vnode/src/vnodeWrite.c @@ -52,20 +52,24 @@ int32_t vnodeProcessWrite(void *vparam, void *wparam, int32_t qtype, void *rpara SRspRet * pRspRet = rparam; if (vnodeProcessWriteMsgFp[pHead->msgType] == NULL) { - vDebug("vgId:%d, msgType:%s not processed, no handle", pVnode->vgId, taosMsg[pHead->msgType]); + vError("vgId:%d, msg:%s not processed since no handle, qtype:%s hver:%" PRIu64, pVnode->vgId, + taosMsg[pHead->msgType], qtypeStr[qtype], pHead->version); return TSDB_CODE_VND_MSG_NOT_PROCESSED; } + vTrace("vgId:%d, msg:%s will be processed in vnode, qtype:%s hver:%" PRIu64 " vver:%" PRIu64, pVnode->vgId, + taosMsg[pHead->msgType], qtypeStr[qtype], pHead->version, pVnode->version); + if (pHead->version == 0) { // from client or CQ if (pVnode->status != TAOS_VN_STATUS_READY) { - vDebug("vgId:%d, msgType:%s not processed, vnode status is %d", pVnode->vgId, taosMsg[pHead->msgType], - pVnode->status); + vDebug("vgId:%d, msg:%s not processed since vstatus:%d, qtype:%s hver:%" PRIu64, pVnode->vgId, + taosMsg[pHead->msgType], pVnode->status, qtypeStr[qtype], pHead->version); return TSDB_CODE_APP_NOT_READY; // it may be in deleting or closing state } if (pVnode->role != TAOS_SYNC_ROLE_MASTER) { - vDebug("vgId:%d, msgType:%s not processed, replica:%d role:%s", pVnode->vgId, taosMsg[pHead->msgType], - pVnode->syncCfg.replica, syncRole[pVnode->role]); + vDebug("vgId:%d, msg:%s not processed since replica:%d role:%s, qtype:%s hver:%" PRIu64, pVnode->vgId, + taosMsg[pHead->msgType], pVnode->syncCfg.replica, syncRole[pVnode->role], qtypeStr[qtype], pHead->version); return TSDB_CODE_APP_NOT_READY; } diff --git a/src/wal/src/walWrite.c b/src/wal/src/walWrite.c index ecd0fd0ca0..9681f4b898 100644 --- a/src/wal/src/walWrite.c +++ b/src/wal/src/walWrite.c @@ -99,8 +99,8 @@ int32_t walWrite(void *handle, SWalHead *pHead) { code = TAOS_SYSTEM_ERROR(errno); wError("vgId:%d, file:%s, failed to write since %s", pWal->vgId, pWal->name, strerror(errno)); } else { - wTrace("vgId:%d, fileId:%" PRId64 " fd:%d, write wal ver:%" PRId64 ", head ver:%" PRIu64 ", len:%d ", pWal->vgId, - pWal->fileId, pWal->fd, pWal->version, pHead->version, pHead->len); + wTrace("vgId:%d, write wal, fileId:%" PRId64 " fd:%d hver:%" PRId64 " wver:%" PRIu64 " len:%d", pWal->vgId, + pWal->fileId, pWal->fd, pHead->version, pWal->version, pHead->len); pWal->version = pHead->version; } @@ -261,7 +261,7 @@ static int32_t walRestoreWalFile(SWal *pWal, void *pVnode, FWalWrite writeFp, ch } if (!taosCheckChecksumWhole((uint8_t *)pHead, sizeof(SWalHead))) { - wError("vgId:%d, file:%s, wal head cksum is messed up, ver:%" PRIu64 " len:%d offset:%" PRId64, pWal->vgId, name, + wError("vgId:%d, file:%s, wal head cksum is messed up, hver:%" PRIu64 " len:%d offset:%" PRId64, pWal->vgId, name, pHead->version, pHead->len, offset); code = walSkipCorruptedRecord(pWal, pHead, fd, &offset); if (code != TSDB_CODE_SUCCESS) { @@ -297,8 +297,8 @@ static int32_t walRestoreWalFile(SWal *pWal, void *pVnode, FWalWrite writeFp, ch offset = offset + sizeof(SWalHead) + pHead->len; - wTrace("vgId:%d, fileId:%" PRId64 ", restore wal ver:%" PRIu64 ", head ver:%" PRIu64 " len:%d", pWal->vgId, fileId, - pWal->version, pHead->version, pHead->len); + wTrace("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; (*writeFp)(pVnode, pHead, TAOS_QTYPE_WAL, NULL); -- GitLab