Re: [PATCH net-next] net: skb: fix kfree_skb event output error in perf

[Eric Dumazet <edumazet@google.com>]

On Fri, Aug 26, 2022 at 8:44 AM Menglong Dong <menglong8.dong@gmail.com> wrote:
>
> On Fri, Aug 26, 2022 at 11:07 PM Eric Dumazet <edumazet@google.com> wrote:
> >
> >
> >
> > On Thu, Aug 25, 2022 at 9:47 PM Menglong Dong <menglong8.dong@gmail.com> wrote:
> >>
> >> On Thu, Aug 25, 2022 at 11:32 PM Eric Dumazet <edumazet@google.com> wrote:
> >> >
> >> > On Wed, Aug 24, 2022 at 10:37 PM <menglong8.dong@gmail.com> wrote:
> >> > >
> >> > > From: Menglong Dong <imagedong@tencent.com>
> >> > >
> >> > > As Eric reported, the 'reason' field is not presented when trace the
> >> > > kfree_skb event by perf:
> >> > >
> >> > > $ perf record -e skb:kfree_skb -a sleep 10
> >> > > $ perf script
> >> > >   ip_defrag 14605 [021]   221.614303:   skb:kfree_skb:
> >> > >   skbaddr=0xffff9d2851242700 protocol=34525 location=0xffffffffa39346b1
> >> > >   reason:
> >> > >
> >> > > The cause seems to be passing kernel address directly to TP_printk(),
> >> > > which is not right.
> >> >
> >> > Why ?
> >> >
> >>
> >> I think it is because of how perf passes data to the user space. From
> >> what 'perf_output_sample()' do, we can know that perf passes the data
> >> of entry (with other data) to the user, and the user generates the output
> >> string from the format string (which can be obtained from
> >> /sys/kernel/debug/tracing/event/skb/kfree_skb/format) and the entry data.
> >>
> >> Therefore, perf can't get the string of drop reasons from the entry, only
> >> the enum.
> >>
> >> > It seems this adds an expensive copy of a string that should reside in
> >> > rodata section of vmlinux, thus can not disappear...
> >> > (Also the ring buffer entry will have a dynamic size ?)
> >> >
> >>
> >> It indeed will add additional cost, but it seems unavoidable. In the old
> >> version, __print_symbolic() is used, which will loop all the drop reason
> >> from a array and find corresponding string:
> >>
> >>     TP_printk("skbaddr=%p protocol=%u location=%p reason: %s",
> >>           __entry->skbaddr, __entry->protocol, __entry->location,
> >>           __print_symbolic(__entry->reason,
> >>                    TRACE_SKB_DROP_REASON))
> >>
> >> And I think the cost of coping strings may be less than this loop? as the
> >> drop reasons are getting more and more.
> >
> >
> > We are back to original feedback about all this stuff.
> >
> > Please measure the tax on a workload dropping 5,000,000 packets per second
> > when/if a "perf -e skb:kfree_skb" is attempted by a clueless admin :)
> >
>
> Okay, I'll do such a test.
>
> > If just using an integer instead of a string has a measurable impact, we probably should stick to an integer.
> >
> > kfree_skb tracing is really for experts, they probably can have a tool to understand what a particular integer value means.
> >
> > Then we can also make sure to only add new values to the end of the enum, to have stable integer values among different kernel versions.
> >
>
> In fact, this is exactly what I wanted to do. Users can get little information
> from the output of perf or ftrace for the kfree_skb event without a
> tools, such as dropwatch.
>
> I keep adding new values to the end of the enum. And I tried to
> make the enum as uapi, as user space tools need the enum to
> understand what the integer values mean. Hmm......that commit
> was rejected :)

I think that your initial proposal was to stuff __FILE__ or __LINE__
which was a no go, because they would require anyone having fresh
kernel source to make any mapping.

Also, we added SKB_NOT_DROPPED_YET in first position in the list.

UAPI would have made this kind of change not possible.

I am not suggesting to make enum skb_drop_reason UAPI, I want this to
be clear :)

>
> I'll do the test to see the impact between integer, string copy and
> __print_symbolic. Then we can decide the solutions.
>
> Thanks!
> Menglong Dong
>
> >>
> >> > trace_safe_str() is using is_kernel_rodata() which should return true
> >> > for drop_reasons[X] ?
> >> >
> >> > $ grep drop_reasons net/core/dropreason_str.c
> >> > const char * const drop_reasons[] = {
> >> > ...
> >> >
> >> >
> >> >
> >> > >
> >> > > Therefore, fix this by adding a '__string' field to the TP_STRUCT of
> >> > > kfree_skb, which is 'reason_str', and passing it to TP_printk().
> >> > >
> >> > > (Not sure if we should still keep the 'reason' field in
> >> > > TP_STRUCT__entry)
> >> >
> >> > Maybe for event/trace filtering purposes ?
> >> >
> >> > >
> >> > > Reported-by: Eric Dumazet <edumazet@google.com>
> >> > > Signed-off-by: Menglong Dong <imagedong@tencent.com>
> >> > > ---
> >> > >  include/trace/events/skb.h | 4 +++-
> >> > >  1 file changed, 3 insertions(+), 1 deletion(-)
> >> > >
> >> > > diff --git a/include/trace/events/skb.h b/include/trace/events/skb.h
> >> > > index 45264e4bb254..7235554141c3 100644
> >> > > --- a/include/trace/events/skb.h
> >> > > +++ b/include/trace/events/skb.h
> >> > > @@ -24,6 +24,7 @@ TRACE_EVENT(kfree_skb,
> >> > >                 __field(void *,         location)
> >> > >                 __field(unsigned short, protocol)
> >> > >                 __field(enum skb_drop_reason,   reason)
> >> > > +               __string(reason_str, drop_reasons[reason])
> >> > >         ),
> >> > >
> >> > >         TP_fast_assign(
> >> > > @@ -31,11 +32,12 @@ TRACE_EVENT(kfree_skb,
> >> > >                 __entry->location = location;
> >> > >                 __entry->protocol = ntohs(skb->protocol);
> >> > >                 __entry->reason = reason;
> >> > > +               __assign_str(reason_str, drop_reasons[reason]);
> >> > >         ),
> >> > >
> >> > >         TP_printk("skbaddr=%p protocol=%u location=%p reason: %s",
> >> > >                   __entry->skbaddr, __entry->protocol, __entry->location,
> >> > > -                 drop_reasons[__entry->reason])
> >> > > +                 __get_str(reason_str))
> >> > >  );
> >> > >
> >> > >  TRACE_EVENT(consume_skb,
> >> > > --
> >> > > 2.37.2
> >> > >