From a163f29a438c27a8b042f6446de62898202ea0f6 Mon Sep 17 00:00:00 2001
From: Wim Taymans <wtaymans@redhat.com>
Date: Thu, 30 Mar 2023 11:34:30 +0200
Subject: [PATCH] improve logging

---
 spa/plugins/alsa/alsa-pcm.c         | 4 ++--
 spa/plugins/audiomixer/audiomixer.c | 7 ++++---
 spa/plugins/audiomixer/mixer-dsp.c  | 4 ++--
 src/pipewire/stream.c               | 3 ++-
 4 files changed, 10 insertions(+), 8 deletions(-)

diff --git a/spa/plugins/alsa/alsa-pcm.c b/spa/plugins/alsa/alsa-pcm.c
index 5d47240a0..45748ffe9 100644
--- a/spa/plugins/alsa/alsa-pcm.c
+++ b/spa/plugins/alsa/alsa-pcm.c
@@ -2130,7 +2130,7 @@ again:
 					state->props.device, snd_strerror(res));
 			return res;
 		}
-		spa_log_trace_fp(state->log, "%p: begin %ld %ld %d",
+		spa_log_trace_fp(state->log, "%p: begin offset:%ld avail:%ld threshold:%d",
 				state, offset, frames, state->threshold);
 		off = offset;
 	} else {
@@ -2192,7 +2192,7 @@ again:
 		to_write -= n_frames;
 	}
 
-	spa_log_trace_fp(state->log, "%p: commit %ld %ld %"PRIi64,
+	spa_log_trace_fp(state->log, "%p: commit offset:%ld written:%ld sample_count:%"PRIi64,
 			state, offset, written, state->sample_count);
 	total_written += written;
 
diff --git a/spa/plugins/audiomixer/audiomixer.c b/spa/plugins/audiomixer/audiomixer.c
index 5c2d78353..1e6e3ca7d 100644
--- a/spa/plugins/audiomixer/audiomixer.c
+++ b/spa/plugins/audiomixer/audiomixer.c
@@ -770,9 +770,9 @@ static int impl_node_process(void *object)
 		size = SPA_MIN(bd->maxsize - offs, bd->chunk->size);
 		maxsize = SPA_MIN(size, maxsize);
 
-		spa_log_trace_fp(this->log, "%p: mix input %d %p->%p %d %d %d:%d", this,
+		spa_log_trace_fp(this->log, "%p: mix input %d %p->%p %d %d %d:%d/%d", this,
 				i, inio, outio, inio->status, inio->buffer_id,
-				offs, size);
+				offs, size, this->stride);
 
 		if (!SPA_FLAG_IS_SET(bd->chunk->flags, SPA_CHUNK_FLAG_EMPTY)) {
 			datas[n_buffers] = SPA_PTROFF(bd->data, offs, void);
@@ -783,7 +783,8 @@ static int impl_node_process(void *object)
 
 	outb = dequeue_buffer(this, outport);
         if (SPA_UNLIKELY(outb == NULL)) {
-                spa_log_trace(this->log, "%p: out of buffers", this);
+                spa_log_trace(this->log, "%p: out of buffers (%d)", this,
+				outport->n_buffers);
                 return -EPIPE;
         }
 
diff --git a/spa/plugins/audiomixer/mixer-dsp.c b/spa/plugins/audiomixer/mixer-dsp.c
index 173917d03..510d7e40b 100644
--- a/spa/plugins/audiomixer/mixer-dsp.c
+++ b/spa/plugins/audiomixer/mixer-dsp.c
@@ -706,9 +706,9 @@ static int impl_node_process(void *object)
 		size = SPA_MIN(bd->maxsize - offs, bd->chunk->size);
 		maxsize = SPA_MIN(maxsize, size);
 
-		spa_log_trace_fp(this->log, "%p: mix input %d %p->%p %d %d %d:%d", this,
+		spa_log_trace_fp(this->log, "%p: mix input %d %p->%p %d %d %d:%d/%d", this,
 				i, inio, outio, inio->status, inio->buffer_id,
-				offs, size);
+				offs, size, (int)sizeof(float));
 
 		if (!SPA_FLAG_IS_SET(bd->chunk->flags, SPA_CHUNK_FLAG_EMPTY)) {
 			datas[n_buffers] = SPA_PTROFF(bd->data, offs, void);
diff --git a/src/pipewire/stream.c b/src/pipewire/stream.c
index df5916ffd..5fda0a185 100644
--- a/src/pipewire/stream.c
+++ b/src/pipewire/stream.c
@@ -1045,7 +1045,6 @@ again:
 			impl->drained = false;
 			io->buffer_id = b->id;
 			res = io->status = SPA_STATUS_HAVE_DATA;
-			pw_log_trace_fp("%p: pop %d %p", stream, b->id, io);
 			/* we have a buffer, if we are not rt and don't follow
 			 * any rate matching and there are no more
 			 * buffers queued and there is a buffer to dequeue, ask for
@@ -1056,6 +1055,8 @@ again:
 			ask_more = !impl->process_rt && impl->rate_match == NULL &&
 				queue_is_empty(impl, &impl->queued) &&
 				!queue_is_empty(impl, &impl->dequeued);
+			pw_log_trace_fp("%p: pop %d %p ask_more:%u %p", stream, b->id, io,
+					ask_more, impl->rate_match);
 		} else if (impl->draining || impl->drained) {
 			impl->draining = true;
 			impl->drained = true;