[RFC PATCH v2 0/1] ALSA: virtio: trace control message lifecycles

[RFC PATCH v2 0/1] ALSA: virtio: trace control message lifecycles

[Joonho Lee]

Hi,

This adds a control-message lifecycle trace event to virtio-snd. A per-send
ID connects enqueue, response, cancellation and sender wait outcomes,
including a response arriving after a timeout.

Changes in v2:
- Group internal helper event arguments in struct virtsnd_ctl_event.
- Use designated initializers and named validity flags instead of positional
  booleans. Keep TRACE_EVENT and its record format unchanged.

The event definition, error handling and request lifetime are unchanged
from v1. The patch applies directly to the base below and has no dependency
on the experimental VZ capture changes.

Validation of v2:
- ARM64 W=1 builds, including KASAN/lockdep, BPF events and tracing-disabled
  configurations, passed without warnings or errors.
- Eight QEMU boots passed malformed-response, enqueue failure, asynchronous
  completion, interrupted wait, timeout and reset/recovery checks. Trace-on
  fixture runs recorded 280 events each without loss or KASAN/lockdep reports.
- A non-debug QEMU/HVF comparison completed 90,000 lifecycle cycles and three
  10-second synthetic captures at 4,096 frames. All functional checks passed;
  captures each read 480,000 frames with no XRUNs or read errors.

On GCC 14.2.0 ARM64, the event arguments are scalarized. The control object
text shrinks by 56 bytes and the send stack frame drops from 192 to 176 bytes.
With event tracing compiled out, the old and new object text is identical.
The existing 24-byte per-request metadata cost remains unchanged.

Host-load stability checks failed during the timing comparison, so those
measurements do not establish an isolated runtime overhead percentage.
These regressions use synthetic QEMU devices; native VZ steady-capture
performance and physical microphone acceptance remain unverified.

The malformed-length fixture writes a full response and changes only the
reported used length. The sender retains its existing behavior; this patch
records diagnostic fields without changing protocol validation.

Previous version:
https://lore.kernel.org/linux-sound/rfc-virtio-snd-control-trace-0.208f05ae8ea44e77@gmail.com/T/

Thanks,
Joonho

Joonho Lee (1):
  ALSA: virtio: trace control message lifecycles

 sound/virtio/Makefile               |   2 +
 sound/virtio/virtio_ctl_msg.c       | 178 +++++++++++++++++++++++++++++++++++-
 sound/virtio/virtio_ctl_msg_trace.h | 107 ++++++++++++++++++++++
 3 files changed, 286 insertions(+), 1 deletion(-)

base-commit: 2f2f7eeef8b0a1a9b9ca998231419873ccae8d4e

[RFC PATCH v2 1/1] ALSA: virtio: trace control message lifecycles

[Joonho Lee]

A timed-out control request can complete later or be canceled during
teardown. The existing opcode-only timeout message does not identify the
request or show when the queue gives it back, which makes it difficult to
correlate control stalls with guest scheduling and device reset activity.

Add a virtio_snd_ctl_msg trace event with a per-send identifier and phases
for enqueue, response, cancellation and the sender's wait outcome. Record
PCM stream IDs where the request layout supplies one, the enqueue or wait
result, and the device's used length and response status. Mark optional
fields explicitly and check the writable response capacity before reading
a status for the event.

Assign IDs only to requests sent while the event is enabled. Keep sender
wait outcomes separate from queue completion so a timeout followed by a
late response retains the same ID. Include neither audio data nor kernel
addresses in the event.

Leave protocol results, request ownership and timeout handling unchanged.
The added fields increase each control-message structure by 24 bytes on
the tested ARM64 configurations, including when tracing is disabled. No
events are added to PCM data completions.

Assisted-by: LLM
Signed-off-by: Joonho Lee <mynameisjune111@gmail.com>
---
Changes in v2:
- Group internal helper event arguments in struct virtsnd_ctl_event.
- Use designated initializers and named validity flags instead of positional
  booleans. Keep TRACE_EVENT and its record format unchanged.

 sound/virtio/Makefile               |   2 +
 sound/virtio/virtio_ctl_msg.c       | 178 +++++++++++++++++++++++++++++++++++-
 sound/virtio/virtio_ctl_msg_trace.h | 107 ++++++++++++++++++++++
 3 files changed, 286 insertions(+), 1 deletion(-)

