lkml.org 
[lkml]   [2022]   [Aug]   [26]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
From
Date
SubjectRe: [PATCH net-next] net: skb: fix kfree_skb event output error in perf
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'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
>> > >

\
 
 \ /
  Last update: 2022-08-26 17:44    [W:0.077 / U:0.732 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site