diff mbox series

[v2,bpf-next,2/2] selftests/bpf: add selftests verifying bpf_trace_printk() behaviour

Message ID 1594390953-31757-3-git-send-email-alan.maguire@oracle.com
State Changes Requested
Delegated to: BPF Maintainers
Headers show
Series bpf: fix use of trace_printk() in BPF | expand

Commit Message

Alan Maguire July 10, 2020, 2:22 p.m. UTC 
Simple selftests that verifies bpf_trace_printk() returns a sensible
value and tracing messages appear.

Signed-off-by: Alan Maguire <alan.maguire@oracle.com>
---
 .../selftests/bpf/prog_tests/trace_printk.c        | 74 ++++++++++++++++++++++
 tools/testing/selftests/bpf/progs/trace_printk.c   | 21 ++++++
 2 files changed, 95 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_printk.c
 create mode 100644 tools/testing/selftests/bpf/progs/trace_printk.c

Comments

Andrii Nakryiko July 10, 2020, 8:55 p.m. UTC | #1 
On Fri, Jul 10, 2020 at 7:25 AM Alan Maguire <alan.maguire@oracle.com> wrote:
>
> Simple selftests that verifies bpf_trace_printk() returns a sensible
> value and tracing messages appear.
>
> Signed-off-by: Alan Maguire <alan.maguire@oracle.com>
> ---

see pedantic note below, but I don't think that's an issue in practice

Acked-by: Andrii Nakryiko <andriin@fb.com>

>  .../selftests/bpf/prog_tests/trace_printk.c        | 74 ++++++++++++++++++++++
>  tools/testing/selftests/bpf/progs/trace_printk.c   | 21 ++++++
>  2 files changed, 95 insertions(+)
>  create mode 100644 tools/testing/selftests/bpf/prog_tests/trace_printk.c
>  create mode 100644 tools/testing/selftests/bpf/progs/trace_printk.c
>

[...]

> +
> +       /* verify our search string is in the trace buffer */
> +       while (read(fd, buf, sizeof(buf)) >= 0 || errno == EAGAIN) {

There is a minor chance that "testing,testing" won't be found, if it
so happened that the first part is in the first read buffer, and the
second is in the second. I don't think it's ever the case for our CI
and for my local testing setup, but could be a cause of some
instability if there is something else emitting data to trace_pipe,
right?

Maybe line-based reading would be more reliable (unless printk can
intermix, not sure about that, in which case there is simply no way to
solve this 100% reliably).


> +               if (strstr(buf, SEARCHMSG) != NULL)
> +                       found++;
> +               if (found == bss->trace_printk_ran)
> +                       break;
> +               if (++iter > 1000)
> +                       break;
> +       }
> +
> +       if (CHECK(!found, "message from bpf_trace_printk not found",
> +                 "no instance of %s in %s", SEARCHMSG, TRACEBUF))
> +               goto cleanup;
> +
> +       printf("ran %d times; last return value %d, with %d instances of msg\n",
> +              bss->trace_printk_ran, bss->trace_printk_ret, found);

Is this needed or it's some debug leftover?

> +cleanup:
> +       trace_printk__destroy(skel);
> +       if (fd != -1)
> +               close(fd);
> +}

[...]
diff mbox series

Patch

diff --git a/tools/testing/selftests/bpf/prog_tests/trace_printk.c b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
new file mode 100644
index 0000000..25dd0f47
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/trace_printk.c
@@ -0,0 +1,74 @@ 
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2020, Oracle and/or its affiliates. */
+
+#include <test_progs.h>
+
+#include "trace_printk.skel.h"
+
+#define TRACEBUF	"/sys/kernel/debug/tracing/trace_pipe"
+#define SEARCHMSG	"testing,testing"
+
+void test_trace_printk(void)
+{
+	int err, iter = 0, duration = 0, found = 0, fd = -1;
+	struct trace_printk__bss *bss;
+	struct trace_printk *skel;
+	char buf[1024];
+
+	skel = trace_printk__open();
+	if (CHECK(!skel, "skel_open", "failed to open skeleton\n"))
+		return;
+
+	err = trace_printk__load(skel);
+	if (CHECK(err, "skel_load", "failed to load skeleton: %d\n", err))
+		goto cleanup;
+
+	bss = skel->bss;
+
+	err = trace_printk__attach(skel);
+	if (CHECK(err, "skel_attach", "skeleton attach failed: %d\n", err))
+		goto cleanup;
+
+	fd = open(TRACEBUF, O_RDONLY);
+	if (CHECK(fd < 0, "could not open trace buffer",
+		  "error %d opening %s", errno, TRACEBUF))
+		goto cleanup;
+
+	/* We do not want to wait forever if this test fails... */
+	fcntl(fd, F_SETFL, O_NONBLOCK);
+
+	/* wait for tracepoint to trigger */
+	usleep(1);
+	trace_printk__detach(skel);
+
+	if (CHECK(bss->trace_printk_ran == 0,
+		  "bpf_trace_printk never ran",
+		  "ran == %d", bss->trace_printk_ran))
+		goto cleanup;
+
+	if (CHECK(bss->trace_printk_ret <= 0,
+		  "bpf_trace_printk returned <= 0 value",
+		  "got %d", bss->trace_printk_ret))
+		goto cleanup;
+
+	/* verify our search string is in the trace buffer */
+	while (read(fd, buf, sizeof(buf)) >= 0 || errno == EAGAIN) {
+		if (strstr(buf, SEARCHMSG) != NULL)
+			found++;
+		if (found == bss->trace_printk_ran)
+			break;
+		if (++iter > 1000)
+			break;
+	}
+
+	if (CHECK(!found, "message from bpf_trace_printk not found",
+		  "no instance of %s in %s", SEARCHMSG, TRACEBUF))
+		goto cleanup;
+
+	printf("ran %d times; last return value %d, with %d instances of msg\n",
+	       bss->trace_printk_ran, bss->trace_printk_ret, found);
+cleanup:
+	trace_printk__destroy(skel);
+	if (fd != -1)
+		close(fd);
+}
diff --git a/tools/testing/selftests/bpf/progs/trace_printk.c b/tools/testing/selftests/bpf/progs/trace_printk.c
new file mode 100644
index 0000000..8ca7f39
--- /dev/null
+++ b/tools/testing/selftests/bpf/progs/trace_printk.c
@@ -0,0 +1,21 @@ 
+// SPDX-License-Identifier: GPL-2.0
+// Copyright (c) 2020, Oracle and/or its affiliates.
+
+#include "vmlinux.h"
+#include <bpf/bpf_helpers.h>
+#include <bpf/bpf_tracing.h>
+
+char _license[] SEC("license") = "GPL";
+
+int trace_printk_ret = 0;
+int trace_printk_ran = 0;
+
+SEC("tp/raw_syscalls/sys_enter")
+int sys_enter(void *ctx)
+{
+	static const char fmt[] = "testing,testing %d\n";
+
+	trace_printk_ret = bpf_trace_printk(fmt, sizeof(fmt),
+					    ++trace_printk_ran);
+	return 0;
+}