diff --git a/sound/virtio/Makefile b/sound/virtio/Makefile
index 3ca41b3c8..3db8ad687 100644
--- a/sound/virtio/Makefile
+++ b/sound/virtio/Makefile
@@ -2,6 +2,8 @@
 
 obj-$(CONFIG_SND_VIRTIO) += virtio_snd.o
 
+CFLAGS_virtio_ctl_msg.o := -I$(src)
+
 virtio_snd-y := \
 	virtio_card.o \
 	virtio_chmap.o \
diff --git a/sound/virtio/virtio_ctl_msg.c b/sound/virtio/virtio_ctl_msg.c
index 6433c870f..4cac9aa0d 100644
--- a/sound/virtio/virtio_ctl_msg.c
+++ b/sound/virtio/virtio_ctl_msg.c
@@ -3,11 +3,16 @@
  * virtio-snd: Virtio sound device
  * Copyright (C) 2021 OpenSynergy GmbH
  */
+#include <linux/device.h>
+#include <linux/limits.h>
 #include <linux/moduleparam.h>
 #include <linux/virtio_config.h>
 
 #include "virtio_card.h"
 
+#define CREATE_TRACE_POINTS
+#include "virtio_ctl_msg_trace.h"
+
 /**
  * struct virtio_snd_msg - Control message.
  * @sg_request: Scattergather list containing a device request (header).
@@ -15,6 +20,13 @@
  * @list: Pending message list entry.
  * @notify: Request completed notification.
  * @ref_count: Reference count used to manage a message lifetime.
+ * @trace_id: Stable identifier for tracing this request lifecycle.
+ * @trace_opcode: Decoded request opcode for tracing.
+ * @trace_stream_id: Decoded PCM stream identifier for tracing.
+ * @trace_response_capacity: Cached capacity of writable response buffers.
+ * @trace_opcode_valid: Whether @trace_opcode was decoded from the request.
+ * @trace_stream_id_valid: Whether @trace_stream_id was decoded safely.
+ * @trace_canceled: Whether teardown canceled this request.
  */
 struct virtio_snd_msg {
 	struct scatterlist sg_request;
@@ -22,8 +34,111 @@ struct virtio_snd_msg {
 	struct list_head list;
 	struct completion notify;
 	refcount_t ref_count;
+	u64 trace_id;
+	u32 trace_opcode;
+	u32 trace_stream_id;
+	u32 trace_response_capacity;
+	bool trace_opcode_valid;
+	bool trace_stream_id_valid;
+	bool trace_canceled;
+};
+
+static atomic64_t virtsnd_ctl_msg_trace_id = ATOMIC64_INIT(0);
+
+/* Per-event values; request-lifetime metadata stays in virtio_snd_msg. */
+struct virtsnd_ctl_event {
+	u8 phase;
+	u8 outcome;
+	u8 flags;
+	int result;
+	u32 used_len;
+	u32 status;
 };
 
+static inline void virtsnd_ctl_msg_trace(struct virtio_snd *snd,
+					 struct virtio_snd_msg *msg,
+					 const struct virtsnd_ctl_event *event)
+{
+	u8 flags;
+
+	if (!msg->trace_id)
+		return;
+
+	flags = event->flags;
+	if (msg->trace_opcode_valid)
+		flags |= VIRTSND_CTL_TRACE_VALID_OPCODE;
+	if (msg->trace_stream_id_valid)
+		flags |= VIRTSND_CTL_TRACE_VALID_STREAM_ID;
+
+	trace_virtio_snd_ctl_msg(dev_name(&snd->vdev->dev), msg->trace_id,
+				 event->phase, event->outcome, flags,
+				 msg->trace_opcode, msg->trace_stream_id,
+				 event->result, event->used_len, event->status);
+}
+
+static u32 virtsnd_ctl_msg_trace_capacity(struct virtio_snd_msg *msg,
+					  struct scatterlist *in_sgs)
+{
+	struct scatterlist *sg;
+	u32 capacity = msg->sg_response.length;
+
+	for (sg = in_sgs; sg; sg = sg_next(sg)) {
+		if (capacity > U32_MAX - sg->length)
+			return U32_MAX;
+
+		capacity += sg->length;
+	}
+
+	return capacity;
+}
+
+static void virtsnd_ctl_msg_trace_prepare(struct virtio_snd_msg *msg,
+					  struct virtio_snd_hdr *request,
+					  struct scatterlist *in_sgs)
+{
+	struct virtio_snd_pcm_hdr *pcm_request = (void *)request;
+	size_t request_size;
+	u32 opcode;
+
+	msg->trace_id = 0;
+	msg->trace_canceled = false;
+
+	if (!trace_virtio_snd_ctl_msg_enabled())
+		return;
+
+	request_size = msg->sg_request.length;
+	msg->trace_opcode = 0;
+	msg->trace_stream_id = 0;
+	msg->trace_response_capacity =
+		virtsnd_ctl_msg_trace_capacity(msg, in_sgs);
+	msg->trace_opcode_valid = false;
+	msg->trace_stream_id_valid = false;
+
+	msg->trace_id = atomic64_inc_return(&virtsnd_ctl_msg_trace_id);
+	if (request_size < sizeof(*request))
+		return;
+
+	opcode = le32_to_cpu(request->code);
+	msg->trace_opcode = opcode;
+	msg->trace_opcode_valid = true;
+
+	if (request_size < sizeof(struct virtio_snd_pcm_hdr))
+		return;
+
+	switch (opcode) {
+	case VIRTIO_SND_R_PCM_SET_PARAMS:
+	case VIRTIO_SND_R_PCM_PREPARE:
+	case VIRTIO_SND_R_PCM_RELEASE:
+	case VIRTIO_SND_R_PCM_START:
+	case VIRTIO_SND_R_PCM_STOP:
+		msg->trace_stream_id = le32_to_cpu(pcm_request->stream_id);
+		msg->trace_stream_id_valid = true;
+		break;
+	default:
+		break;
+	}
+}
+
 /**
  * virtsnd_ctl_msg_ref() - Increment reference counter for the message.
  * @msg: Control message.
@@ -134,6 +249,7 @@ int virtsnd_ctl_msg_send(struct virtio_snd *snd, struct virtio_snd_msg *msg,
 	int rc;
 
 	virtsnd_ctl_msg_ref(msg);
+	virtsnd_ctl_msg_trace_prepare(msg, request, in_sgs);
 
 	/* Set the default status in case the message was canceled. */
 	response->code = cpu_to_le32(VIRTIO_SND_S_IO_ERR);
@@ -154,6 +270,18 @@ int virtsnd_ctl_msg_send(struct virtio_snd *snd, struct virtio_snd_msg *msg,
 
 			list_add_tail(&msg->list, &snd->ctl_msgs);
 		}
+
+		virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+			.phase = VIRTSND_CTL_TRACE_ENQUEUE,
+			.outcome = VIRTSND_CTL_TRACE_OUTCOME_NONE,
+			.flags = VIRTSND_CTL_TRACE_VALID_RESULT,
+			.result = rc,
+		});
+		if (!rc && nowait)
+			virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+				.phase = VIRTSND_CTL_TRACE_WAIT,
+				.outcome = VIRTSND_CTL_TRACE_OUTCOME_ASYNC,
+			});
 	}
 
 	if (rc) {
@@ -182,6 +310,19 @@ int virtsnd_ctl_msg_send(struct virtio_snd *snd, struct virtio_snd_msg *msg,
 				"control message (0x%08x) timeout\n",
 				le32_to_cpu(request->code));
 			rc = -ETIMEDOUT;
+			virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+				.phase = VIRTSND_CTL_TRACE_WAIT,
+				.outcome = VIRTSND_CTL_TRACE_OUTCOME_TIMEOUT,
+				.flags = VIRTSND_CTL_TRACE_VALID_RESULT,
+				.result = rc,
+			});
+		} else {
+			virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+				.phase = VIRTSND_CTL_TRACE_WAIT,
+				.outcome = VIRTSND_CTL_TRACE_OUTCOME_SIGNAL,
+				.flags = VIRTSND_CTL_TRACE_VALID_RESULT,
+				.result = rc,
+			});
 		}
 
 		goto on_exit;
