Changeset 91186 in vbox for trunk/src/VBox/ValidationKit/utils/audio/vkatCommon.cpp

Timestamp:

Sep 9, 2021 6:54:31 PM (3 years ago)

Author:

vboxsync

Message:

Audio/Validation Kit: Some more diagnostics to find out why some testbox guests refuse to play any test tones. ​bugref:10008

File:

• trunk/src/VBox/ValidationKit/utils/audio/vkatCommon.cpp (modified) (6 diffs)

trunk/src/VBox/ValidationKit/utils/audio/vkatCommon.cpp

@@ -309 +309 @@
             if (cbCanWrite)
             {
+                if (g_uVerbosity)
+                    RTTestPrintf(g_hTest, RTTESTLVL_ALWAYS, "Stream is writable with %RU32ms (%RU32 bytes)\n",
+                                 PDMAudioPropsBytesToMilli(pMix->pProps, cbCanWrite), cbCanWrite);
+
                 uint32_t const cbToGenerate = RT_MIN(RT_MIN(cbToPlayTotal - cbPlayedTotal, sizeof(abBuf)), cbCanWrite);
                 uint32_t       cbToPlay;
@@ -341 +345 @@
             else if (AudioTestMixStreamIsOkay(&pStream->Mix))
             {
+                RTMSINTERVAL const msSleep = RT_MIN(RT_MAX(1, pStream->Cfg.Device.cMsSchedulingHint), 256);
+
                 if (!nsLastMsgCantWrite || nsNow - nsLastMsgCantWrite > RT_NS_10SEC) /* Don't spam the output too much. */
                 {
-                    RTTestPrintf(g_hTest, RTTESTLVL_ALWAYS, "Waiting for stream to be writable again ...\n");
+                    RTTestPrintf(g_hTest, RTTESTLVL_ALWAYS, "Waiting %RU32ms for stream to be writable again ...\n", msSleep);
                     nsLastMsgCantWrite = nsNow;
                 }
 
-                RTThreadSleep(RT_MIN(RT_MAX(1, pStream->Cfg.Device.cMsSchedulingHint), 256));
+                RTThreadSleep(msSleep);
             }
             else
@@ -359 +365 @@
             if (cNsElapsed > nsTimeout)
             {
-                RTTestFailed(g_hTest, "Playback took too long (runng %RU64 vs. timeout %RU64), aborting\n", cNsElapsed, nsTimeout);
+                RTTestFailed(g_hTest, "Playback took too long (running %RU64 vs. timeout %RU64), aborting\n", cNsElapsed, nsTimeout);
                 rc = VERR_TIMEOUT;
             }
@@ -433 +439 @@
         uint32_t const  cbSamplesAligned = PDMAudioPropsFloorBytesToFrame(pMix->pProps, sizeof(abSamples));
         uint64_t        cbRecTotal  = 0;
+
+        uint64_t const  nsStarted         = RTTimeNanoTS();
+
+        uint64_t        nsTimeout         = RT_MS_5MIN_64 * RT_NS_1MS;
+        uint64_t        nsLastMsgCantRead = 0; /* Timestamp (in ns) when the last message of an unreadable stream was shown. */
+
         while (!g_fTerminate && cbRecTotal < cbToRecTotal)
         {
+            uint64_t const nsNow = RTTimeNanoTS();
+
             /*
              * Anything we can read?
@@ -441 +455 @@
             if (cbCanRead)
             {
+                if (g_uVerbosity)
+                    RTTestPrintf(g_hTest, RTTESTLVL_ALWAYS, "Stream is readable with %RU32ms (%RU32 bytes)\n",
+                                 PDMAudioPropsBytesToMilli(pMix->pProps, cbCanRead), cbCanRead);
+
                 uint32_t const cbToRead   = RT_MIN(cbCanRead, cbSamplesAligned);
                 uint32_t       cbRecorded = 0;
@@ -459 +477 @@
             }
             else if (AudioTestMixStreamIsOkay(pMix))
-                RTThreadSleep(RT_MIN(RT_MAX(1, pTstEnv->cMsSchedulingHint), 256));
+            {
+                RTMSINTERVAL const msSleep = RT_MIN(RT_MAX(1, pStream->Cfg.Device.cMsSchedulingHint), 256);
+
+                if (!nsLastMsgCantRead || nsNow - nsLastMsgCantRead > RT_NS_10SEC) /* Don't spam the output too much. */
+                {
+                    RTTestPrintf(g_hTest, RTTESTLVL_ALWAYS, "Waiting %RU32ms for stream to be readable again ...\n", msSleep);
+                    nsLastMsgCantRead = nsNow;
+                }
+
+                RTThreadSleep(msSleep);
+            }
+
+            /* Fail-safe in case something screwed up while playing back. */
+            uint64_t const cNsElapsed = nsNow - nsStarted;
+            if (cNsElapsed > nsTimeout)
+            {
+                RTTestFailed(g_hTest, "Recording took too long (running %RU64 vs. timeout %RU64), aborting\n", cNsElapsed, nsTimeout);
+                rc = VERR_TIMEOUT;
+            }
 
             if (RT_FAILURE(rc))
                 break;
         }
+
+        if (cbRecTotal != cbToRecTotal)
+            RTTestFailed(g_hTest, "Recording ended unexpectedly (%RU32/%RU32 recorded)\n", cbRecTotal, cbToRecTotal);
 
         int rc2 = AudioTestMixStreamDisable(pMix);