From c94f30e3838106d50423bd8c64eb901ca6675313 Mon Sep 17 00:00:00 2001 From: Shengliang Guan Date: Mon, 3 Jan 2022 23:20:29 -0800 Subject: [PATCH] add some logs --- source/dnode/mnode/impl/src/mndDnode.c | 2 +- source/dnode/mnode/impl/src/mndShow.c | 2 +- source/dnode/mnode/impl/src/mndSync.c | 16 ++++++++----- source/dnode/mnode/impl/src/mndTrans.c | 14 +++++++---- source/dnode/mnode/impl/src/mnode.c | 28 +++++++++++----------- source/dnode/mnode/sdb/src/sdb.c | 4 ++-- source/dnode/mnode/sdb/src/sdbFile.c | 1 + source/dnode/mnode/sdb/src/sdbHash.c | 32 +++++++++++++++++++++----- 8 files changed, 64 insertions(+), 35 deletions(-) diff --git a/source/dnode/mnode/impl/src/mndDnode.c b/source/dnode/mnode/impl/src/mndDnode.c index d110969025..1d78359015 100644 --- a/source/dnode/mnode/impl/src/mndDnode.c +++ b/source/dnode/mnode/impl/src/mndDnode.c @@ -354,7 +354,7 @@ static int32_t mndProcessStatusMsg(SMnodeMsg *pMsg) { } if (pStatus->dnodeId == 0) { - mDebug("dnode:%d %s, first access, set clusterId %" PRId64, pDnode->id, pDnode->ep, pMnode->clusterId); + mDebug("dnode:%d, %s first access, set clusterId %" PRId64, pDnode->id, pDnode->ep, pMnode->clusterId); } else { if (pStatus->clusterId != pMnode->clusterId) { if (pDnode != NULL) { diff --git a/source/dnode/mnode/impl/src/mndShow.c b/source/dnode/mnode/impl/src/mndShow.c index c156c87123..125c250614 100644 --- a/source/dnode/mnode/impl/src/mndShow.c +++ b/source/dnode/mnode/impl/src/mndShow.c @@ -152,7 +152,7 @@ static int32_t mndProcessShowMsg(SMnodeMsg *pMnodeMsg) { } int32_t code = (*metaFp)(pMnodeMsg, pShow, &pRsp->tableMeta); - mDebug("show:0x%" PRIx64 ", get meta finished, numOfRows:%d cols:%d type:%s result:%s", pShow->id, pShow->numOfRows, + mDebug("show:0x%" PRIx64 ", get meta finished, numOfRows:%d cols:%d type:%s, result:%s", pShow->id, pShow->numOfRows, pShow->numOfColumns, mndShowStr(type), tstrerror(code)); if (code == TSDB_CODE_SUCCESS) { diff --git a/source/dnode/mnode/impl/src/mndSync.c b/source/dnode/mnode/impl/src/mndSync.c index 49eaa45156..19fb89454e 100644 --- a/source/dnode/mnode/impl/src/mndSync.c +++ b/source/dnode/mnode/impl/src/mndSync.c @@ -52,11 +52,12 @@ static int32_t mndRestoreWal(SMnode *pMnode) { SWalReadHandle *pHandle = walOpenReadHandle(pWal); if (pHandle == NULL) return -1; - int64_t start = walGetFirstVer(pWal); - int64_t end = walGetLastVer(pWal); - start = MAX(lastSdbVer + 1, start); + int64_t first = walGetFirstVer(pWal); + int64_t last = walGetLastVer(pWal); + mDebug("restore sdb wal start, sdb ver:%" PRId64 ", wal first:%" PRId64 " last:%" PRId64, lastSdbVer, first, last); - for (int64_t ver = start; ver >= 0 && ver <= end; ++ver) { + first = MAX(lastSdbVer + 1, first); + for (int64_t ver = first; ver >= 0 && ver <= last; ++ver) { if (walReadWithHandle(pHandle, ver) < 0) { mError("failed to read by wal handle since %s, ver:%" PRId64, terrstr(), ver); goto WAL_RESTORE_OVER; @@ -76,15 +77,18 @@ static int32_t mndRestoreWal(SMnode *pMnode) { } sdbUpdateVer(pSdb, 1); + mDebug("wal:%" PRId64 ", is restored", ver); } int64_t sdbVer = sdbUpdateVer(pSdb, 0); + mDebug("restore sdb wal finished, sdb ver:%" PRId64, sdbVer); + if (walBeginSnapshot(pWal, sdbVer) < 0) { goto WAL_RESTORE_OVER; } if (sdbVer != lastSdbVer) { - mInfo("sdb restore wal from %" PRId64 " to %" PRId64, lastSdbVer, sdbVer); + mInfo("sdb restored from %" PRId64 " to %" PRId64 ", write file", lastSdbVer, sdbVer); if (sdbWriteFile(pSdb) != 0) { goto WAL_RESTORE_OVER; } @@ -147,7 +151,7 @@ int32_t mndSyncPropose(SMnode *pMnode, SSdbRaw *pRaw) { return -1; } - mTrace("raw:%p has been write to wal, ver:%" PRId64, pRaw, ver); + mTrace("raw:%p, write to wal, ver:%" PRId64, pRaw, ver); walCommit(pWal, ver); walFsync(pWal, true); diff --git a/source/dnode/mnode/impl/src/mndTrans.c b/source/dnode/mnode/impl/src/mndTrans.c index 5062048d6d..bf472a504c 100644 --- a/source/dnode/mnode/impl/src/mndTrans.c +++ b/source/dnode/mnode/impl/src/mndTrans.c @@ -169,7 +169,7 @@ TRANS_ENCODE_OVER: return NULL; } - mTrace("trans:%d, encode to raw:%p, len:%d", pTrans->id, pRaw, dataPos); + mTrace("trans:%d, encode to raw:%p, row:%p len:%d", pTrans->id, pRaw, pTrans, dataPos); return pRaw; } @@ -226,6 +226,7 @@ static SSdbRow *mndTransActionDecode(SSdbRaw *pRaw) { SDB_GET_INT32(pRaw, dataPos, &dataLen, TRANS_DECODE_OVER) pData = malloc(dataLen); if (pData == NULL) goto TRANS_DECODE_OVER; + mTrace("raw:%p, is created", pData); SDB_GET_BINARY(pRaw, dataPos, pData, dataLen, TRANS_DECODE_OVER); if (taosArrayPush(pTrans->redoLogs, &pData) == NULL) goto TRANS_DECODE_OVER; pData = NULL; @@ -235,6 +236,7 @@ static SSdbRow *mndTransActionDecode(SSdbRaw *pRaw) { SDB_GET_INT32(pRaw, dataPos, &dataLen, TRANS_DECODE_OVER) pData = malloc(dataLen); if (pData == NULL) goto TRANS_DECODE_OVER; + mTrace("raw:%p, is created", pData); SDB_GET_BINARY(pRaw, dataPos, pData, dataLen, TRANS_DECODE_OVER); if (taosArrayPush(pTrans->undoLogs, &pData) == NULL) goto TRANS_DECODE_OVER; pData = NULL; @@ -243,6 +245,8 @@ static SSdbRow *mndTransActionDecode(SSdbRaw *pRaw) { for (int32_t i = 0; i < commitLogNum; ++i) { SDB_GET_INT32(pRaw, dataPos, &dataLen, TRANS_DECODE_OVER) pData = malloc(dataLen); + if (pData == NULL) goto TRANS_DECODE_OVER; + mTrace("raw:%p, is created", pData); SDB_GET_BINARY(pRaw, dataPos, pData, dataLen, TRANS_DECODE_OVER); if (taosArrayPush(pTrans->commitLogs, &pData) == NULL) goto TRANS_DECODE_OVER; pData = NULL; @@ -284,13 +288,13 @@ TRANS_DECODE_OVER: return NULL; } - mTrace("trans:%d, decode from raw:%p, data:%p", pTrans->id, pRaw, pTrans); + mTrace("trans:%d, decode from raw:%p, row:%p", pTrans->id, pRaw, pTrans); return pRow; } static int32_t mndTransActionInsert(SSdb *pSdb, STrans *pTrans) { pTrans->stage = TRN_STAGE_PREPARE; - mTrace("trans:%d, perform insert action, data:%p", pTrans->id, pTrans); + mTrace("trans:%d, perform insert action, row:%p", pTrans->id, pTrans); return 0; } @@ -303,13 +307,13 @@ static void mndTransDropData(STrans *pTrans) { } static int32_t mndTransActionDelete(SSdb *pSdb, STrans *pTrans) { - mTrace("trans:%d, perform delete action, data:%p", pTrans->id, pTrans); + mTrace("trans:%d, perform delete action, row:%p", pTrans->id, pTrans); mndTransDropData(pTrans); return 0; } static int32_t mndTransActionUpdate(SSdb *pSdb, STrans *pOldTrans, STrans *pNewTrans) { - mTrace("trans:%d, perform update action, data:%p", pOldTrans->id, pOldTrans); + mTrace("trans:%d, perform update action, old_row:%p new_row:%p", pOldTrans->id, pOldTrans, pNewTrans); pOldTrans->stage = pNewTrans->stage; return 0; } diff --git a/source/dnode/mnode/impl/src/mnode.c b/source/dnode/mnode/impl/src/mnode.c index 3a55961d4a..abc86a7d35 100644 --- a/source/dnode/mnode/impl/src/mnode.c +++ b/source/dnode/mnode/impl/src/mnode.c @@ -185,7 +185,7 @@ static void mndCleanupSteps(SMnode *pMnode, int32_t pos) { for (int32_t s = pos; s >= 0; s--) { SMnodeStep *pStep = taosArrayGet(pMnode->pSteps, s); - mDebug("step:%s will cleanup", pStep->name); + mDebug("%s will cleanup", pStep->name); if (pStep->cleanupFp != NULL) { (*pStep->cleanupFp)(pMnode); } @@ -204,12 +204,12 @@ static int32_t mndExecSteps(SMnode *pMnode) { if ((*pStep->initFp)(pMnode) != 0) { int32_t code = terrno; - mError("step:%s exec failed since %s, start to cleanup", pStep->name, terrstr()); + mError("%s exec failed since %s, start to cleanup", pStep->name, terrstr()); mndCleanupSteps(pMnode, pos); terrno = code; return -1; } else { - mDebug("step:%s is initialized", pStep->name); + mDebug("%s is initialized", pStep->name); } } @@ -357,7 +357,7 @@ SMnodeMsg *mndInitMsg(SMnode *pMnode, SRpcMsg *pRpcMsg) { SMnodeMsg *pMsg = taosAllocateQitem(sizeof(SMnodeMsg)); if (pMsg == NULL) { terrno = TSDB_CODE_OUT_OF_MEMORY; - mError("RPC:%p, app:%p failed to create msg since %s", pRpcMsg->handle, pRpcMsg->ahandle, terrstr()); + mError("failed to create msg since %s, app:%p RPC:%p", terrstr(), pRpcMsg->ahandle, pRpcMsg->handle); return NULL; } @@ -365,7 +365,7 @@ SMnodeMsg *mndInitMsg(SMnode *pMnode, SRpcMsg *pRpcMsg) { if ((pRpcMsg->msgType & 1U) && rpcGetConnInfo(pRpcMsg->handle, &connInfo) != 0) { taosFreeQitem(pMsg); terrno = TSDB_CODE_MND_NO_USER_FROM_CONN; - mError("RPC:%p, app:%p failed to create msg since %s", pRpcMsg->handle, pRpcMsg->ahandle, terrstr()); + mError("failed to create msg since %s, app:%p RPC:%p", terrstr(), pRpcMsg->ahandle, pRpcMsg->handle); return NULL; } memcpy(pMsg->user, connInfo.user, TSDB_USER_LEN); @@ -374,12 +374,12 @@ SMnodeMsg *mndInitMsg(SMnode *pMnode, SRpcMsg *pRpcMsg) { pMsg->rpcMsg = *pRpcMsg; pMsg->createdTime = taosGetTimestampSec(); - mTrace("msg:%p, app:%p is created, RPC:%p", pMsg, pRpcMsg->ahandle, pRpcMsg->handle); + mTrace("msg:%p, is created, app:%p RPC:%p user:%s", pMsg, pRpcMsg->ahandle, pRpcMsg->handle, pMsg->user); return pMsg; } void mndCleanupMsg(SMnodeMsg *pMsg) { - mTrace("msg:%p, app:%p is destroyed, RPC:%p", pMsg, pMsg->rpcMsg.ahandle, pMsg->rpcMsg.handle); + mTrace("msg:%p, is destroyed, app:%p RPC:%p", pMsg, pMsg->rpcMsg.ahandle, pMsg->rpcMsg.handle); rpcFreeCont(pMsg->rpcMsg.pCont); pMsg->rpcMsg.pCont = NULL; taosFreeQitem(pMsg); @@ -397,37 +397,37 @@ void mndProcessMsg(SMnodeMsg *pMsg) { void *ahandle = pMsg->rpcMsg.ahandle; bool isReq = (msgType & 1U); - mTrace("msg:%p, app:%p type:%s will be processed", pMsg, ahandle, TMSG_INFO(msgType)); + mTrace("msg:%p, type:%s will be processed, app:%p", pMsg, TMSG_INFO(msgType), ahandle); if (isReq && !mndIsMaster(pMnode)) { code = TSDB_CODE_APP_NOT_READY; - mDebug("msg:%p, app:%p failed to process since %s", pMsg, ahandle, terrstr()); + mDebug("msg:%p, failed to process since %s, app:%p", pMsg, terrstr(), ahandle); goto PROCESS_RPC_END; } if (isReq && pMsg->rpcMsg.pCont == NULL) { code = TSDB_CODE_MND_INVALID_MSG_LEN; - mError("msg:%p, app:%p failed to process since %s", pMsg, ahandle, terrstr()); + mError("msg:%p, failed to process since %s, app:%p", pMsg, terrstr(), ahandle); goto PROCESS_RPC_END; } MndMsgFp fp = pMnode->msgFp[TMSG_INDEX(msgType)]; if (fp == NULL) { code = TSDB_CODE_MSG_NOT_PROCESSED; - mError("msg:%p, app:%p failed to process since no handle", pMsg, ahandle); + mError("msg:%p, failed to process since no msg handle, app:%p", pMsg, ahandle); goto PROCESS_RPC_END; } code = (*fp)(pMsg); if (code == TSDB_CODE_MND_ACTION_IN_PROGRESS) { - mTrace("msg:%p, app:%p in progressing", pMsg, ahandle); + mTrace("msg:%p, in progress, app:%p", pMsg, ahandle); return; } else if (code != 0) { code = terrno; - mError("msg:%p, app:%p failed to process since %s", pMsg, ahandle, terrstr()); + mError("msg:%p, failed to process since %s, app:%p", pMsg, terrstr(), ahandle); goto PROCESS_RPC_END; } else { - mTrace("msg:%p, app:%p is processed", pMsg, ahandle); + mTrace("msg:%p, is processed, app:%p", pMsg, ahandle); } PROCESS_RPC_END: diff --git a/source/dnode/mnode/sdb/src/sdb.c b/source/dnode/mnode/sdb/src/sdb.c index 0671434218..ef5bb6f16f 100644 --- a/source/dnode/mnode/sdb/src/sdb.c +++ b/source/dnode/mnode/sdb/src/sdb.c @@ -65,7 +65,7 @@ void sdbCleanup(SSdb *pSdb) { mDebug("start to cleanup sdb"); if (pSdb->curVer != pSdb->lastCommitVer) { - mDebug("write sdb file for curVer:% " PRId64 " and lastCommitVer:%" PRId64, pSdb->curVer, pSdb->lastCommitVer); + mDebug("write sdb file for current ver:%" PRId64 " != last commit ver:%" PRId64, pSdb->curVer, pSdb->lastCommitVer); sdbWriteFile(pSdb); } @@ -138,7 +138,7 @@ int32_t sdbSetTable(SSdb *pSdb, SSdbTable table) { pSdb->maxId[sdbType] = 0; pSdb->hashObjs[sdbType] = hash; taosInitRWLatch(&pSdb->locks[sdbType]); - mDebug("sdb table:%d is initialized", sdbType); + mDebug("sdb table:%s is initialized", sdbTableName(sdbType)); return 0; } diff --git a/source/dnode/mnode/sdb/src/sdbFile.c b/source/dnode/mnode/sdb/src/sdbFile.c index cc36b8ec13..970fdc2061 100644 --- a/source/dnode/mnode/sdb/src/sdbFile.c +++ b/source/dnode/mnode/sdb/src/sdbFile.c @@ -146,6 +146,7 @@ int32_t sdbReadFile(SSdb *pSdb) { char file[PATH_MAX] = {0}; snprintf(file, sizeof(file), "%s%ssdb.data", pSdb->currDir, TD_DIRSEP); + mDebug("start to read file:%s", file); FileFd fd = taosOpenFileRead(file); if (fd <= 0) { diff --git a/source/dnode/mnode/sdb/src/sdbHash.c b/source/dnode/mnode/sdb/src/sdbHash.c index 4b11ec3e76..733075757f 100644 --- a/source/dnode/mnode/sdb/src/sdbHash.c +++ b/source/dnode/mnode/sdb/src/sdbHash.c @@ -57,18 +57,35 @@ const char *sdbTableName(ESdbType type) { } } +static const char *sdbStatusStr(ESdbStatus status) { + switch (status) { + case SDB_STATUS_CREATING: + return "creating"; + case SDB_STATUS_UPDATING: + return "updating"; + case SDB_STATUS_DROPPING: + return "dropping"; + case SDB_STATUS_READY: + return "ready"; + case SDB_STATUS_DROPPED: + return "dropped"; + default: + return "undefine"; + } +} + void sdbPrintOper(SSdb *pSdb, SSdbRow *pRow, const char *oper) { EKeyType keyType = pSdb->keyTypes[pRow->type]; if (keyType == SDB_KEY_BINARY) { - mTrace("%s:%s, refCount:%d oper:%s row:%p", sdbTableName(pRow->type), (char *)pRow->pObj, pRow->refCount, oper, - pRow->pObj); + mTrace("%s:%s, refCount:%d oper:%s row:%p status:%s", sdbTableName(pRow->type), (char *)pRow->pObj, pRow->refCount, + oper, pRow->pObj, sdbStatusStr(pRow->status)); } else if (keyType == SDB_KEY_INT32) { - mTrace("%s:%d, refCount:%d oper:%s row:%p", sdbTableName(pRow->type), *(int32_t *)pRow->pObj, pRow->refCount, oper, - pRow->pObj); + mTrace("%s:%d, refCount:%d oper:%s row:%p status:%s", sdbTableName(pRow->type), *(int32_t *)pRow->pObj, + pRow->refCount, oper, pRow->pObj, sdbStatusStr(pRow->status)); } else if (keyType == SDB_KEY_INT64) { - mTrace("%s:%" PRId64 ", refCount:%d oper:%s row:%p", sdbTableName(pRow->type), *(int64_t *)pRow->pObj, - pRow->refCount, oper, pRow->pObj); + mTrace("%s:%" PRId64 ", refCount:%d oper:%s row:%p status:%s", sdbTableName(pRow->type), *(int64_t *)pRow->pObj, + pRow->refCount, oper, pRow->pObj, sdbStatusStr(pRow->status)); } else { } } @@ -165,6 +182,7 @@ static int32_t sdbUpdateRow(SSdb *pSdb, SHashObj *hash, SSdbRaw *pRaw, SSdbRow * SSdbRow *pOldRow = *ppOldRow; pOldRow->status = pRaw->status; + sdbPrintOper(pSdb, pOldRow, "updateRow"); taosRUnLockLatch(pLock); int32_t code = 0; @@ -193,6 +211,8 @@ static int32_t sdbDeleteRow(SSdb *pSdb, SHashObj *hash, SSdbRaw *pRaw, SSdbRow * SSdbRow *pOldRow = *ppOldRow; pOldRow->status = pRaw->status; + sdbPrintOper(pSdb, pOldRow, "deleteRow"); + taosHashRemove(hash, pOldRow->pObj, keySize); taosWUnLockLatch(pLock);