@@ -202,6 +343,15 @@ int virtsnd_ctl_msg_send(struct virtio_snd *snd, struct virtio_snd_msg *msg,
 		break;
 	}
 
+	virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+		.phase = VIRTSND_CTL_TRACE_WAIT,
+		.outcome = READ_ONCE(msg->trace_canceled) ?
+			VIRTSND_CTL_TRACE_OUTCOME_CANCEL :
+			VIRTSND_CTL_TRACE_OUTCOME_RESPONSE,
+		.flags = VIRTSND_CTL_TRACE_VALID_RESULT,
+		.result = rc,
+	});
+
 on_exit:
 	virtsnd_ctl_msg_unref(msg);
 
@@ -239,6 +389,11 @@ void virtsnd_ctl_msg_cancel_all(struct virtio_snd *snd)
 			list_first_entry(&snd->ctl_msgs, struct virtio_snd_msg,
 					 list);
 
+		WRITE_ONCE(msg->trace_canceled, true);
+		virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+			.phase = VIRTSND_CTL_TRACE_CANCEL,
+			.outcome = VIRTSND_CTL_TRACE_OUTCOME_CANCEL,
+		});
 		virtsnd_ctl_msg_complete(msg);
 	}
 }
@@ -297,7 +452,28 @@ void virtsnd_ctl_notify_cb(struct virtqueue *vqueue)
 	guard(spinlock_irqsave)(&queue->lock);
 	do {
 		virtqueue_disable_cb(vqueue);
-		while ((msg = virtqueue_get_buf(vqueue, &length)))
+		while ((msg = virtqueue_get_buf(vqueue, &length))) {
+			struct virtio_snd_hdr *response =
+				virtsnd_ctl_msg_response(msg);
+
+			if (trace_virtio_snd_ctl_msg_enabled() && msg->trace_id) {
+				bool status_valid =
+					msg->sg_response.length >= sizeof(*response) &&
+					length >= sizeof(*response) &&
+					length <= msg->trace_response_capacity;
+				u32 status = status_valid ?
+					le32_to_cpu(response->code) : 0;
+
+				virtsnd_ctl_msg_trace(snd, msg, &(const struct virtsnd_ctl_event) {
+					.phase = VIRTSND_CTL_TRACE_RESPONSE,
+					.outcome = VIRTSND_CTL_TRACE_OUTCOME_NONE,
+					.flags = status_valid ?
+						VIRTSND_CTL_TRACE_VALID_STATUS : 0,
+					.used_len = length,
+					.status = status,
+				});
+			}
 			virtsnd_ctl_msg_complete(msg);
+		}
 	} while (!virtqueue_enable_cb(vqueue));
 }
