Ticket #7703: 0001-Audio-debug-output.patch

src/add-ons/kernel/drivers/audio/hda/hda_controller.cpp

@@ -1018 +1018 @@
         controller->Write16(HDAC_CORB_WRITE_POS, controller->corb_write_pos);
         status_t status = acquire_sem_etc(codec->response_sem, queued,
             B_RELATIVE_TIMEOUT, 50000ULL);
-        if (status != B_OK)
+        if (status != B_OK) {
+            dprintf("hda: ERROR: failed to acquire codec response sem: %s\n",
+                strerror(status));
             return status;
+        }
     }
 
     if (responses != NULL)

src/add-ons/media/media-add-ons/mixer/AudioMixer.cpp

@@ -315 +315 @@
         return;
     }
 
-    //PRINT(4, "buffer received at %12Ld, should arrive at %12Ld, delta %12Ld\n", TimeSource()->Now(), buffer->Header()->start_time, TimeSource()->Now() - buffer->Header()->start_time);
+    debug_printf("buffer received at %12" B_PRIdBIGTIME ", should arrive at %12"
+        B_PRIdBIGTIME ", delta %12" B_PRIdBIGTIME "\n", TimeSource()->Now(),
+        buffer->Header()->start_time,
+        TimeSource()->Now() - buffer->Header()->start_time);
 
     // to receive the buffer at the right time,
     // push it through the event looper
@@ -329 +332 @@
 void
 AudioMixer::HandleInputBuffer(BBuffer* buffer, bigtime_t lateness)
 {
+    debug_printf("AudioMixer: handle input buffer\n");
     bigtime_t variation = 0;
     if (lateness > fLastLateness)
         variation = lateness-fLastLateness;
@@ -348 +352 @@
             NotifyLateProducer(source, variation, TimeSource()->Now());
 
             if (RunMode() == B_DROP_DATA) {
-                TRACE("AudioMixer: dropping buffer\n");
+                debug_printf("AudioMixer: dropping buffer\n");
                 return;
             }
         }
