Changeset 91181 in vbox

Timestamp:

Sep 9, 2021 3:36:41 PM (4 years ago)

Author:

vboxsync

svn:sync-xref-src-repo-rev:

146835

Message:

Audio/Validation Kit: Log the time delta (delay) of when a test got registered and when the test actually got started. ​bugref:10008

File:

• trunk/src/VBox/Devices/Audio/DrvHostAudioValidationKit.cpp (modified) (6 diffs)

trunk/src/VBox/Devices/Audio/DrvHostAudioValidationKit.cpp

@@ -105 +105 @@
         VALKITTESTTONEDATA TestTone;
     } t;
+    /** Time stamp (real, in ms) when test got registered. */
+    uint64_t               msRegisteredTS;
     /** Time stamp (real, in ms) when test started. */
     uint64_t               msStartedTS;
@@ -428 +430 @@
         RTListAppend(&pThis->lstTestsRec, &pTestData->Node);
 
-        pTestData->idxTest = pThis->cTestsTotal++;
+        pTestData->msRegisteredTS = RTTimeMilliTS();
+        pTestData->idxTest        = pThis->cTestsTotal++;
 
         pThis->cTestsRec++;
@@ -466 +469 @@
         RTListAppend(&pThis->lstTestsPlay, &pTestData->Node);
 
-        pTestData->idxTest = pThis->cTestsTotal++;
+        pTestData->msRegisteredTS = RTTimeMilliTS();
+        pTestData->idxTest        = pThis->cTestsTotal++;
 
         pThis->cTestsPlay++;
@@ -755 +759 @@
         {
             pTst->msStartedTS = RTTimeMilliTS();
-            LogRel(("ValKit: Injecting audio input data (%RU16Hz, %RU32ms, %RU32 bytes) started\n",
+            LogRel(("ValKit: Injecting audio input data (%RU16Hz, %RU32ms, %RU32 bytes) started (delay is %RU32ms)\n",
                     (uint16_t)pTst->t.TestTone.Tone.rdFreqHz,
-                    pTst->t.TestTone.Parms.msDuration, pTst->t.TestTone.u.Rec.cbToWrite));
+                    pTst->t.TestTone.Parms.msDuration, pTst->t.TestTone.u.Rec.cbToWrite,
+                    RTTimeMilliTS() - pTst->msRegisteredTS));
         }
 
@@ -848 +853 @@
     if (pTst == NULL) /* Empty list? */
     {
+        LogRel2(("ValKit: Warning: Guest is playing back audio (%RU32 bytes, %RU64ms) when no playback test is active\n",
+                 cbBuf, PDMAudioPropsBytesToMilli(&pStream->pStream->Cfg.Props, cbBuf)));
+
         pThis->cbPlayedNoTest += cbBuf;
 
@@ -891 +899 @@
         {
             pTst->msStartedTS = RTTimeMilliTS();
-            LogRel(("ValKit: Test #%RU32: Recording audio data (%RU16Hz, %RU32ms) started\n",
-                    pTst->idxTest, (uint16_t)Parms.TestTone.dbFreqHz, Parms.TestTone.msDuration));
+            LogRel(("ValKit: Test #%RU32: Recording audio data (%RU16Hz, %RU32ms) started (delay is %RU32ms)\n",
+                    pTst->idxTest, (uint16_t)Parms.TestTone.dbFreqHz, Parms.TestTone.msDuration,
+                    RTTimeMilliTS() - pTst->msRegisteredTS));
         }
     }