diff --git a/sound/virtio/virtio_ctl_msg_trace.h b/sound/virtio/virtio_ctl_msg_trace.h
new file mode 100644
index 000000000..d6d9e9a04
--- /dev/null
+++ b/sound/virtio/virtio_ctl_msg_trace.h
@@ -0,0 +1,107 @@
+/* SPDX-License-Identifier: GPL-2.0+ */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM virtio_snd
+
+#if !defined(_TRACE_VIRTIO_SND_CTL_MSG_H) || \
+	defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_VIRTIO_SND_CTL_MSG_H
+
+#include <linux/tracepoint.h>
+
+#define VIRTSND_CTL_TRACE_ENQUEUE		0
+#define VIRTSND_CTL_TRACE_RESPONSE		1
+#define VIRTSND_CTL_TRACE_CANCEL		2
+#define VIRTSND_CTL_TRACE_WAIT			3
+
+#define VIRTSND_CTL_TRACE_OUTCOME_NONE		0
+#define VIRTSND_CTL_TRACE_OUTCOME_ASYNC		1
+#define VIRTSND_CTL_TRACE_OUTCOME_RESPONSE	2
+#define VIRTSND_CTL_TRACE_OUTCOME_CANCEL	3
+#define VIRTSND_CTL_TRACE_OUTCOME_TIMEOUT	4
+#define VIRTSND_CTL_TRACE_OUTCOME_SIGNAL		5
+
+#define VIRTSND_CTL_TRACE_VALID_OPCODE		0x01
+#define VIRTSND_CTL_TRACE_VALID_STREAM_ID	0x02
+#define VIRTSND_CTL_TRACE_VALID_RESULT		0x04
+#define VIRTSND_CTL_TRACE_VALID_STATUS		0x08
+
+/*
+ * An ID identifies one send during this module's lifetime. Only requests sent
+ * while this event is enabled receive an ID. Enabling it during an existing
+ * request therefore does not produce a partial lifecycle for that request.
+ *
+ * A wait event describes the sender's return; response and cancel describe
+ * queue ownership ending. A timeout or signal can precede a later response.
+ * Invalid fields contain zero and must be interpreted using their valid flag.
+ */
+TRACE_EVENT(virtio_snd_ctl_msg,
+
+	TP_PROTO(const char *device, u64 request_id, u8 phase, u8 outcome,
+		 u8 flags, u32 opcode, u32 stream_id, int result,
+		 u32 used_len, u32 status),
+
+	TP_ARGS(device, request_id, phase, outcome, flags, opcode, stream_id,
+		result, used_len, status),
+
+	TP_STRUCT__entry(
+		__string(device, device)
+		__field(u64, request_id)
+		__field(u8, phase)
+		__field(u8, outcome)
+		__field(bool, opcode_valid)
+		__field(u32, opcode)
+		__field(bool, stream_id_valid)
+		__field(u32, stream_id)
+		__field(int, result)
+		__field(bool, result_valid)
+		__field(u32, used_len)
+		__field(bool, status_valid)
+		__field(u32, status)
+	),
+
+	TP_fast_assign(
+		__assign_str(device);
+		__entry->request_id = request_id;
+		__entry->phase = phase;
+		__entry->outcome = outcome;
+		__entry->opcode_valid = flags & VIRTSND_CTL_TRACE_VALID_OPCODE;
+		__entry->opcode = opcode;
+		__entry->stream_id_valid =
+			flags & VIRTSND_CTL_TRACE_VALID_STREAM_ID;
+		__entry->stream_id = stream_id;
+		__entry->result = result;
+		__entry->result_valid = flags & VIRTSND_CTL_TRACE_VALID_RESULT;
+		__entry->used_len = used_len;
+		__entry->status_valid = flags & VIRTSND_CTL_TRACE_VALID_STATUS;
+		__entry->status = status;
+	),
+
+	TP_printk("device=%s id=%llu phase=%s outcome=%s opcode_valid=%d opcode=0x%08x stream_id_valid=%d stream_id=%u result_valid=%d result=%d used_len=%u status_valid=%d status=0x%08x",
+		  __get_str(device),
+		  (unsigned long long)__entry->request_id,
+		  __print_symbolic(__entry->phase,
+				   { VIRTSND_CTL_TRACE_ENQUEUE, "enqueue" },
+				   { VIRTSND_CTL_TRACE_RESPONSE, "response" },
+				   { VIRTSND_CTL_TRACE_CANCEL, "cancel" },
+				   { VIRTSND_CTL_TRACE_WAIT, "wait" }),
+		  __print_symbolic(__entry->outcome,
+				   { VIRTSND_CTL_TRACE_OUTCOME_NONE, "none" },
+				   { VIRTSND_CTL_TRACE_OUTCOME_ASYNC, "async" },
+				   { VIRTSND_CTL_TRACE_OUTCOME_RESPONSE, "response" },
+				   { VIRTSND_CTL_TRACE_OUTCOME_CANCEL, "cancel" },
+				   { VIRTSND_CTL_TRACE_OUTCOME_TIMEOUT, "timeout" },
+				   { VIRTSND_CTL_TRACE_OUTCOME_SIGNAL, "signal" }),
+		  __entry->opcode_valid, __entry->opcode,
+		  __entry->stream_id_valid, __entry->stream_id,
+		  __entry->result_valid, __entry->result, __entry->used_len,
+		  __entry->status_valid, __entry->status)
+);
+
+#endif /* _TRACE_VIRTIO_SND_CTL_MSG_H */
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE virtio_ctl_msg_trace
+#include <trace/define_trace.h>
-- 
2.50.1

