Changeset 73812 in vbox for trunk

Timestamp:

Aug 22, 2018 8:36:02 AM (6 years ago)

Author:

vboxsync

Message:

Audio/DrvAudio: Logging.

File:

• trunk/src/VBox/Devices/Audio/DrvAudio.cpp (modified) (7 diffs)

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

@@ -955 +955 @@
             else
             {
-                Log3Func(("[%s] Buffer: Writing %RU32 frames (%RU64ms), now filled with %RU64ms -- %RU8%%\n",
+                Log3Func(("[%s] Writing %RU32 frames (%RU64ms), now filled with %RU64ms -- %RU8%%\n",
                           pStream->szName, cfGstWritten, DrvAudioHlpFramesToMilli(cfGstWritten, &pStream->Guest.Cfg.Props),
                           DrvAudioHlpFramesToMilli(AudioMixBufUsed(&pStream->Host.MixBuf), &pStream->Host.Cfg.Props),
@@ -981 +981 @@
         }
 
-        Log3Func(("[%s] cbToWrite=%RU32, cfHstUsed=%RU32, cfHstfLive=%RU32, cfGstWritten=%RU32, cfGstMixed=%RU32, rc=%Rrc\n",
-                  pStream->szName, cbToWrite, AudioMixBufUsed(&pStream->Host.MixBuf),
-                  AudioMixBufLive(&pStream->Host.MixBuf), cfGstWritten, cfGstMixed, rc));
+        Log3Func(("[%s] Dbg: cbBuf=%RU32, cbToWrite=%RU32, cfHstUsed=%RU32, cfHstfLive=%RU32, cfGstWritten=%RU32, "
+                  "cfGstMixed=%RU32, cbWrittenTotal=%RU32, rc=%Rrc\n",
+                  pStream->szName, cbBuf, cbToWrite, AudioMixBufUsed(&pStream->Host.MixBuf),
+                  AudioMixBufLive(&pStream->Host.MixBuf), cfGstWritten, cfGstMixed, cbWrittenTotal, rc));
 
     } while (0);
-
-    Log3Func(("[%s] cbWrittenTotal=%RU32, rc=%Rrc\n", pStream->szName, cbWrittenTotal, rc));
 
 #ifdef LOG_ENABLED
@@ -1410 +1409 @@
         const uint64_t tsDeltaPlayedCapturedNs = RTTimeNanoTS() - pStream->tsLastPlayedCapturedNs;
 
-              uint32_t cfPassed     = DrvAudioHlpNanoToFrames(tsDeltaPlayedCapturedNs, &pStream->Host.Cfg.Props);
+              uint32_t cfPassedReal = DrvAudioHlpNanoToFrames(tsDeltaPlayedCapturedNs, &pStream->Host.Cfg.Props);
 #endif
         const uint32_t cfPeriod     = pStream->Host.Cfg.Backend.cfPeriod;
@@ -1426 +1425 @@
             {
                 LogRel2(("Audio: Stream '%s' buffering complete\n", pStream->szName));
+                Log3Func(("[%s] Dbg: Buffering complete\n", pStream->szName));
                 fDoPlay = true;
             }
@@ -1437 +1437 @@
             {
                 LogRel2(("Audio: Stream '%s' buffering complete (short sound)\n", pStream->szName));
+                Log3Func(("[%s] Dbg: Buffering complete (short)\n", pStream->szName));
                 fDoPlay = true;
             }
@@ -1445 +1446 @@
                 fJustStarted = true;
                 LogRel2(("Audio: Stream '%s' started playing\n", pStream->szName));
+                Log3Func(("[%s] Dbg: started playing\n", pStream->szName));
             }
             else /* Not yet, so still buffering audio data. */
@@ -1505 +1507 @@
             }
 
-            Log3Func(("[%s] Dbg: fJustStarted=%RTbool, cfPassed=%RU32 (%RU64ms), cfLive=%RU32 (%RU64ms), cfPeriod=%RU32 (%RU64ms), "
-                      "cfWritable=%RU32 (%RU64ms), -> cfToPlay=%RU32 (%RU64ms), cfPlayed=%RU32 (%RU64ms)\n",
+            Log3Func(("[%s] Dbg: fJustStarted=%RTbool, cfSched=%RU32 (%RU64ms), cfPassedReal=%RU32 (%RU64ms), "
+                      "cfLive=%RU32 (%RU64ms), cfPeriod=%RU32 (%RU64ms), cfWritable=%RU32 (%RU64ms), "
+                      "-> cfToPlay=%RU32 (%RU64ms), cfPlayed=%RU32 (%RU64ms)\n",
                       pStream->szName, fJustStarted,
-                      cfPassed, DrvAudioHlpFramesToMilli(cfPassed, &pStream->Host.Cfg.Props),
+                      DrvAudioHlpMilliToFrames(pStream->Guest.Cfg.Device.uSchedulingHintMs, &pStream->Host.Cfg.Props),
+                      pStream->Guest.Cfg.Device.uSchedulingHintMs,
+                      cfPassedReal, DrvAudioHlpFramesToMilli(cfPassedReal, &pStream->Host.Cfg.Props),
                       cfLive, DrvAudioHlpFramesToMilli(cfLive, &pStream->Host.Cfg.Props),
                       cfPeriod, DrvAudioHlpFramesToMilli(cfPeriod, &pStream->Host.Cfg.Props),