Re: [PATCH bpf-next V2 3/6] selftests/bpf: xdp_hw_metadata RX hash return code info

[Stanislav Fomichev <sdf@google.com>]

On Thu, Mar 23, 2023 at 10:35 AM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Thu, Mar 23, 2023 at 1:51 AM Jesper Dangaard Brouer
> <jbrouer@redhat.com> wrote:
> >
> >
> > On 22/03/2023 20.33, Stanislav Fomichev wrote:
> > > On Wed, Mar 22, 2023 at 12:30 PM Alexei Starovoitov
> > > <alexei.starovoitov@gmail.com> wrote:
> > >>
> > >> On Wed, Mar 22, 2023 at 12:23 PM Stanislav Fomichev <sdf@google.com> wrote:
> > >>>
> > >>> On Wed, Mar 22, 2023 at 12:17 PM Alexei Starovoitov
> > >>> <alexei.starovoitov@gmail.com> wrote:
> > >>>>
> > >>>> On Wed, Mar 22, 2023 at 12:00 PM Stanislav Fomichev <sdf@google.com> wrote:
> > >>>>>
> > >>>>> On Wed, Mar 22, 2023 at 9:07 AM Alexei Starovoitov
> > >>>>> <alexei.starovoitov@gmail.com> wrote:
> > >>>>>>
> > >>>>>> On Wed, Mar 22, 2023 at 9:05 AM Jesper Dangaard Brouer
> > >>>>>> <jbrouer@redhat.com> wrote:
> > >>>>>>>
> > >>>>>>>
> > >>>>>>>
> > >>>>>>> On 21/03/2023 19.47, Stanislav Fomichev wrote:
> > >>>>>>>> On Tue, Mar 21, 2023 at 6:47 AM Jesper Dangaard Brouer
> > >>>>>>>> <brouer@redhat.com> wrote:
> > >>>>>>>>>
> > >>>>>>>>> When driver developers add XDP-hints kfuncs for RX hash it is
> > >>>>>>>>> practical to print the return code in bpf_printk trace pipe log.
> > >>>>>>>>>
> > >>>>>>>>> Print hash value as a hex value, both AF_XDP userspace and bpf_prog,
> > >>>>>>>>> as this makes it easier to spot poor quality hashes.
> > >>>>>>>>>
> > >>>>>>>>> Signed-off-by: Jesper Dangaard Brouer <brouer@redhat.com>
> > >>>>>>>>> ---
> > >>>>>>>>>    .../testing/selftests/bpf/progs/xdp_hw_metadata.c  |    9 ++++++---
> > >>>>>>>>>    tools/testing/selftests/bpf/xdp_hw_metadata.c      |    5 ++++-
> > >>>>>>>>>    2 files changed, 10 insertions(+), 4 deletions(-)
> > >>>>>>>>>
> > >>>>>>>>> diff --git a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
> > >>>>>>>>> index 40c17adbf483..ce07010e4d48 100644
> > >>>>>>>>> --- a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
> > >>>>>>>>> +++ b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
> > >>>>>>>>> @@ -77,10 +77,13 @@ int rx(struct xdp_md *ctx)
> > >>>>>>>>>                   meta->rx_timestamp = 0; /* Used by AF_XDP as not avail signal */
> > >>>>>>>>>           }
> > >>>>>>>>>
> > >>>>>>>>> -       if (!bpf_xdp_metadata_rx_hash(ctx, &meta->rx_hash))
> > >>>>>>>>> -               bpf_printk("populated rx_hash with %u", meta->rx_hash);
> > >>>>>>>>> -       else
> > >>>>>>>>> +       ret = bpf_xdp_metadata_rx_hash(ctx, &meta->rx_hash);
> > >>>>>>>>> +       if (ret >= 0) {
> > >>>>>>>>> +               bpf_printk("populated rx_hash with 0x%08X", meta->rx_hash);
> > >>>>>>>>> +       } else {
> > >>>>>>>>> +               bpf_printk("rx_hash not-avail errno:%d", ret);
> > >>>>>>>>>                   meta->rx_hash = 0; /* Used by AF_XDP as not avail signal */
> > >>>>>>>>> +       }
> > >>>>>>>>>
> > >>>>>>>>>           return bpf_redirect_map(&xsk, ctx->rx_queue_index, XDP_PASS);
> > >>>>>>>>>    }
> > >>>>>>>>> diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c b/tools/testing/selftests/bpf/xdp_hw_metadata.c
> > >>>>>>>>> index 400bfe19abfe..f3ec07ccdc95 100644
> > >>>>>>>>> --- a/tools/testing/selftests/bpf/xdp_hw_metadata.c
> > >>>>>>>>> +++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c
> > >>>>>>>>> @@ -3,6 +3,9 @@
> > >>>>>>>>>    /* Reference program for verifying XDP metadata on real HW. Functional test
> > >>>>>>>>>     * only, doesn't test the performance.
> > >>>>>>>>>     *
> > >>>>>>>>> + * BPF-prog bpf_printk info outout can be access via
> > >>>>>>>>> + * /sys/kernel/debug/tracing/trace_pipe
> > >>>>>>>>
> > >>>>>>>> s/outout/output/
> > >>>>>>>>
> > >>>>>>>
> > >>>>>>> Fixed in V3
> > >>>>>>>
> > >>>>>>>> But let's maybe drop it? If you want to make it more usable, let's
> > >>>>>>>> have a separate patch to enable tracing and periodically dump it to
> > >>>>>>>> the console instead (as previously discussed).
> > >>>>>>>
> > >>>>>>> Cat'ing /sys/kernel/debug/tracing/trace_pipe work for me regardless of
> > >>>>>>> setting in
> > >>>>>>> /sys/kernel/debug/tracing/events/bpf_trace/bpf_trace_printk/enable
> > >>>>>>>
> > >>>>>>> We likely need a followup patch that adds a BPF config switch that can
> > >>>>>>> disable bpf_printk calls, because this adds overhead and thus affects
> > >>>>>>> the timestamps.
> > >>>>>>
> > >>>>>> No. This is by design.
> > >>>>>> Do not use bpf_printk* in production.
> >
> > I fully agree do not use bpf_printk in *production*.
> >
> > >>>>>
> > >>>>> But that's not for the production? xdp_hw_metadata is a small tool to
> > >>>>> verify that the metadata being dumped is correct (during the
> > >>>>> development).
> > >>>>> We have a proper (less verbose) selftest in
> > >>>>> {progs,prog_tests}/xdp_metadata.c (over veth).
> > >>>>> This xdp_hw_metadata was supposed to be used for running it against
> > >>>>> the real hardware, so having as much debugging at hand as possible
> > >>>>> seems helpful? (at least it was helpful to me when playing with mlx4)
> >
> > My experience when developing these kfuncs for igc (real hardware), this
> > "tool" xdp_hw_metadata was super helpful, because it was very verbose
> > (and I was juggling reading chip registers BE/LE and see patch1 a buggy
> > implementation for RX-hash).
> >
> > As I wrote in cover-letter, I recommend other driver developers to do
> > the same, because it really help speed up the development. In theory
> > xdp_hw_metadata doesn't belong in selftests directory and IMHO it should
> > have been placed in samples/bpf/, but given the relationship with real
> > selftest {progs,prog_tests}/xdp_metadata.c I think it makes sense to
> > keep here.
> >
> >
> > >>>>
> > >>>> The only use of bpf_printk is for debugging of bpf progs themselves.
> > >>>> It should not be used in any tool.
> > >>>
> > >>> Hmm, good point. I guess it also means we won't have to mess with
> > >>> enabling/dumping ftrace (and don't need this comment about cat'ing the
> > >>> file).
> > >>> Jesper, maybe we can instead pass the status of those
> > >>> bpf_xdp_metadata_xxx kfuncs via 'struct xdp_meta'? And dump this info
> > >>> from the userspace if needed.
> > >>
> > >> There are so many other ways for bpf prog to communicate with user space.
> > >> Use ringbuf, perf_event buffer, global vars, maps, etc.
> > >> trace_pipe is debug only because it's global and will conflict with
> > >> all other debug sessions.
> >
> > I want to highlight above paragraph: It is very true for production
> > code. (Anyone Googling this pay attention to above paragraph).
> >
> > >
> > > 👍 makes sense, ty! hopefully we won't have to add a separate channel
> > > for those and can (ab)use the metadata area.
> > >
> >
> > Proposed solution: How about default disabling the bpf_printk's via a
> > macro define, and then driver developer can manually reenable them
> > easily via a single define, to enable a debugging mode.
> >
> > I was only watching /sys/kernel/debug/tracing/trace_pipe when I was
> > debugging a driver issue.  Thus, an extra step of modifying a single
> > define in BPF seems easier, than instrumenting my driver with printk.
>
> It's certainly fine to have commented out bpf_printk in selftests
> and sample code.
> But the patch does:
> +       if (ret >= 0) {
> +               bpf_printk("populated rx_hash with 0x%08X", meta->rx_hash);
> +       } else {
> +               bpf_printk("rx_hash not-avail errno:%d", ret);
>                 meta->rx_hash = 0; /* Used by AF_XDP as not avail signal */
> +       }
>
> It feels that printk is the only thing that provides the signal to the user.
> Doing s/ret >= 0/true/ won't make any difference to selftest and
> to the consumer and that's my main concern with such selftest/samples.