Re: [RFC PATCH v2 1/1] ALSA: virtio: trace control message lifecycles

[sashiko-bot]

> A timed-out control request can complete later or be canceled during
> teardown. The existing opcode-only timeout message does not identify the
> request or show when the queue gives it back, which makes it difficult to
> correlate control stalls with guest scheduling and device reset activity.
> 
> Add a virtio_snd_ctl_msg trace event with a per-send identifier and phases
> for enqueue, response, cancellation and the sender's wait outcome. Record
> PCM stream IDs where the request layout supplies one, the enqueue or wait
> result, and the device's used length and response status. Mark optional
> fields explicitly and check the writable response capacity before reading
> a status for the event.
> 
> Assign IDs only to requests sent while the event is enabled. Keep sender
> wait outcomes separate from queue completion so a timeout followed by a
> late response retains the same ID. Include neither audio data nor kernel
> addresses in the event.
> 
> Leave protocol results, request ownership and timeout handling unchanged.
> The added fields increase each control-message structure by 24 bytes on
> the tested ARM64 configurations, including when tracing is disabled. No
> events are added to PCM data completions.
> 
> Assisted-by: LLM
> Signed-off-by: Joonho Lee <mynameisjune111@gmail.com>

Sashiko has reviewed this patch and found no issues.

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/rfc-v2-virtio-snd-control-trace-0.60ead383067a41ae@gmail.com?part=1