[FEATURE] Switch implementation of IPC payload dump to Linux BPF

[kv2019i]

Follow-up discussion at thesofproject/sof#9123 (comment)

To reduce the overhead of IPC payload dump, BPF should be used to enable the feature universally.

BFP script already drafted in comment thesofproject/sof#9123 (comment)

[ujfalusi]

for the record, the bpf script to capture the tx IPC messages with payload (the rx trace position update message is ignored):

#!/usr/bin/bpftrace
   
struct sof_ipc4_msg {
	union {
		unsigned long header_u64;
		struct {
			unsigned int primary;
			unsigned int extension;
		};
	};

	unsigned long data_size;
	void *data_ptr;
};
 
BEGIN
{
	printf("SOF IPC4 tx message logging. Ctrl-C to end.\n\n");
}

/*
 * Log the sent IPC4 messages, ignoring the 0x1b060000 notification
 * from firmware (trace update)
 * The message payload is printed as bytes, arranged by 16 bytes/line
 */
kprobe:sof_ipc4_log_header {
	$msg = (struct sof_ipc4_msg *)arg2;

	if ($msg->primary != 0x1b060000 && arg3 == 1 && $msg->data_size != 0) {
		printf("%s : 0x%x|0x%x [data size:: %llu]\n", str(arg1),
		       $msg->primary, $msg->extension, $msg->data_size);
		if (!strcontains(str(arg1), "done")) {
			$count = (int64) $msg->data_size;
			$ptr = (uint8*) $msg->data_ptr;
			$line = 0;

			printf("Message payload:\n");
			while ($line < 500) {
				if ($count <= 16) {
					printf("%rh\n", buf($ptr, $count));
					break;
				}

				printf("%rh\n", buf($ptr, 16));
				$count -= 16;
				if ($count == 0) {
					break;
				}
				$ptr += 16;
				$line++;
			}
		} else {
			printf("\n");
		}
	} else if ($msg->primary != 0x1b060000) {
		printf("%s : 0x%x|0x%x\n", str(arg1), $msg->primary,
		       $msg->extension);
		if (strcontains(str(arg1), "done")) {
			printf("\n");
		}
	}	
}

the log:

sof-up-xtreme:[root]:~# ./ipc4_msg_trace.bt
Attaching 2 probes...
SOF IPC4 tx message logging. Ctrl-C to end.

ipc rx       : 0x1b080000|0x0
ipc rx done  : 0x1b080000|0x0

ipc tx       : 0x44000000|0x31400008 [data size:: 8]
Message payload:
f8 7a c2 25 05 00 00 00
ipc tx reply : 0x64000000|0x31400008
ipc tx done  : 0x44000000|0x31400008 [data size:: 8]

ipc tx       : 0x44000000|0x3060004c [data size:: 76]
Message payload:
00 01 00 00 00 10 00 00 01 00 00 00 ef 01 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00
ipc tx reply : 0x64000000|0x3060004c
ipc tx done  : 0x44000000|0x3060004c [data size:: 76]

ipc tx       : 0x11000005|0x0
ipc tx reply : 0x31000000|0x0
ipc tx done  : 0x11000005|0x0

ipc tx       : 0x40000004|0x15 [data size:: 84]
Message payload:
00 00 00 00 c0 00 00 00 80 01 00 00 01 00 00 00
80 bb 00 00 10 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 10 01 00 80 bb 00 00 20 00 00 00
10 ff ff ff 01 00 00 00 00 00 00 00 02 20 01 00
00 00 00 00 00 00 00 00 80 01 00 00 01 00 00 00
00 00 00 00
ipc tx reply : 0x60000000|0x15
ipc tx done  : 0x40000004|0x15 [data size:: 84]

ipc tx       : 0x40000006|0x10 [data size:: 64]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00 ff ff ff ff ff ff ff 7f
02 00 00 00 00 00 00 00 40 0d 03 00 00 00 00 00
ipc tx reply : 0x60000000|0x10
ipc tx done  : 0x40000006|0x10 [data size:: 64]

ipc tx       : 0x44000006|0x30000018 [data size:: 24]
Message payload:
ff ff ff ff ff ff ff 7f 02 00 00 00 00 00 00 00
40 0d 03 00 00 00 00 00
ipc tx reply : 0x64000000|0x30000018
ipc tx done  : 0x44000006|0x30000018 [data size:: 24]

ipc tx       : 0x40000002|0xa [data size:: 40]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00
ipc tx reply : 0x60000000|0xa
ipc tx done  : 0x40000002|0xa [data size:: 40]

