From 458f0fbc2da1fb1ca031911a975ce34d1f86695b Mon Sep 17 00:00:00 2001 From: ztong Date: Fri, 10 Jan 2020 18:37:46 +0800 Subject: [PATCH] AMP: CLK: regulate CHECK_ log for different policy Change-Id: I04706cfe56ca0c5e2b2357105836350611f5ff97 Reviewed-on: https://sc-debu-git.synaptics.com/gerrit/91998 Reviewed-by: Jenkins Reviewed-by: Zhe Tong Reviewed-by: Yuanfeng Chu Reviewed-by: Xiaomei Shang Reviewed-by: Yanyan Peng --- diff --git a/amp/src/ddl/comp_clk/source/clk_avsync.c b/amp/src/ddl/comp_clk/source/clk_avsync.c index 3de6ada..3230252 100755 --- a/amp/src/ddl/comp_clk/source/clk_avsync.c +++ b/amp/src/ddl/comp_clk/source/clk_avsync.c @@ -61,6 +61,7 @@ #define NUM_BD_QUEUE_OUTPUT_SIZE 4 #define SAMPLE_INFO_SIZE 16 +#define AVS_CHECKER_LOG_BUFFER_SIZE 256 #define AVSE(...) AMPLOG(MODULE_AVS, AMP_LOG_ERROR, __VA_ARGS__) #define AVSH(...) AMPLOG(MODULE_AVS, AMP_LOG_HIGH, __VA_ARGS__) @@ -121,6 +122,167 @@ { 24, 1, 15000}, }; +static void avsync_mgr_log(AVSYNC_MGR *pSyncMgr, SYNC_STREAM *pStream, + AMP_BD_HANDLE hBD, BD_INFO *pBDInfo, + AMP_CLK_AREN_INFO *pAudInfo, AMP_CLK_ACT eAct, + UINT32 uiTime, UINT64 uiSTC, UINT32 uiPolicyDelay) +{ + UINT32 num = 0; + AMP_LOG_LEVEL eLevel = AMP_LOG_INFO; + char log_buffer[AVS_CHECKER_LOG_BUFFER_SIZE] = {0}; + UINT32 writeIndex = 0; + UINT64 uiPTS = 0; + INT64 iPTSDiff = 0; + INT64 iSTCDiff = 0; + INT64 iPTSSTCDiff = 0; + UINT64 uiAOutPTS = 0; + INT64 iAOutPTSDiff = 0; + UINT32 uiBufferedBD = 0; + AMP_BD_HANDLE hBufDesc = NULL; + BOOL fEos = FALSE; + + CLK_ASSERT(eAct < AMP_CLK_ACT_MAX); + CLK_ASSERT(pStream->m_eType < STREAM_TYPE_MAX); + CLK_ASSERT(pSyncMgr->m_eSyncStatus < SYNC_STATUS_MAX); + CLK_ASSERT(hBD != NULL || pBDInfo != NULL); + + if (pStream->m_eType == STREAM_TYPE_VIDEO) { + eLevel = AMP_LOG_USER1; + } else if (pStream->m_eType == STREAM_TYPE_AUDIO) { + eLevel = AMP_LOG_USER2; + } + + if ((eAct == AMP_CLK_DROP) && (pSyncMgr->m_eSyncStatus != SYNC_INIT)) { + eLevel = AMP_LOG_ERROR; + } + + uiBufferedBD = bd_queue_get_fullness(pStream->m_pBdQueue); + + // get PTS, BD, and EOS flag from BDInfo or BD + if (pBDInfo) { + uiPTS = GET_PTS_VAL64(pBDInfo->m_uiPtsStart); + hBufDesc = pBDInfo->m_hBD; + fEos = pBDInfo->m_fEosReached; + } else { + HRESULT ret; + UINT32 uiNumTag, uiTagIdx; + AMP_BDTAG_H *pTag = NULL; + AMP_BDTAG_AVS_PTS *pPTSTag = NULL; + AMP_BDTAG_AUD_FRAME_INFO *pInfoA = NULL; + AMP_BGTAG_FRAME_INFO *pInfoV = NULL; + + hBufDesc = hBD; + + ret = AMPBuf_BDTag_GetNum(hBufDesc, &uiNumTag); + if (ret == SUCCESS) { + for (uiTagIdx = 0; uiTagIdx < uiNumTag; uiTagIdx++) { + ret = AMPBuf_BDTag_GetWithIndex(hBufDesc, uiTagIdx, (VOID **)&pTag); + if (ret == SUCCESS) { + switch (pTag->eType) { + case AMP_BDTAG_SYNC_PTS_META: + pPTSTag = (AMP_BDTAG_AVS_PTS *)pTag; + uiPTS = GET_PTS_VAL64( + GET_FULL_PTS64(pPTSTag->uPtsHigh, + pPTSTag->uPtsLow)); + break; + case AMP_BDTAG_AUD_FRAME_CTRL: + pInfoA = (AMP_BDTAG_AUD_FRAME_INFO *)pTag; + if (pInfoA->uFlag & AMP_MEMINFO_FLAG_EOS_MASK) { + fEos = TRUE; + } + break; + case AMP_BGTAG_FRAME_INFO_META: + pInfoV = (AMP_BGTAG_FRAME_INFO *)pTag; + uiPTS = GET_PTS_VAL64( + GET_FULL_PTS64(pInfoV->uiPtsHigh, + pInfoV->uiPtsLow)); + break; + case AMP_BDTAG_ASSOCIATE_MEM_INFO: + if (((AMP_BDTAG_MEMINFO *)pTag)->uFlag & + AMP_MEMINFO_FLAG_EOS_MASK) { + fEos = TRUE; + } + break; + default: + break; + } + } + } + } + } + + uiSTC = GET_PTS_VAL64(uiSTC); + + iPTSDiff = uiPTS - pStream->m_uiLastCheckPts; + iSTCDiff = uiSTC - pStream->m_uiLastCheckStc; + iPTSSTCDiff = uiPTS - uiSTC; + + // common AVS check log + num = snprintf(log_buffer, sizeof(log_buffer), + "[%d]CHECK_%s[%c][%c]," + "PTS:[0x%09llX][%lld],STC:[0x%09llX][%lld],PTS-STC:%lld," + "BD:%p,BDID:%d,bufferedBDs:%2u," + "CheckTimeDiff:%d,Delay:%5d/%d,Eos:%u,F:%u,RS:%u,", + pSyncMgr->m_pAVClock->m_uiClockID, pStream->m_szName, + pszActChar[eAct], pszSyncChar[pSyncMgr->m_eSyncStatus], + uiPTS, iPTSDiff, uiSTC, iSTCDiff, iPTSSTCDiff, + hBufDesc, hBufDesc->uiBDId, uiBufferedBD, + uiTime - pStream->m_uiLastCheckTime, + uiPolicyDelay, pStream->m_iUsrDelay, fEos, pStream->m_uiFCnt, + pStream->m_fResyncPending); + + if (num >= sizeof(log_buffer)) { + AVSE("lack of log buffer, write: %d, remain:%d/%d \n", num, + sizeof(log_buffer), sizeof(log_buffer)); + goto exit; + } else { + writeIndex += num; + } + + // Audio related log + if (pAudInfo && IS_PTS_VALID64(pAudInfo->m_uiAOutPts)) { + uiAOutPTS = GET_PTS_VAL64(pAudInfo->m_uiAOutPts); + iAOutPTSDiff = uiAOutPTS - pStream->m_uiLastCheckOutPts; + + num = snprintf(log_buffer + writeIndex, sizeof(log_buffer) - writeIndex, + "AoutPTS:0x%08llX:%lld(%2u/%2u/%4u/%4u/%4u/%4u/%4u/%4u/%4u)", + uiAOutPTS, iAOutPTSDiff, + pAudInfo && pAudInfo->m_uiNumComps > 0 ? + pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0, + pAudInfo && pAudInfo->m_uiNumComps > 0 ? + pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0, + pAudInfo && pAudInfo->m_uiNumComps > 1 ? + pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 2 ? + pAudInfo->m_eAudCompInfo[2].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 3 ? + pAudInfo->m_eAudCompInfo[3].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 4 ? + pAudInfo->m_eAudCompInfo[4].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 5 ? + pAudInfo->m_eAudCompInfo[5].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 6 ? + pAudInfo->m_eAudCompInfo[6].m_uiInputFullness : 0, + pAudInfo && pAudInfo->m_uiNumComps > 7 ? + pAudInfo->m_eAudCompInfo[7].m_uiInputFullness : 0); + + if (num >= sizeof(log_buffer) - writeIndex) { + AVSE("lack of log buffer, write: %d, remain:%d/%d \n", num, + sizeof(log_buffer) - writeIndex, sizeof(log_buffer)); + goto exit; + } else { + writeIndex += num; + } + } + + AMPLOG(MODULE_AVS, eLevel, "%s", log_buffer); + +exit: + pStream->m_uiLastCheckStc = uiSTC; + pStream->m_uiLastCheckPts = uiPTS; + pStream->m_uiLastCheckOutPts = uiAOutPTS; + pStream->m_uiLastCheckTime = uiTime; +} BD_INFO *stream_resync_to_bd(SYNC_STREAM *pStream, AMP_BD_HANDLE hBD) { @@ -1073,141 +1235,6 @@ return (uiAPPFullness > uiFullnessThresh ? AMP_CLK_HOLD : AMP_CLK_DISP); } -VOID file_playback_debug(UINT64 uiSTCNow, INT32 iDelay, AMP_CLK_ACT eAct, - AMP_BD_HANDLE hBD, BD_INFO *pBDInfo, - SYNC_STREAM *pStream, AVSYNC_MGR *pSyncMgr, - AMP_CLK_AREN_INFO *pAudInfo) -{ - UINT64 uiPTSNow = 0, uiOutPTSNow = 0; - UINT64 uiPTSDelta, uiSTCDelta, uiOutPTSDelta; - UINT32 uiBufferedBD; - AMP_BD_HANDLE hBufDesc = NULL; - AMP_LOG_LEVEL eLevel = AMP_LOG_INFO; - BOOL fEos = FALSE; - - CLK_ASSERT(eAct < AMP_CLK_ACT_MAX); - CLK_ASSERT(pStream->m_eType < STREAM_TYPE_MAX); - CLK_ASSERT(pSyncMgr->m_eSyncStatus < SYNC_STATUS_MAX); - - if (pStream->m_eType == STREAM_TYPE_VIDEO) { - eLevel = AMP_LOG_USER1; - } else if (pStream->m_eType == STREAM_TYPE_AUDIO) { - eLevel = AMP_LOG_USER2; - } - - if ((eAct == AMP_CLK_DROP) && (pSyncMgr->m_eSyncStatus != SYNC_INIT)) { - eLevel = AMP_LOG_ERROR; - } - - uiBufferedBD = bd_queue_get_fullness(pStream->m_pBdQueue); - - if (pBDInfo) { - uiPTSNow = GET_PTS_VAL64(pBDInfo->m_uiPtsStart); - hBufDesc = pBDInfo->m_hBD; - fEos = pBDInfo->m_fEosReached; - } else { - HRESULT ret; - UINT32 uiNumTag, uiTagIdx; - AMP_BDTAG_H *pTag = NULL; - AMP_BDTAG_AVS_PTS *pPTSTag = NULL; - AMP_BDTAG_AUD_FRAME_INFO *pInfoA = NULL; - AMP_BGTAG_FRAME_INFO *pInfoV = NULL; - - hBufDesc = hBD; - - ret = AMPBuf_BDTag_GetNum(hBufDesc, &uiNumTag); - if (ret == SUCCESS) { - for (uiTagIdx = 0; uiTagIdx < uiNumTag; uiTagIdx++) { - ret = AMPBuf_BDTag_GetWithIndex(hBufDesc, uiTagIdx, (VOID **)&pTag); - if (ret == SUCCESS) { - switch (pTag->eType) { - case AMP_BDTAG_SYNC_PTS_META: - pPTSTag = (AMP_BDTAG_AVS_PTS *)pTag; - uiPTSNow = GET_PTS_VAL64( - GET_FULL_PTS64(pPTSTag->uPtsHigh, - pPTSTag->uPtsLow)); - break; - case AMP_BDTAG_AUD_FRAME_CTRL: - pInfoA = (AMP_BDTAG_AUD_FRAME_INFO *)pTag; - if (pInfoA->uFlag & AMP_MEMINFO_FLAG_EOS_MASK) { - fEos = TRUE; - } - break; - case AMP_BGTAG_FRAME_INFO_META: - pInfoV = (AMP_BGTAG_FRAME_INFO *)pTag; - uiPTSNow = GET_PTS_VAL64( - GET_FULL_PTS64(pInfoV->uiPtsHigh, - pInfoV->uiPtsLow)); - break; - case AMP_BDTAG_ASSOCIATE_MEM_INFO: - if (((AMP_BDTAG_MEMINFO *)pTag)->uFlag & - AMP_MEMINFO_FLAG_EOS_MASK) { - fEos = TRUE; - } - break; - default: - break; - } - } - } - } - } - - if (pAudInfo && IS_PTS_VALID64(pAudInfo->m_uiAOutPts)) { - uiOutPTSNow = GET_PTS_VAL64(pAudInfo->m_uiAOutPts); - } - - uiPTSDelta = uiPTSNow - pStream->m_uiLastCheckPts; - uiSTCDelta = uiSTCNow - pStream->m_uiLastCheckStc; - uiOutPTSDelta = uiOutPTSNow - pStream->m_uiLastCheckOutPts; - - AMPLOG(MODULE_AVS, eLevel, - "[%d]CHECK_%s[%c][%c] PTS:%9llX(%5d)[%6d] " - "STC:%9llX(%5d)[%6d] " - "OUT:%9llX(%5d)[%6d] " - "BD:%p(%x) " - "R:%2u(%2u/%2u/%4u/%4u/%4u/%4u/%4u/%4u/%4u) " - "D:%5d/%d E:%u F:%u, RS:%u", - pSyncMgr->m_pAVClock->m_uiClockID, pStream->m_szName, - pszActChar[eAct], pszSyncChar[pSyncMgr->m_eSyncStatus], - uiPTSNow, (INT32)uiPTSDelta, - pSyncMgr->m_pNewV && pSyncMgr->m_pNewA ? - (INT32)(GET_PTS_VAL64(pSyncMgr->m_pNewV->m_uiPTS) - - GET_PTS_VAL64(pSyncMgr->m_pNewA->m_uiPTS)) : 0, - uiSTCNow, (INT32)uiSTCDelta, - (INT32)(uiPTSNow - uiSTCNow), - uiOutPTSNow, (INT32)uiOutPTSDelta, - (INT32)(uiSTCNow - uiOutPTSNow), - hBufDesc, hBufDesc->uiBDId, - uiBufferedBD, - pAudInfo && pAudInfo->m_uiNumComps > 0 ? - pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0, - pAudInfo && pAudInfo->m_uiNumComps > 0 ? - pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0, - pAudInfo && pAudInfo->m_uiNumComps > 1 ? - pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 2 ? - pAudInfo->m_eAudCompInfo[2].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 3 ? - pAudInfo->m_eAudCompInfo[3].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 4 ? - pAudInfo->m_eAudCompInfo[4].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 5 ? - pAudInfo->m_eAudCompInfo[5].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 6 ? - pAudInfo->m_eAudCompInfo[6].m_uiInputFullness : 0, - pAudInfo && pAudInfo->m_uiNumComps > 7 ? - pAudInfo->m_eAudCompInfo[7].m_uiInputFullness : 0, - iDelay, pStream->m_iUsrDelay, fEos, pStream->m_uiFCnt, - pStream->m_fResyncPending); - - pStream->m_uiLastCheckStc = uiSTCNow; - pStream->m_uiLastCheckPts = uiPTSNow; - pStream->m_uiLastCheckOutPts = uiOutPTSNow; - - return; -} - VOID file_playback_check_bd_queue(SYNC_STREAM *pStream, UINT64 *pNextPTS, UINT32 *pBDNr, BOOL *pDisc) { @@ -1545,6 +1572,7 @@ UINT64 uiSTCNow, uiSTCAdj, uiPTSNow; UINT32 uiRateDen, uiBufferedBD, uiThresholdL, uiThresholdR; INT32 iRateNum, iDelay = 0; + UINT32 uiTime = 0; BD_INFO *pBDInfo = NULL; AMP_CLK_ACT eAct = AMP_CLK_HOLD; @@ -1553,6 +1581,7 @@ CLK_ASSERT(pSyncMgr->m_pStreams[pStream->m_uiIndex] == pStream); CLK_ASSERT(pStream->m_pBdQueue); + uiTime = AMP_GetCurrentTimeMS(); uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, TRUE)); avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen); @@ -1716,9 +1745,8 @@ } Exit: - file_playback_debug(uiSTCNow, iDelay, eAct, - hBD, pBDInfo, - pStream, pSyncMgr, NULL); + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime, + uiSTCNow, iDelay); if (eAct != AMP_CLK_HOLD) { if (pBDInfo) { @@ -1761,6 +1789,7 @@ UINT64 uiSTCNow, uiSTCAdj, uiPTSNow; UINT32 uiRateDen, uiBufferedBD, uiThresholdL, uiThresholdR; INT32 iRateNum = 0; + UINT32 uiTime = 0; BD_INFO *pBDInfo = NULL; AMP_CLK_AREN_INFO *pAudInfo = NULL; AMP_CLK_ACT eAct = AMP_CLK_HOLD; @@ -1772,6 +1801,7 @@ pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData; + uiTime = AMP_GetCurrentTimeMS(); uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, FALSE)); avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen); @@ -1942,9 +1972,8 @@ } Exit: - file_playback_debug(uiSTCNow, pStream->m_iDelay, eAct, - hBD, pBDInfo, - pStream, pSyncMgr, pAudInfo); + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime, + uiSTCNow, pStream->m_iDelay); if (eAct != AMP_CLK_HOLD) { if (pBDInfo) { @@ -2114,6 +2143,7 @@ UINT64 uiSTCNow, uiSTCAdj, uiPTSNow; UINT32 uiBufferedSamples, uiRateDen, uiThresholdL, uiThresholdR; INT32 iRateNum = 0, iDelay = 0; + UINT32 uiTime = 0; BD_INFO *pBDInfo = NULL; AMP_CLK_ACT eAct = AMP_CLK_HOLD; BOOL fPullDown; @@ -2123,6 +2153,7 @@ CLK_ASSERT(pSyncMgr->m_pStreams[pStream->m_uiIndex] == pStream); CLK_ASSERT(pStream->m_pBdQueue); + uiTime = AMP_GetCurrentTimeMS(); uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, TRUE)); avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen); @@ -2190,9 +2221,8 @@ } Exit: - file_playback_debug(uiSTCNow, iDelay, eAct, - hBD, pBDInfo, - pStream, pSyncMgr, NULL); + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime, + uiSTCNow, iDelay); if (eAct != AMP_CLK_HOLD) { if (pBDInfo) { @@ -2220,6 +2250,7 @@ UINT64 uiSTCNow, uiSTCAdj, uiPTSNow; UINT32 uiRateDen, uiBufferedSamples, uiThresholdL, uiThresholdR; INT32 iRateNum = 0; + UINT32 uiTime = 0; BD_INFO *pBDInfo = NULL; AMP_CLK_AREN_INFO *pAudInfo = NULL; AMP_CLK_ACT eAct = AMP_CLK_HOLD; @@ -2230,6 +2261,7 @@ CLK_ASSERT(pRndInfo); pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData; + uiTime = AMP_GetCurrentTimeMS(); uiSTCNow = GET_PTS_VAL64(avclock_get_stc64(pSyncMgr->m_pAVClock, FALSE)); avclock_get_rate(pSyncMgr->m_pAVClock, &iRateNum, &uiRateDen); @@ -2319,9 +2351,8 @@ } Exit: - file_playback_debug(uiSTCNow, pStream->m_iDelay, eAct, - hBD, pBDInfo, - pStream, pSyncMgr, pAudInfo); + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime, + uiSTCNow, pStream->m_iDelay); if (eAct != AMP_CLK_HOLD) { if (pBDInfo) { @@ -2779,24 +2810,8 @@ } _Exit: - - AVSU1("[AVS][%d]CHECK_%s([%c][%c%c%c%c] V:0x%08x(%d), M:0x%08x(%d)[%d], " - "AM:0x%08x, AM-V:%d)\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eActP], pszActChar[eActN], pszActChar[eActL], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0, - (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc), - uiTime - pStream->m_uiLastCheckTime, - (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0); - - //eAct = AMP_CLK_DISP; - - pStream->m_uiLastCheckStc = uiOrigSTC; - pStream->m_uiLastCheckTime = uiTime; - if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime, + uiOrigSTC, uiDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration; @@ -2950,26 +2965,8 @@ } } - - AVSU2("[AVS][%d]CHECK_%s([%d][%c][%c%c%c%c] PTS:0x%08x, STC:0x%08x(%d)," - " D:%d, O:0x%08x(%d), AM:0x%08x(%d))\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - uiTime - pStream->m_uiLastCheckTime, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eActP], pszActChar[eActN], pszActChar[eActL], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc), - pStream->m_iDelay, (UINT32)pStream->m_uiOutPTS, - pBDInfo ? (INT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) - - GET_PTS_VAL64(pStream->m_uiOutPTS)) / 90 : 0, - uiSTC + pStream->m_iDelay, - pBDInfo ? (INT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) - - GET_PTS_VAL64(uiSTC + pStream->m_iDelay)) / 90 : 0); - - //eAct = AMP_CLK_DISP; - pStream->m_uiLastCheckStc = uiSTC; - pStream->m_uiLastCheckTime = uiTime; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime, + uiSTC, pStream->m_iDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration; @@ -3799,24 +3796,8 @@ } _Exit: - //eAct = AMP_CLK_DISP; - AVSU1("[AVS][%d]CHECK_%s([%c][%c%c%c%c] V:0x%08x(%d), M:0x%08x(%d)[%d], " - "AM:0x%08x, AM-V:%d)%s, usrdelay %d ms, range %d\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eActP], pszActChar[eActN], pszActChar[eActL], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0, - (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc), - uiTime - pStream->m_uiLastCheckTime, - (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0, - (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "", - pStream->m_iUsrDelay/90, uiRange); - - pStream->m_uiLastCheckStc = uiOrigSTC; - pStream->m_uiLastCheckTime = uiTime; - if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime, + uiOrigSTC, uiDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration; @@ -4012,30 +3993,8 @@ } } - //eAct = AMP_CLK_DISP; - AVSU2("[AVS][%d]CHECK_%s([%c][%c%c%c%c] A:0x%08x(%d), M:0x%08x(%d)[%d], " - "O:0x%08x, A:[%d, %d][%d]%s)\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eActP], pszActChar[eActN], pszActChar[eActL], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - pBDInfo ? (UINT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) - - GET_PTS_VAL64(pStream->m_uiLastCheckPts)) : 0, - (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc), - uiTime - pStream->m_uiLastCheckTime, - pAudInfo ? (UINT32)pAudInfo->m_uiAOutPts : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 0) ? - pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 0) ? - pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 1) ? - pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0, - (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : ""); - - pStream->m_uiLastCheckStc = uiSTC; - pStream->m_uiLastCheckTime = uiTime; - pStream->m_uiLastCheckPts = pBDInfo ? pBDInfo->m_uiPtsStart : 0; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime, + uiSTC, pStream->m_iDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration; @@ -4439,23 +4398,8 @@ eAct = check_pts_range(pBDInfo->m_uiPtsStart, uiSTC, uiRangeL, uiRangeR, pSyncMgr->m_fBackward); _Exit: - //eAct = AMP_CLK_DISP; - AVSU1("[AVS][%d]CHECK_%s([%c][%c] V:0x%08x(%d), M:0x%08x(%d)[%d], " - "AM:0x%08x, AM-V:%d)%s, usrdelay %d ms\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - pBDInfo ? (INT32)(pBDInfo->m_uiPtsStart - pStream->m_uiLastCheckPts): 0, - (UINT32)uiOrigSTC, (UINT32)(uiOrigSTC - pStream->m_uiLastCheckStc), - uiTime - pStream->m_uiLastCheckTime, - (UINT32)uiSTC, pBDInfo ? (UINT32)PTS64_DIFF_WRAP(uiSTC, pBDInfo->m_uiPtsStart) : 0, - (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : "", - pStream->m_iUsrDelay/90); - - pStream->m_uiLastCheckStc = uiOrigSTC; - pStream->m_uiLastCheckTime = uiTime; - if (pBDInfo) pStream->m_uiLastCheckPts = pBDInfo->m_uiPtsStart; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, NULL, eAct, uiTime, + uiOrigSTC, uiDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration; @@ -4485,7 +4429,7 @@ AMP_CLK_ACT *pAction, AMP_CLK_DROP_INFO *pDropInfo) { BD_INFO *pBDInfo = 0; - AMP_CLK_ACT eActP, eActN, eActL, eAct; + AMP_CLK_ACT eAct; UINT64 uiSTC = 0; UINT32 uiTime = 0, uiRateDen; INT32 iRateNum; @@ -4500,7 +4444,6 @@ pAudInfo = (AMP_CLK_AREN_INFO *)pRndInfo->m_pPrivData; eAct = AMP_CLK_DISP; - eActP = eActN = eActL = AMP_CLK_ACT_MAX; pBDInfo = stream_resync_to_bd(pStream, hBD); if (pSyncMgr->m_eSyncStatus == SYNC_DISABLED) { @@ -4539,31 +4482,8 @@ } _Exit: - - //eAct = AMP_CLK_DISP; - AVSU2("[AVS][%d]CHECK_%s([%c][%c%c%c%c] A:0x%08x(%d), M:0x%08x(%d)[%d], " - "O:0x%08x, A:[%d, %d][%d]%s)\n", - pSyncMgr->m_pAVClock->m_uiClockID, - pStream->m_szName, - pszSyncChar[pSyncMgr->m_eSyncStatus], - pszActChar[eActP], pszActChar[eActN], pszActChar[eActL], - pszActChar[eAct], pBDInfo ? (UINT32)pBDInfo->m_uiPtsStart : 0, - pBDInfo ? (UINT32)(GET_PTS_VAL64(pBDInfo->m_uiPtsStart) - - GET_PTS_VAL64(pStream->m_uiLastCheckPts)) : 0, - (UINT32)uiSTC, (UINT32)(uiSTC - pStream->m_uiLastCheckStc), - uiTime - pStream->m_uiLastCheckTime, - pAudInfo ? (UINT32)pAudInfo->m_uiAOutPts : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 0) ? - pAudInfo->m_eAudCompInfo[0].m_uiInputBD : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 0) ? - pAudInfo->m_eAudCompInfo[0].m_uiOutputBD : 0, - pAudInfo && (pAudInfo->m_uiNumComps > 1) ? - pAudInfo->m_eAudCompInfo[1].m_uiInputFullness : 0, - (pBDInfo && pBDInfo->m_fEosReached) ? "--EOS" : ""); - - pStream->m_uiLastCheckStc = uiSTC; - pStream->m_uiLastCheckTime = uiTime; - pStream->m_uiLastCheckPts = pBDInfo ? pBDInfo->m_uiPtsStart : 0; + avsync_mgr_log(pSyncMgr, pStream, hBD, pBDInfo, pAudInfo, eAct, uiTime, + uiSTC, pStream->m_iDelay); if ((AMP_CLK_HOLD != eAct) && pBDInfo) { pStream->m_uiBuffedTime -= pBDInfo->m_uiDuration;