Re: [PATCH v3 bpf-next 4/8] printk: add type-printing %pT format specifier which uses BTF

[Alan Maguire]

On Fri, 26 Jun 2020, Petr Mladek wrote:

> On Tue 2020-06-23 13:07:07, Alan Maguire wrote:
> > printk supports multiple pointer object type specifiers (printing
> > netdev features etc).  Extend this support using BTF to cover
> > arbitrary types.  "%pT" specifies the typed format, and the pointer
> > argument is a "struct btf_ptr *" where struct btf_ptr is as follows:
> > 
> > struct btf_ptr {
> >         void *ptr;
> >         const char *type;
> >         u32 id;
> > };
> > 
> > Either the "type" string ("struct sk_buff") or the BTF "id" can be
> > used to identify the type to use in displaying the associated "ptr"
> > value.  A convenience function to create and point at the struct
> > is provided:
> > 
> >         printk(KERN_INFO "%pT", BTF_PTR_TYPE(skb, struct sk_buff));
> > 
> > When invoked, BTF information is used to traverse the sk_buff *
> > and display it.  Support is present for structs, unions, enums,
> > typedefs and core types (though in the latter case there's not
> > much value in using this feature of course).
> > 
> > Default output is indented, but compact output can be specified
> > via the 'c' option.  Type names/member values can be suppressed
> > using the 'N' option.  Zero values are not displayed by default
> > but can be using the '0' option.  Pointer values are obfuscated
> > unless the 'x' option is specified.  As an example:
> > 
> >   struct sk_buff *skb = alloc_skb(64, GFP_KERNEL);
> >   pr_info("%pT", BTF_PTR_TYPE(skb, struct sk_buff));
> > 
> > ...gives us:
> > 
> > (struct sk_buff){
> >  .transport_header = (__u16)65535,
> >  .mac_header = (__u16)65535,
> >  .end = (sk_buff_data_t)192,
> >  .head = (unsigned char *)0x000000006b71155a,
> >  .data = (unsigned char *)0x000000006b71155a,
> >  .truesize = (unsigned int)768,
> >  .users = (refcount_t){
> >   .refs = (atomic_t){
> >    .counter = (int)1,
> >   },
> >  },
> >  .extensions = (struct skb_ext *)0x00000000f486a130,
> > }
> > 
> > printk output is truncated at 1024 bytes.  For cases where overflow
> > is likely, the compact/no type names display modes may be used.
> 
> Hmm, this scares me:
> 
>    1. The long message and many lines are going to stretch printk
>       design in another dimensions.
> 
>    2. vsprintf() is important for debugging the system. It has to be
>       stable. But the btf code is too complex.
>

Right on both points, and there's no way around that really. Representing 
even small data structures will stretch us to or beyond the 1024 byte 
limit.  This can be mitigated by using compact display mode and not 
printing field names, but the output becomes hard to parse then.

I think a better approach might be to start small, adding the core
btf_show functionality to BPF, allowing consumers to use it there,
perhaps via a custom helper. In the current model bpf_trace_printk()
inherits the functionality to display data from core printk, so a
different approach would be needed there.  Other consumers outside of BPF
could potentially avail of the show functionality directly via the btf_show
functions in the future, but at least it would have one consumer at the 
outset, and wouldn't present problems like these for printk.
 
> I would strongly prefer to keep this outside vsprintf and printk.
> Please, invert the logic and convert it into using separate printk()
> call for each printed line.
> 

I think the above is in line with what you're suggesting?

> 
> More details:
> 
> Add 1: Long messages with many lines:
> 
>   IMHO, all existing printk() users are far below this limit. And this is
>   even worse because there are many short lines. They would require
>   double space to add prefixes (loglevel, timestamp, caller id) when
>   printing to console.
> 
>   You might argue that 1024bytes are enough for you. But for how long?
> 
>   Now, we have huge troubles to make printk() lockless and thus more
>   reliable. There is no way to allocate any internal buffers
>   dynamically. People using kernel on small devices have problem
>   with large static buffers.
> 
>   printk() is primary designed to print single line messages. There are
>   many use cases where many lines are needed and they are solved by
>   many separate printk() calls.
> 
> 
> Add 2: Complex code:
> 
>   vsprintf() is currently called in printk() under logbuf_lock. It
>   might block printk() on the entire system.
> 
>   Most existing %p<modifier> handlers are implemented by relatively
>   simple routines inside lib/vsprinf.c. The other external routines
>   look simple as well.
> 
>   btf looks like a huge beast to me. For example, probe_kernel_read()
>   prevented boot recently, see the commit 2ac5a3bf7042a1c4abb
>   ("vsprintf: Do not break early boot with probing addresses").
> 
> 

Yep, no way round this either. I'll try a different approach. Thanks for 
taking a look!

Alan

> Best Regards,
> Petr
>