@@ -1101 +1105 @@
 AudioMixer::HandleEvent(const media_timed_event *event, bigtime_t lateness,
     bool realTimeEvent)
 {
+    debug_printf("AudioMixer: handle event, lateness %" B_PRIdBIGTIME "\n",
+        lateness);
+
     switch (event->type) {
         case BTimedEventQueue::B_HANDLE_BUFFER:
         {
@@ -1215 +1222 @@
 status_t
 AudioMixer::SendBuffer(BBuffer* buffer, MixerOutput* output)
 {
+    debug_printf("AudioMixer: send buffer\n");
     return BBufferProducer::SendBuffer(buffer, output->MediaOutput().source,
         output->MediaOutput().destination);
 }

src/add-ons/media/media-add-ons/mixer/MixerCore.cpp

@@ -500 +500 @@
     bigtime_t bufferRequestTimeout = buffer_duration(
         fOutput->MediaOutput().format.u.raw_audio) / 2;
 
-    TRACE("MixerCore: starting _MixThread at %Ld with latency %Ld and "
-        "downstream latency %Ld, bufferRequestTimeout %Ld\n", start, latency,
-        fDownstreamLatency, bufferRequestTimeout);
+    debug_printf("MixerCore: starting _MixThread at %" B_PRIdBIGTIME
+        " with latency %" B_PRIdBIGTIME " and downstream latency %"
+        B_PRIdBIGTIME ", bufferRequestTimeout %" B_PRIdBIGTIME "\n", start,
+        fEventLatency, fDownstreamLatency, bufferRequestTimeout);
 
     // We must read from the input buffer at a position (pos) that is always
     // a multiple of fMixBufferFrameCount.
@@ -511 +512 @@
         * fMixBufferFrameCount;
     bigtime_t timeBase = duration_for_frames(fMixBufferFrameRate, frameBase);
 
-    TRACE("MixerCore: starting _MixThread, start %Ld, timeBase %Ld, "
-        "frameBase %Ld\n", start, timeBase, frameBase);
+    debug_printf("MixerCore: starting _MixThread, start %" B_PRIdBIGTIME
+        ", timeBase %" B_PRIdBIGTIME ", frameBase %" B_PRIdBIGTIME "\n", start,
+        timeBase, frameBase);
 
     ASSERT(fMixBufferFrameCount > 0);
 
@@ -534 +536 @@
     status_t ret = B_ERROR;
 
     while(fRunning == true) {
+        debug_printf("mix thread\n");
         if (fHasEvent == false)
             goto schedule_next_event;
 
@@ -735 +738 @@
         media_timed_event mixerEvent(PickEvent(),
             MIXER_PROCESS_EVENT, 0, BTimedEventQueue::B_NO_CLEANUP);
 
+        debug_printf("schedule next event: event time %" B_PRIdBIGTIME " -> %"
+            B_PRIdBIGTIME "\n", fEventTime, mixerEvent.event_time);
         ret = write_port(fNode->ControlPort(), MIXER_SCHEDULE_EVENT,
             &mixerEvent, sizeof(mixerEvent));
         if (ret != B_OK)
-            TRACE("MixerCore::_MixThread: can't write to owner port\n");
+            debug_printf("MixerCore::_MixThread: can't write to owner port\n");
 
         fHasEvent = true;
 

src/add-ons/media/media-add-ons/multi_audio/MultiAudioNode.cpp

@@ -25 +25 @@
 #ifdef DEBUG
 #   define PRINTING
 #endif
+#define DEBUG 3
 #include "debug.h"
 #include "Resampler.h"
 
@@ -35 +36 @@
 #define PARAMETER_ID_OUTPUT_FREQUENCY   2
 
 
+#define printf(x...)        debug_printf(x)
+#define fprintf(x, y...)    debug_printf(y)
+
+
 //This represent an hardware output
 class node_input {
 public:
@@ -630 +635 @@
 void
 MultiAudioNode::BufferReceived(BBuffer* buffer)
 {
-    //CALLED();
+    CALLED();
     switch (buffer->Header()->type) {
         /*case B_MEDIA_PARAMETERS:
             {
@@ -672 +677 @@
 MultiAudioNode::ProducerDataStatus(const media_destination& forWhom,
     int32 status, bigtime_t atPerformanceTime)
 {
+    CALLED();
     node_input* channel = _FindInput(forWhom);
     if (channel == NULL) {
         fprintf(stderr, "invalid destination received in "
@@ -1152 +1158 @@
 MultiAudioNode::HandleEvent(const media_timed_event* event, bigtime_t lateness,
     bool realTimeEvent)
 {
+    CALLED();
     switch (event->type) {
         case BTimedEventQueue::B_START:
             _HandleStart(event, lateness, realTimeEvent);
@@ -1187 +1194 @@
 MultiAudioNode::_HandleBuffer(const media_timed_event* event,
     bigtime_t lateness, bool realTimeEvent)
 {
+    CALLED();
     BBuffer* buffer = const_cast<BBuffer*>((BBuffer*)event->pointer);
     if (buffer == NULL)
         return B_BAD_VALUE;
@@ -1234 +1242 @@
 MultiAudioNode::_HandleDataStatus(const media_timed_event* event,
     bigtime_t lateness, bool realTimeEvent)
 {
+    CALLED();
     PRINT(("MultiAudioNode::HandleDataStatus status:%" B_PRIi32 ", lateness:%"
         B_PRIiBIGTIME "\n", event->data, lateness));
     switch (event->data) {
@@ -1680 +1689 @@
 const char*
 MultiAudioNode::_GetControlName(multi_mix_control& control)
 {
+    CALLED();
     if (control.string != S_null)
         return kMultiControlString[control.string];
 
@@ -1784 +1794 @@
 MultiAudioNode::_CreateFrequencyParameterGroup(BParameterGroup* parentGroup,
     const char* name, int32 parameterID, uint32 rateMask)
 {
+    CALLED();
     BParameterGroup* group = parentGroup->MakeGroup(name);
     BDiscreteParameter* frequencyParam = group->MakeDiscreteParameter(
         parameterID, B_MEDIA_NO_TYPE,
@@ -1868 +1879 @@
                     //PRINT(("MultiAudioNode::Runthread WriteZeros\n"));
                 }
             } else {
-                //PRINT(("playback_buffer_cycle non ok input: %i\n", i));
+                debug_printf("playback_buffer_cycle non ok input: %" B_PRId32
+                    "\n", i);
             }
         }
 
@@ -1921 +1933 @@
 
                     output->fOldBufferInfo = bufferInfo;
                 } else {
-                    //PRINT(("record_buffer_cycle non ok\n"));
+                    debug_printf("record_buffer_cycle non ok: %" B_PRId32 "\n",
+                        i);
                 }
             }
         }
@@ -1934 +1947 @@
 void
 MultiAudioNode::_WriteZeros(node_input& input, uint32 bufferCycle)
 {
-    //CALLED();
+    CALLED();
     /*int32 samples = input.fInput.format.u.raw_audio.buffer_size;
     if(input.fInput.format.u.raw_audio.format == media_raw_audio_format::B_AUDIO_UCHAR) {
         uint8 *sample = (uint8*)fDevice->BufferList().playback_buffers[input.fBufferCycle][input.fChannelId].base;
@@ -2036 +2049 @@
 void
 MultiAudioNode::_FillNextBuffer(node_input& input, BBuffer* buffer)
 {
+    CALLED();
     uint32 channelCount = input.fInput.format.u.raw_audio.channel_count;
     size_t inputSampleSize = input.fInput.format.u.raw_audio.format
             & media_raw_audio_format::B_AUDIO_SIZE_MASK;
@@ -2122 +2136 @@
 MultiAudioNode::_UpdateTimeSource(multi_buffer_info& info,
     multi_buffer_info& oldInfo, node_input& input)
 {
-    //CALLED();
+    CALLED();
     if (!fTimeSourceStarted || oldInfo.played_real_time == 0)
         return;
 
     fTimeComputer.AddTimeStamp(info.played_real_time,
         info.played_frames_count);
+
+    debug_printf("publish time: performance: %" B_PRIdBIGTIME ", real: %"
+        B_PRIdBIGTIME ", drift %f\n", fTimeComputer.PerformanceTime(),
+        fTimeComputer.RealTime(), fTimeComputer.Drift());
+
     PublishTime(fTimeComputer.PerformanceTime(), fTimeComputer.RealTime(),
         fTimeComputer.Drift());
 }
@@ -2136 +2155 @@
 BBuffer*
 MultiAudioNode::_FillNextBuffer(multi_buffer_info& info, node_output& output)
 {
-    //CALLED();
+    CALLED();
     // get a buffer from our buffer group
     //PRINT(("buffer size: %i, buffer duration: %i\n", fOutput.format.u.raw_audio.buffer_size, BufferDuration()));
     //PRINT(("MBI.record_buffer_cycle: %i\n", MBI.record_buffer_cycle));
@@ -2245 +2264 @@
 node_output*
 MultiAudioNode::_FindOutput(media_source source)
 {
+    CALLED();
     node_output* channel = NULL;
 
     for (int32 i = 0; i < fOutputs.CountItems(); i++) {
@@ -2263 +2283 @@
 node_input*
 MultiAudioNode::_FindInput(media_destination dest)
 {
+    CALLED();
     node_input* channel = NULL;
 
     for (int32 i = 0; i < fInputs.CountItems(); i++) {
@@ -2281 +2302 @@
 node_input*
 MultiAudioNode::_FindInput(int32 destinationId)
 {
+    CALLED();
     node_input* channel = NULL;
 
     for (int32 i = 0; i < fInputs.CountItems(); i++) {
@@ -2307 +2329 @@
 status_t
 MultiAudioNode::_SetNodeInputFrameRate(float frameRate)
 {
+    CALLED();
     // check whether the frame rate is supported
     uint32 multiAudioRate = MultiAudio::convert_from_sample_rate(frameRate);
     if ((fDevice->Description().output_rates & multiAudioRate) == 0)
@@ -2359 +2382 @@
 status_t
 MultiAudioNode::_SetNodeOutputFrameRate(float frameRate)
 {
+    CALLED();
     // check whether the frame rate is supported
     uint32 multiAudioRate = MultiAudio::convert_from_sample_rate(frameRate);
     if ((fDevice->Description().input_rates & multiAudioRate) == 0)
@@ -2411 +2435 @@
 void
 MultiAudioNode::_UpdateInternalLatency(const media_format& format)
 {
+    CALLED();
     // use half a buffer length latency
     fInternalLatency = format.u.raw_audio.buffer_size * 10000 / 2
         / ((format.u.raw_audio.format