ipc tx       : 0x1101000c|0x0
ipc tx reply : 0x31000000|0x0
ipc tx done  : 0x1101000c|0x0

ipc tx       : 0x40000003|0x1000a [data size:: 40]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00
ipc tx reply : 0x60000000|0x1000a
ipc tx done  : 0x40000003|0x1000a [data size:: 40]

ipc tx       : 0x40010006|0x10010 [data size:: 64]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00 ff ff ff ff ff ff ff 7f
02 00 00 00 00 00 00 00 40 0d 03 00 00 00 00 00
ipc tx reply : 0x60000000|0x10010
ipc tx done  : 0x40010006|0x10010 [data size:: 64]

ipc tx       : 0x44010006|0x30000018 [data size:: 24]
Message payload:
ff ff ff ff ff ff ff 7f 02 00 00 00 00 00 00 00
40 0d 03 00 00 00 00 00
ipc tx reply : 0x64000000|0x30000018
ipc tx done  : 0x44010006|0x30000018 [data size:: 24]

ipc tx       : 0x4000000a|0x1000a [data size:: 40]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00
ipc tx reply : 0x60000000|0x1000a
ipc tx done  : 0x4000000a|0x1000a [data size:: 40]

ipc tx       : 0x4400000a|0x30000058 [data size:: 88]
Message payload:
58 00 00 00 02 00 00 00 01 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 ff ff ff ff
ff ff ff ff 01 00 00 00 01 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 9e 73 13 20
00 00 00 00 b2 7f 00 00
ipc tx reply : 0x64000000|0x30000058
ipc tx done  : 0x4400000a|0x30000058 [data size:: 88]

ipc tx       : 0x4000000b|0x1000a [data size:: 40]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00
ipc tx reply : 0x60000000|0x1000a
ipc tx done  : 0x4000000b|0x1000a [data size:: 40]

ipc tx       : 0x4400000b|0x30000038 [data size:: 56]
Message payload:
38 00 00 00 02 00 01 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 ff ff ff ff 04 00 ff ff
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 40 00 00 00 00 00 00
ipc tx reply : 0x64000000|0x30000038
ipc tx done  : 0x4400000b|0x30000038 [data size:: 56]

ipc tx       : 0x40000010|0x1000a [data size:: 40]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 00 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00
ipc tx reply : 0x60000000|0x1000a
ipc tx done  : 0x40000010|0x1000a [data size:: 40]

ipc tx       : 0x44000010|0x3c80001c [data size:: 28]
Message payload:
00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00
ipc tx reply : 0x64000000|0x3c80001c
ipc tx done  : 0x44000010|0x3c80001c [data size:: 28]

ipc tx       : 0x44000010|0x3000006c [data size:: 108]
Message payload:
6c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 e8 00 00 00 1e
00 00 00 0c d3 4d 62 00 b1 c2 09 04 55 55 55 05
50 fa 1e 00 55 60 94 00 7e 98 6a ff 83 c9 fe 01
64 47 47 22 17 56 74 01 1c c7 71 00 77 77 77 ff
d8 77 1f 00 05 00 00 00 00 80 43 00 d7 7d 04 00
a0 ce 25 00 d7 7d 09 00 b1 b5 00 00
ipc tx reply : 0x64000000|0x3000006c
ipc tx done  : 0x44000010|0x3000006c [data size:: 108]

ipc tx       : 0x40010004|0x10015 [data size:: 84]
Message payload:
00 00 00 00 80 01 00 00 80 01 00 00 01 00 00 00
80 bb 00 00 20 00 00 00 10 ff ff ff 01 00 00 00
00 00 00 00 02 20 01 00 80 bb 00 00 20 00 00 00
10 ff ff ff 01 00 00 00 00 00 00 00 02 20 01 00
00 00 00 00 00 08 00 00 00 03 00 00 01 00 00 00
00 00 00 00
ipc tx reply : 0x60000000|0x10015
ipc tx done  : 0x40010004|0x10015 [data size:: 84]

ipc tx       : 0x45000004|0x6
ipc tx reply : 0x65000000|0x6
ipc tx done  : 0x45000004|0x6

ipc tx       : 0x45000006|0x2
ipc tx reply : 0x65000000|0x2
ipc tx done  : 0x45000006|0x2

ipc tx       : 0x45000002|0x3
ipc tx reply : 0x65000000|0x3
ipc tx done  : 0x45000002|0x3

ipc tx       : 0x45000003|0x10006
ipc tx reply : 0x65000000|0x10006
ipc tx done  : 0x45000003|0x10006

ipc tx       : 0x45010006|0xa
ipc tx reply : 0x65000000|0xa
ipc tx done  : 0x45010006|0xa