I agree, having this signal delivered to the user (without the ifdefs)
seems like a better way to go.
Seems trivial to do something like the following below? (untested,
doesn't compile, gmail-copy-pasted so don't try to apply it)

diff --git a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
index 4c55b4d79d3d..061c410f68ea 100644
--- a/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
+++ b/tools/testing/selftests/bpf/progs/xdp_hw_metadata.c
@@ -12,6 +12,9 @@ struct {
  __type(value, __u32);
 } xsk SEC(".maps");

+int received;
+int dropped;
+
 extern int bpf_xdp_metadata_rx_timestamp(const struct xdp_md *ctx,
  __u64 *timestamp) __ksym;
 extern int bpf_xdp_metadata_rx_hash(const struct xdp_md *ctx,
@@ -52,11 +55,11 @@ int rx(struct xdp_md *ctx)
  if (udp->dest != bpf_htons(9091))
  return XDP_PASS;

- bpf_printk("forwarding UDP:9091 to AF_XDP");
+ __sync_fetch_and_add(&received, 1);

  ret = bpf_xdp_adjust_meta(ctx, -(int)sizeof(struct xdp_meta));
  if (ret != 0) {
- bpf_printk("bpf_xdp_adjust_meta returned %d", ret);
+ __sync_fetch_and_add(&dropped, 1);
  return XDP_PASS;
  }

@@ -65,19 +68,12 @@ int rx(struct xdp_md *ctx)
  meta = data_meta;

  if (meta + 1 > data) {
- bpf_printk("bpf_xdp_adjust_meta doesn't appear to work");
+ __sync_fetch_and_add(&dropped, 1);
  return XDP_PASS;
  }

- if (!bpf_xdp_metadata_rx_timestamp(ctx, &meta->rx_timestamp))
- bpf_printk("populated rx_timestamp with %llu", meta->rx_timestamp);
- else
- meta->rx_timestamp = 0; /* Used by AF_XDP as not avail signal */
-
- if (!bpf_xdp_metadata_rx_hash(ctx, &meta->rx_hash))
- bpf_printk("populated rx_hash with %u", meta->rx_hash);
- else
- meta->rx_hash = 0; /* Used by AF_XDP as not avail signal */
+ meta->rx_timestamp_ret = bpf_xdp_metadata_rx_timestamp(ctx,
&meta->rx_timestamp);
+ meta->rx_hash_ret = bpf_xdp_metadata_rx_hash(ctx, &meta->rx_hash);

  return bpf_redirect_map(&xsk, ctx->rx_queue_index, XDP_PASS);
 }
