Index: /trunk/src/VBox/Devices/Audio/DrvHostAudioDSound.cpp =================================================================== --- /trunk/src/VBox/Devices/Audio/DrvHostAudioDSound.cpp (revision 88563) +++ /trunk/src/VBox/Devices/Audio/DrvHostAudioDSound.cpp (revision 88564) @@ -117,6 +117,4 @@ /** Size (in bytes) of the DirectSound buffer. */ DWORD cbBufSize; - /** The stream's critical section for synchronizing access. */ - RTCRITSECT CritSect; union { @@ -157,17 +155,15 @@ * to the DirectSound buffer was. */ uint32_t cbLastTransferred; - /** Timestamp (in ms) of the last transfer from the internal buffer - * to the DirectSound buffer. */ - uint64_t tsLastTransferredMs; - /** Number of buffer underruns happened. Used for logging. */ - uint8_t cUnderruns; } Out; }; -#ifdef LOG_ENABLED - struct - { - uint64_t tsLastTransferredMs; - } Dbg; -#endif + /** Timestamp (in ms) of the last transfer from the internal buffer to/from the + * DirectSound buffer. */ + uint64_t msLastTransfer; + /** The stream's critical section for synchronizing access. */ + RTCRITSECT CritSect; + /** Used for formatting the current DSound status. */ + char szStatus[127]; + /** Fixed zero terminator. */ + char const chStateZero; } DSOUNDSTREAM, *PDSOUNDSTREAM; @@ -232,4 +228,136 @@ static void dsoundUpdateStatusInternal(PDRVHOSTDSOUND pThis); + + +#if defined(LOG_ENABLED) // || defined(RTLOG_REL_ENABLED) +/** + * Gets the stream status as a string for logging purposes. + * + * @returns Status string (pStreamDS->szStatus). + * @param pStreamDS The stream to get the status for. + */ +static const char *drvHostDSoundStreamStatusString(PDSOUNDSTREAM pStreamDS) +{ + /* + * Out internal stream status first. + */ + size_t off; + if (pStreamDS->fEnabled) + { + memcpy(pStreamDS->szStatus, RT_STR_TUPLE("ENABLED ")); + off = sizeof("ENABLED ") - 1; + } + else + { + memcpy(pStreamDS->szStatus, RT_STR_TUPLE("DISABLED")); + off = sizeof("DISABLED") - 1; + } + + /* + * Direction specific stuff, returning with a status DWORD and string mappings for it. + */ + typedef struct DRVHOSTDSOUNDSFLAGS2STR + { + const char *pszMnemonic; + uint32_t cchMnemonic; + uint32_t fFlag; + } DRVHOSTDSOUNDSFLAGS2STR; + static const DRVHOSTDSOUNDSFLAGS2STR s_aCaptureFlags[] = + { + { RT_STR_TUPLE(" CAPTURING"), DSCBSTATUS_CAPTURING }, + { RT_STR_TUPLE(" LOOPING"), DSCBSTATUS_LOOPING }, + }; + static const DRVHOSTDSOUNDSFLAGS2STR s_aPlaybackFlags[] = + { + { RT_STR_TUPLE(" PLAYING"), DSBSTATUS_PLAYING }, + { RT_STR_TUPLE(" BUFFERLOST"), DSBSTATUS_BUFFERLOST }, + { RT_STR_TUPLE(" LOOPING"), DSBSTATUS_LOOPING }, + { RT_STR_TUPLE(" LOCHARDWARE"), DSBSTATUS_LOCHARDWARE }, + { RT_STR_TUPLE(" LOCSOFTWARE"), DSBSTATUS_LOCSOFTWARE }, + { RT_STR_TUPLE(" TERMINATED"), DSBSTATUS_TERMINATED }, + }; + DRVHOSTDSOUNDSFLAGS2STR const *paMappings = NULL; + size_t cMappings = 0; + DWORD fStatus = 0; + if (pStreamDS->Cfg.enmDir == PDMAUDIODIR_IN) + { + if (pStreamDS->In.pDSCB) + { + HRESULT hrc = pStreamDS->In.pDSCB->GetStatus(&fStatus); + if (SUCCEEDED(hrc)) + { + paMappings = s_aCaptureFlags; + cMappings = RT_ELEMENTS(s_aCaptureFlags); + } + else + RTStrPrintf(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, "GetStatus->%Rhrc", hrc); + } + else + RTStrCopy(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, "NO-DSCB"); + } + else if (pStreamDS->Cfg.enmDir == PDMAUDIODIR_OUT) + { + if (pStreamDS->Out.fDrain) + { + memcpy(&pStreamDS->szStatus[off], RT_STR_TUPLE(" DRAINING")); + off += sizeof(" DRAINING") - 1; + } + + if (pStreamDS->Out.fFirstTransfer) + { + memcpy(&pStreamDS->szStatus[off], RT_STR_TUPLE(" NOXFER")); + off += sizeof(" NOXFER") - 1; + } + + if (pStreamDS->Out.pDSB) + { + HRESULT hrc = pStreamDS->Out.pDSB->GetStatus(&fStatus); + if (SUCCEEDED(hrc)) + { + paMappings = s_aPlaybackFlags; + cMappings = RT_ELEMENTS(s_aPlaybackFlags); + } + else + RTStrPrintf(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, "GetStatus->%Rhrc", hrc); + } + else + RTStrCopy(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, "NO-DSB"); + } + else + RTStrCopy(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, "BAD-DIR"); + + /* Format flags. */ + if (paMappings) + { + if (fStatus == 0) + RTStrCopy(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, " 0"); + else + { + for (size_t i = 0; i < cMappings; i++) + if (fStatus & paMappings[i].fFlag) + { + memcpy(&pStreamDS->szStatus[off], paMappings[i].pszMnemonic, paMappings[i].cchMnemonic); + off += paMappings[i].cchMnemonic; + + fStatus &= ~paMappings[i].fFlag; + if (!fStatus) + break; + } + if (fStatus != 0) + off += RTStrPrintf(&pStreamDS->szStatus[off], sizeof(pStreamDS->szStatus) - off, " %#x", fStatus); + } + } + + /* + * Finally, terminate the string. By postponing it this long, it won't be + * a big deal if two threads go thru here at the same time as long as the + * status is the same. + */ + Assert(off < sizeof(pStreamDS->szStatus)); + pStreamDS->szStatus[off] = '\0'; + + return pStreamDS->szStatus; +} +#endif /* LOG_ENABLED || RTLOG_REL_ENABLED */ @@ -1161,9 +1289,10 @@ /* Reset the state: */ + pStreamDS->msLastTransfer = 0; /** @todo r=bird: We set the read position to zero here, but shouldn't we query it * from the buffer instead given that there isn't any interface for repositioning * to the start of the buffer as with playback buffers? */ - pStreamDS->In.offReadPos = 0; - pStreamDS->In.cOverruns = 0; + pStreamDS->In.offReadPos = 0; + pStreamDS->In.cOverruns = 0; /* Clear the buffer content: */ @@ -1205,9 +1334,8 @@ /* Reset the internal state: */ + pStreamDS->msLastTransfer = 0; pStreamDS->Out.fFirstTransfer = true; pStreamDS->Out.fDrain = false; - pStreamDS->Out.cUnderruns = 0; pStreamDS->Out.cbLastTransferred = 0; - pStreamDS->Out.tsLastTransferredMs = 0; pStreamDS->Out.cbTransferred = 0; pStreamDS->Out.cbWritten = 0; @@ -1249,8 +1377,4 @@ } } - -#ifdef LOG_ENABLED - pStreamDS->Dbg.tsLastTransferredMs = 0; -#endif } @@ -1587,4 +1711,5 @@ PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; AssertPtrReturn(pStreamDS, VERR_INVALID_POINTER); + LogFlowFunc(("Stream '%s' {%s}\n", pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); if (pStreamDS->Cfg.enmDir == PDMAUDIODIR_IN) @@ -1712,5 +1837,5 @@ PDRVHOSTDSOUND pThis = RT_FROM_MEMBER(pInterface, DRVHOSTDSOUND, IHostAudio); PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; - LogFlowFunc(("fEnabled=%d '%s'\n", pStreamDS->fEnabled, pStreamDS->Cfg.szName)); + LogFlowFunc(("Stream '%s' {%s}\n", pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); /* @@ -1775,5 +1900,7 @@ PDRVHOSTDSOUND pThis = RT_FROM_MEMBER(pInterface, DRVHOSTDSOUND, IHostAudio); PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; - LogFlowFunc(("fEnabled=%d '%s'\n", pStreamDS->fEnabled, pStreamDS->Cfg.szName)); + LogFlowFunc(("cMsLastTransfer=%RI64 ms, stream '%s' {%s} \n", + pStreamDS->msLastTransfer ? RTTimeMilliTS() - pStreamDS->msLastTransfer : -1, + pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS) )); /* @@ -1820,5 +1947,5 @@ } - LogFlowFunc(("returns %Rrc\n", rc)); + LogFlowFunc(("returns %Rrc {%s}\n", rc, drvHostDSoundStreamStatusString(pStreamDS))); return rc; } @@ -1835,5 +1962,7 @@ PDRVHOSTDSOUND pThis = RT_FROM_MEMBER(pInterface, DRVHOSTDSOUND, IHostAudio); PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; - LogFlowFunc(("fEnabled=%d '%s'\n", pStreamDS->fEnabled, pStreamDS->Cfg.szName)); + LogFlowFunc(("cMsLastTransfer=%RI64 ms, stream '%s' {%s} \n", + pStreamDS->msLastTransfer ? RTTimeMilliTS() - pStreamDS->msLastTransfer : -1, + pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS) )); /* @@ -1873,5 +2002,5 @@ } - LogFlowFunc(("returns %Rrc\n", rc)); + LogFlowFunc(("returns %Rrc {%s}\n", rc, drvHostDSoundStreamStatusString(pStreamDS))); return rc; } @@ -1918,5 +2047,5 @@ PDRVHOSTDSOUND pThis = RT_FROM_MEMBER(pInterface, DRVHOSTDSOUND, IHostAudio); PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; - LogFlowFunc(("fEnabled=%d '%s'\n", pStreamDS->fEnabled, pStreamDS->Cfg.szName)); + LogFlowFunc(("Stream '%s' {%s}\n", pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); /* @@ -1934,5 +2063,5 @@ } - LogFlowFunc(("returns %Rrc\n", rc)); + LogFlowFunc(("returns %Rrc {%s}\n", rc, drvHostDSoundStreamStatusString(pStreamDS))); return rc; } @@ -1947,5 +2076,7 @@ PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; AssertReturn(pStreamDS->Cfg.enmDir == PDMAUDIODIR_OUT, VERR_INVALID_PARAMETER); - LogFlowFunc(("fEnabled=%d fDrain=%d '%s'\n", pStreamDS->fEnabled, pStreamDS->Out.fDrain, pStreamDS->Cfg.szName)); + LogFlowFunc(("cMsLastTransfer=%RI64 ms, stream '%s' {%s} \n", + pStreamDS->msLastTransfer ? RTTimeMilliTS() - pStreamDS->msLastTransfer : -1, + pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS) )); /* @@ -1981,5 +2112,5 @@ } } - LogFlowFunc(("returns %Rrc\n", rc)); + LogFlowFunc(("returns %Rrc {%s}\n", rc, drvHostDSoundStreamStatusString(pStreamDS))); return rc; } @@ -2068,9 +2199,5 @@ LPDIRECTSOUNDBUFFER8 pDSB = pStreamDS->Out.pDSB; - if (!pDSB) - { - AssertPtr(pDSB); - return VERR_INVALID_POINTER; - } + AssertPtrReturn(pDSB, VERR_INVALID_POINTER); HRESULT hr = S_OK; @@ -2141,4 +2268,5 @@ PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; AssertPtrReturn(pStreamDS, 0); + LogFlowFunc(("Stream '%s' {%s}\n", pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); DWORD cbFree = 0; @@ -2160,4 +2288,5 @@ PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; AssertPtrReturn(pStreamDS, 0); + LogFlowFunc(("Stream '%s' {%s}\n", pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); if (pStreamDS->Cfg.enmDir == PDMAUDIODIR_OUT) @@ -2188,13 +2317,12 @@ { RT_NOREF(pInterface); - AssertPtrReturn(pStream, PDMAUDIOSTREAMSTS_FLAGS_NONE); - PDSOUNDSTREAM pStreamDS = (PDSOUNDSTREAM)pStream; + AssertPtrReturn(pStreamDS, PDMAUDIOSTREAMSTS_FLAGS_NONE); PDMAUDIOSTREAMSTS fStrmStatus = PDMAUDIOSTREAMSTS_FLAGS_INITIALIZED; - if (pStreamDS->fEnabled) fStrmStatus |= PDMAUDIOSTREAMSTS_FLAGS_ENABLED; + LogFlowFunc(("returns %#x for '%s' {%s}\n", fStrmStatus, pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS))); return fStrmStatus; } @@ -2218,7 +2346,8 @@ else { - Log2Func(("Stream disabled, skipping\n")); + Log2Func(("Skipping disabled stream {%s}\n", drvHostDSoundStreamStatusString(pStreamDS))); return VINF_SUCCESS; } + Log4Func(("cbBuf=%#x stream '%s' {%s}\n", cbBuf, pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS) )); /** @todo Any condition under which we should call dsoundUpdateStatusInternal(pThis) here? @@ -2242,6 +2371,6 @@ uint32_t const cbToWrite = RT_MIN(cbWritable, cbBuf); - Log3Func(("offPlay=%#x offWritePos=%#x -> cbWritable=%#x cbToWrite=%#x%s%s\n", offPlayCursor, pStreamDS->Out.offWritePos, - cbWritable, cbToWrite, pStreamDS->Out.fFirstTransfer ? " first" : "", pStreamDS->Out.fDrain ? " drain" : "")); + Log3Func(("offPlay=%#x offWritePos=%#x -> cbWritable=%#x cbToWrite=%#x {%s}\n", offPlayCursor, pStreamDS->Out.offWritePos, + cbWritable, cbToWrite, drvHostDSoundStreamStatusString(pStreamDS) )); /* @@ -2301,9 +2430,10 @@ if (cbWritten) { - uint64_t const msPrev = pStreamDS->Out.tsLastTransferredMs; - pStreamDS->Out.cbLastTransferred = cbWritten; - pStreamDS->Out.tsLastTransferredMs = RTTimeMilliTS(); - LogFlowFunc(("cbLastTransferred=%RU32, tsLastTransferredMs=%RU64 cMsDelta=%RU64\n", - cbWritten, pStreamDS->Out.tsLastTransferredMs, msPrev ? pStreamDS->Out.tsLastTransferredMs - msPrev : 0)); + uint64_t const msPrev = pStreamDS->msLastTransfer; + pStreamDS->Out.cbLastTransferred = cbWritten; + pStreamDS->msLastTransfer = RTTimeMilliTS(); + LogFlowFunc(("cbLastTransferred=%RU32, msLastTransfer=%RU64 msNow=%RU64 cMsDelta=%RU64 {%s}\n", + cbWritten, msPrev, pStreamDS->msLastTransfer, msPrev ? pStreamDS->msLastTransfer - msPrev : 0, + drvHostDSoundStreamStatusString(pStreamDS) )); } return VINF_SUCCESS; @@ -2333,4 +2463,5 @@ } #endif + Log4Func(("cbBuf=%#x stream '%s' {%s}\n", cbBuf, pStreamDS->Cfg.szName, drvHostDSoundStreamStatusString(pStreamDS) )); /* @@ -2367,6 +2498,6 @@ uint32_t const cbToRead = RT_MIN(cbReadable, cbBuf); - Log3Func(("offCapture=%#x offRead=%#x/%#x -> cbWritable=%#x cbToWrite=%#x\n", - offCaptureCursor, offReadCursor, pStreamDS->In.offReadPos, cbReadable, cbToRead)); + Log3Func(("offCapture=%#x offRead=%#x/%#x -> cbWritable=%#x cbToWrite=%#x {%s}\n", offCaptureCursor, offReadCursor, + pStreamDS->In.offReadPos, cbReadable, cbToRead, drvHostDSoundStreamStatusString(pStreamDS))); /* @@ -2407,6 +2538,13 @@ * Done. */ - if (pcbRead) - *pcbRead = cbRead; + *pcbRead = cbRead; + if (cbRead) + { + uint64_t const msPrev = pStreamDS->msLastTransfer; + pStreamDS->msLastTransfer = RTTimeMilliTS(); + LogFlowFunc(("cbRead=%RU32, msLastTransfer=%RU64 msNow=%RU64 cMsDelta=%RU64 {%s}\n", + cbRead, msPrev, pStreamDS->msLastTransfer, msPrev ? pStreamDS->msLastTransfer - msPrev : 0, + drvHostDSoundStreamStatusString(pStreamDS) )); + } #ifdef VBOX_AUDIO_DEBUG_DUMP_PCM_DATA