ipc tx       : 0x4500000a|0xb
ipc tx reply : 0x65000000|0xb
ipc tx done  : 0x4500000a|0xb

ipc tx       : 0x4500000b|0x10
ipc tx reply : 0x65000000|0x10
ipc tx done  : 0x4500000b|0x10

ipc tx       : 0x45000010|0x10004
ipc tx reply : 0x65000000|0x10004
ipc tx done  : 0x45000010|0x10004

ipc tx       : 0x13010003|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13010003|0x0

ipc tx       : 0x13010004|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13010004|0x0

ipc tx       : 0x13000003|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13000003|0x0

ipc tx       : 0x13000004|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13000004|0x0

ipc tx       : 0x13000003|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13000003|0x0

ipc tx       : 0x13010003|0x0
ipc tx reply : 0x33000000|0x0
ipc tx done  : 0x13010003|0x0

[marc-hb]

Today a question was raised: should this BPF script be hosted in sof-test.git or sof.git?

The most important point to consider for any test code is: how tightly coupled with production code is it? If tightly coupled (e.g.: unit tests), then the test code should live in the same repo, otherwise there will be mismatches and breakages all the time. If very loose then it should live in the separate sof-test.git for flexibility.

The best litmus test is: imagine you're bisecting sof.git. Would you rather this BPF script to downgrade and upgrade at the same time you're bisecting sof? Or not? Which is the more likely? Same idea with branching, rebasing, cherry-picking etc.

As IPC4 is a very stable API, I'm guessing this BPF script should live in sof-test?

[plbossart]

My take is that BPF can provide access to lots of Linux kernel functions, and as such isn't guaranteed to be stable over time. Bisecting with BPF may or may not be possible between different Linux versions.

https://lwn.net/Articles/921088/

That means that if/when there are changes to the kernel, the scripts shall be updated.
We have similar issues with kmod scripts, the names of modules and the list of modules may change over time.

[ujfalusi]

@plbossart, I agree that there is a risk of kernel change breaking the BPF script, I'm proposing to tap on the sof_ipc4_log_header() which is not expected to change (famous last words?).
We can only get the TX message payloads reliably, I'm not sure if there is a way around to get the reply and I don't plan to decode the notification payload.
For the reply payload we might be able to use kretprobe with saving pointer in kprope and then using that to print the received reply payload, but I have not tried that and I find that a bit more risky than the send IPC message traffic.

[marc-hb]

I agree that there is a risk of kernel change breaking the BPF script

Then the ideal git repo for the BPF script would be the kernel repo; that's the one it's most tightly coupled with. But that's not possible because https://thesofproject.github.io/latest/contribute/linux/development_tree.html#development-summary

     +----reject-----------+                      +--------merge----------------+
     |                     |                      |                             |
     v                     |                      v                             |
+----+------+        +-----+-------+       +------+--------+           +--------+----------+
| developer +------->+ SOF reviews +--ok-->+ topic/sof-dev |         +-+ upstream baseline |
| PR        |        | CI tests    |       |               |         | |                   |
+-----------+        +-----+-------+       +------+--------+         | +---------+---------+
                           |                      |                  |           ^
                           |                               +--rebase-+           |
                           |                      |        |             ALSA maintainers ok
                           |                      |        v                     |
                           |           +----------v--------+--+         +--------+----------+
                           |           | topic/sof-dev-rebase +-email-->+    alsa-devel     |
                           |           |                      |         |    mailing list   |
                           |           +----------------------+         +--------+----------+
                           |                                                     ^
                           |                                                     |
                           |                                                     |
                           +-----------------direct path (exceptions)------------+

So is there a "second best" between sof-test.git and sof.git? Maybe not. Maybe they are both equally inferior.

[ujfalusi]

BPF scripts are not part of the kernel tree. Ideally we should have 'trampolines' (iow, stable BPF entries) for proper support then the scripts could be part of sof-bin package.
But we are not planning to support BPF officially and this script is for developers/CI only.

We can also just see how things work with the dmesg dumping...

[plbossart]

I don't think there's a better proposal than using sof-test for those BPF scripts, so unless there's a sustained objection let's go with that direction.

[ujfalusi]

The initial script: #1205

[marc-hb]

We can also just see how things work with the dmesg dumping...

Even if the current script above is just a "works4me" and does not end up being used, it is still better placed in sof-test.git than in a discussion comment.

It's not like sof-test.git has "coverage" requirement for everything in it, pretty far from that. The bar is of course higher for code that is used every day but it is low for demos and prototypes.

How about sof-test/BPFTrace/IPClogs.bpf ? OR something like it.