diff --git a/tools/testing/selftests/bpf/xdp_hw_metadata.c
b/tools/testing/selftests/bpf/xdp_hw_metadata.c
index 1c8acb68b977..a4ea742547b5 100644
--- a/tools/testing/selftests/bpf/xdp_hw_metadata.c
+++ b/tools/testing/selftests/bpf/xdp_hw_metadata.c
@@ -140,8 +140,17 @@ static void verify_xdp_metadata(void *data)

  meta = data - sizeof(*meta);

- printf("rx_timestamp: %llu\n", meta->rx_timestamp);
- printf("rx_hash: %u\n", meta->rx_hash);
+ printf("received: %d dropped: %d\n", obj->xxx->received, obj->xxx->dropped);
+
+ if (meta->rx_timestamp_ret)
+ printf("rx_timestamp errno: %d\n", meta->rx_timestamp_ret);
+ else
+ printf("rx_timestamp: %llu\n", meta->rx_timestamp);
+
+ if (meta->rx_hash_ret)
+ printf("rx_hash errno: %d\n", meta->rx_hash_ret);
+ else
+ printf("rx_hash: %u\n", meta->rx_hash);
 }

 static void verify_skb_metadata(int fd)
diff --git a/tools/testing/selftests/bpf/xdp_metadata.h
b/tools/testing/selftests/bpf/xdp_metadata.h
index f6780fbb0a21..179f8d902059 100644
--- a/tools/testing/selftests/bpf/xdp_metadata.h
+++ b/tools/testing/selftests/bpf/xdp_metadata.h
@@ -10,6 +10,8 @@
 #endif

 struct xdp_meta {
+ int rx_timestamp_ret;
  __u64 rx_timestamp;
+ int rx_hash_ret;
  __u32 rx_hash;
 };