diff mbox series

[v3,3/4] driver core: add dev_print_hex_dump() logging function.

Message ID 20190327014807.7472-4-ronald@innovation.ch (mailing list archive)
State Superseded
Headers show
Series Add Apple SPI keyboard and trackpad driver | expand

Commit Message

Life is hard, and then you die March 27, 2019, 1:48 a.m. UTC
This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
instead of straight printk() to match other dev_xxx() logging functions.
---
 drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
 include/linux/device.h | 15 +++++++++++++++
 2 files changed, 58 insertions(+)

Comments

Greg KH March 27, 2019, 2:37 a.m. UTC | #1
On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> instead of straight printk() to match other dev_xxx() logging functions.
> ---
>  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
>  include/linux/device.h | 15 +++++++++++++++
>  2 files changed, 58 insertions(+)

No signed-off-by?

Anyway, no, please do not do this.  Please do not dump large hex values
like this to the kernel log, it does not help anyone.

You can do this while debugging, sure, but not for "real" kernel code.

Worst case, just create a debugfs file for your device that you can read
the binary data from if you really need it.  For any "normal" operation,
this is not something that you should ever need.

thanks,

greg k-h
Life is hard, and then you die March 28, 2019, 12:28 a.m. UTC | #2
On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > instead of straight printk() to match other dev_xxx() logging functions.
> > ---
> >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> >  include/linux/device.h | 15 +++++++++++++++
> >  2 files changed, 58 insertions(+)
> 
> No signed-off-by?

Aargh! Apologies, fixed for the future.

> Anyway, no, please do not do this.  Please do not dump large hex values
> like this to the kernel log, it does not help anyone.
> 
> You can do this while debugging, sure, but not for "real" kernel code.

As used by this driver, it is definitely called for debugging only and
must be explicitly enabled via a module param. But having the ability
for folks to easily generate and print out debugging info has proven
quite valuable.

> Worst case, just create a debugfs file for your device that you can read
> the binary data from if you really need it.  For any "normal" operation,
> this is not something that you should ever need.

Ok, can do that.

I'll retract the two print_hex_dump related patches then.


  Cheers,

  Ronald
Greg KH March 28, 2019, 5:29 a.m. UTC | #3
On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> 
> On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > instead of straight printk() to match other dev_xxx() logging functions.
> > > ---
> > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > >  include/linux/device.h | 15 +++++++++++++++
> > >  2 files changed, 58 insertions(+)
> > 
> > No signed-off-by?
> 
> Aargh! Apologies, fixed for the future.
> 
> > Anyway, no, please do not do this.  Please do not dump large hex values
> > like this to the kernel log, it does not help anyone.
> > 
> > You can do this while debugging, sure, but not for "real" kernel code.
> 
> As used by this driver, it is definitely called for debugging only and
> must be explicitly enabled via a module param. But having the ability
> for folks to easily generate and print out debugging info has proven
> quite valuable.

We have dynamic debugging, no need for module parameters at all.  This
isn't the 1990's anymore :)

thanks,

greg k-h
Life is hard, and then you die March 28, 2019, 10:27 a.m. UTC | #4
On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > 
> > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > > instead of straight printk() to match other dev_xxx() logging functions.
> > > > ---
> > > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > > >  include/linux/device.h | 15 +++++++++++++++
> > > >  2 files changed, 58 insertions(+)
> > > 
> > > No signed-off-by?
> > 
> > Aargh! Apologies, fixed for the future.
> > 
> > > Anyway, no, please do not do this.  Please do not dump large hex values
> > > like this to the kernel log, it does not help anyone.
> > > 
> > > You can do this while debugging, sure, but not for "real" kernel code.
> > 
> > As used by this driver, it is definitely called for debugging only and
> > must be explicitly enabled via a module param. But having the ability
> > for folks to easily generate and print out debugging info has proven
> > quite valuable.
> 
> We have dynamic debugging, no need for module parameters at all.  This
> isn't the 1990's anymore :)

I am aware of dynamic debugging, but there are several issues with it
from the perspective of the logging I'm doing here (I mentioned these
in response to an earlier review already):

  1. Dynamic debugging can't be enabled at a function or line level on
     the kernel command line, so this means that to debug issues
     during boot you have to enable everything, which can be way too
     verbose

  2. The expressions to enable the individual logging statements are
     quite brittle (in particular the line-based ones) since they
     (may) change any time the code is changed - having stable
     commands to give to users and put in documentation (e.g.
     "echo 0x200 > /sys/module/applespi/parameters/debug") is
     quite valuable.

     One way to work around this would be to put every single logging
     statement in a function of its own, thereby ensuring a stable
     name is associated with each one.

  3. In at least two places we log different types of packets in the
     same lines of code (protected by a "if (log_mask & PKT_TYPE)") -
     dynamic-debug would only allow enabling or disabling logging of
     all packets. This could be worked around by creating a separate
     (but essentially duplicate) logging function for each packet type
     and some lookup table to call the appropriate one. Not very
     pretty IMO, though.

  4. In a couple places we log both the sent command and the received
     response, with the log-mask determining for which types of
     packets to do this. With a log mask there is one bit to set to
     get both logged; with dynamic debugging you'd have to enable the
     writing and receiving parts separately (not a huge deal, but yet
     one place where things are a bit more complicated than
     necessary).

Except for the first, none of these are insurmountable, but together
they don't make dynamic debugging very attractive for this sort of
logging.


  Cheers,

  Ronald
Greg KH March 28, 2019, 11:29 a.m. UTC | #5
On Thu, Mar 28, 2019 at 03:27:55AM -0700, Life is hard, and then you die wrote:
> 
> On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> > On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > > 
> > > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > > > instead of straight printk() to match other dev_xxx() logging functions.
> > > > > ---
> > > > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > > > >  include/linux/device.h | 15 +++++++++++++++
> > > > >  2 files changed, 58 insertions(+)
> > > > 
> > > > No signed-off-by?
> > > 
> > > Aargh! Apologies, fixed for the future.
> > > 
> > > > Anyway, no, please do not do this.  Please do not dump large hex values
> > > > like this to the kernel log, it does not help anyone.
> > > > 
> > > > You can do this while debugging, sure, but not for "real" kernel code.
> > > 
> > > As used by this driver, it is definitely called for debugging only and
> > > must be explicitly enabled via a module param. But having the ability
> > > for folks to easily generate and print out debugging info has proven
> > > quite valuable.
> > 
> > We have dynamic debugging, no need for module parameters at all.  This
> > isn't the 1990's anymore :)
> 
> I am aware of dynamic debugging, but there are several issues with it
> from the perspective of the logging I'm doing here (I mentioned these
> in response to an earlier review already):
> 
>   1. Dynamic debugging can't be enabled at a function or line level on
>      the kernel command line, so this means that to debug issues
>      during boot you have to enable everything, which can be way too
>      verbose

You can, and should enable it at a function or line level by writing to
the proper kernel file in debugfs.

You have read Documentation/admin-guide/dynamic-debug-howto.rst, right?

No need to do anything on the command line, that's so old-school :)

>   2. The expressions to enable the individual logging statements are
>      quite brittle (in particular the line-based ones) since they
>      (may) change any time the code is changed - having stable
>      commands to give to users and put in documentation (e.g.
>      "echo 0x200 > /sys/module/applespi/parameters/debug") is
>      quite valuable.
> 
>      One way to work around this would be to put every single logging
>      statement in a function of its own, thereby ensuring a stable
>      name is associated with each one.

Again, read the documentation, this works today as-is.

>   3. In at least two places we log different types of packets in the
>      same lines of code (protected by a "if (log_mask & PKT_TYPE)") -
>      dynamic-debug would only allow enabling or disabling logging of
>      all packets. This could be worked around by creating a separate
>      (but essentially duplicate) logging function for each packet type
>      and some lookup table to call the appropriate one. Not very
>      pretty IMO, though.

True, but you can use tracepoints as well, that would probably be much
easier when you are logging data streams.  You can also use an ebpf
program with the tracepoints to log just what you need/want to when you
want to as well.

>   4. In a couple places we log both the sent command and the received
>      response, with the log-mask determining for which types of
>      packets to do this. With a log mask there is one bit to set to
>      get both logged; with dynamic debugging you'd have to enable the
>      writing and receiving parts separately (not a huge deal, but yet
>      one place where things are a bit more complicated than
>      necessary).
> 
> Except for the first, none of these are insurmountable, but together
> they don't make dynamic debugging very attractive for this sort of
> logging.

Look into it some more, we have all of this covered today, no need for
just a single driver to do something fancy on its own :)

thanks,

greg k-h
Steven Rostedt March 28, 2019, 12:30 p.m. UTC | #6
On Thu, 28 Mar 2019 12:29:52 +0100
Greg Kroah-Hartman <gregkh@linuxfoundation.org> wrote:

> >   3. In at least two places we log different types of packets in the
> >      same lines of code (protected by a "if (log_mask & PKT_TYPE)") -
> >      dynamic-debug would only allow enabling or disabling logging of
> >      all packets. This could be worked around by creating a separate
> >      (but essentially duplicate) logging function for each packet type
> >      and some lookup table to call the appropriate one. Not very
> >      pretty IMO, though.  
> 
> True, but you can use tracepoints as well, that would probably be much
> easier when you are logging data streams.  You can also use an ebpf
> program with the tracepoints to log just what you need/want to when you
> want to as well.

And tracepoints have filters where you don't even need ebpf to do such
filtering.

See Documentation/trace/events.rst Section 5: Event Filtering

-- Steve
Life is hard, and then you die April 2, 2019, 2:47 a.m. UTC | #7
On Thu, Mar 28, 2019 at 12:29:52PM +0100, Greg Kroah-Hartman wrote:
> On Thu, Mar 28, 2019 at 03:27:55AM -0700, Life is hard, and then you die wrote:
> > 
> > On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> > > On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > > > 
> > > > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > > > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > > > > instead of straight printk() to match other dev_xxx() logging functions.
> > > > > > ---
> > > > > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > > > > >  include/linux/device.h | 15 +++++++++++++++
> > > > > >  2 files changed, 58 insertions(+)
[snip]
> > > > > Anyway, no, please do not do this.  Please do not dump large hex values
> > > > > like this to the kernel log, it does not help anyone.
> > > > > 
> > > > > You can do this while debugging, sure, but not for "real" kernel code.
> > > > 
> > > > As used by this driver, it is definitely called for debugging only and
> > > > must be explicitly enabled via a module param. But having the ability
> > > > for folks to easily generate and print out debugging info has proven
> > > > quite valuable.
> > > 
> > > We have dynamic debugging, no need for module parameters at all.  This
> > > isn't the 1990's anymore :)
> > 
> > I am aware of dynamic debugging, but there are several issues with it
> > from the perspective of the logging I'm doing here (I mentioned these
> > in response to an earlier review already):
> > 
> >   1. Dynamic debugging can't be enabled at a function or line level on
> >      the kernel command line, so this means that to debug issues
> >      during boot you have to enable everything, which can be way too
> >      verbose
> 
> You can, and should enable it at a function or line level by writing to
> the proper kernel file in debugfs.
> 
> You have read Documentation/admin-guide/dynamic-debug-howto.rst, right?

Yes, and I've played with the parameters quite a bit.

> No need to do anything on the command line, that's so old-school :)

Sorry if I'm being unduly dense, but then how to enable debugging
during early boot? The only other alternative I see is modifying the
initrd, and asking folks to do that is noticeably more complicated
than having them add something to the command line in grub. So from my
perspective I find kernel params far from old-school :-)

> >   2. The expressions to enable the individual logging statements are
> >      quite brittle (in particular the line-based ones) since they
> >      (may) change any time the code is changed - having stable
> >      commands to give to users and put in documentation (e.g.
> >      "echo 0x200 > /sys/module/applespi/parameters/debug") is
> >      quite valuable.
> > 
> >      One way to work around this would be to put every single logging
> >      statement in a function of its own, thereby ensuring a stable
> >      name is associated with each one.
> 
> Again, read the documentation, this works today as-is.

I have read it (we're talking about the dynamic debug docs here), but
I just don't see how it addresses this in any way.

> >   3. In at least two places we log different types of packets in the
> >      same lines of code (protected by a "if (log_mask & PKT_TYPE)") -
> >      dynamic-debug would only allow enabling or disabling logging of
> >      all packets. This could be worked around by creating a separate
> >      (but essentially duplicate) logging function for each packet type
> >      and some lookup table to call the appropriate one. Not very
> >      pretty IMO, though.
> 
> True, but you can use tracepoints as well, that would probably be much
> easier when you are logging data streams.  You can also use an ebpf
> program with the tracepoints to log just what you need/want to when you
> want to as well.

Thanks for the hint, I hadn't paid much attention to tracepoints till
now. They do solve most of these issues I've mentioned here, though.
So I've actually gone and implemented the tracing as tracepoints now.
Two issues I noticed though:

 1. since filters can't be enabled on the command line (and yes, we
    seem to disagree on the usefulness of the command line) it means
    I had to essentially create tracepoints for every trace+filter
    combo I may want to enable (in my case it's just one field, so I
    ended up with 8 tracepoints instead of 1). Not a big deal in my
    case, but could get ugly.

 2. in cases where there is relevant log output too, folks have to be
    told to provide both trace and dmesg output, the outputs have to
    merged back together again. Though I note that with the use of the
    tp_printk kernel param this inconvenience goes away again (but
    we're back to logging the traces in the kernel log :-) ).

> >   4. In a couple places we log both the sent command and the received
> >      response, with the log-mask determining for which types of
> >      packets to do this. With a log mask there is one bit to set to
> >      get both logged; with dynamic debugging you'd have to enable the
> >      writing and receiving parts separately (not a huge deal, but yet
> >      one place where things are a bit more complicated than
> >      necessary).
> > 
> > Except for the first, none of these are insurmountable, but together
> > they don't make dynamic debugging very attractive for this sort of
> > logging.
> 
> Look into it some more, we have all of this covered today, no need for
> just a single driver to do something fancy on its own :)

The tracepoints do indeed cover this too.


  Cheers,

  Ronald
Greg KH April 2, 2019, 6:33 a.m. UTC | #8
On Mon, Apr 01, 2019 at 07:47:14PM -0700, Life is hard, and then you die wrote:
> 
> On Thu, Mar 28, 2019 at 12:29:52PM +0100, Greg Kroah-Hartman wrote:
> > On Thu, Mar 28, 2019 at 03:27:55AM -0700, Life is hard, and then you die wrote:
> > > 
> > > On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> > > > On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > > > > 
> > > > > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > > > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > > > > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > > > > > instead of straight printk() to match other dev_xxx() logging functions.
> > > > > > > ---
> > > > > > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > > > > > >  include/linux/device.h | 15 +++++++++++++++
> > > > > > >  2 files changed, 58 insertions(+)
> [snip]
> > > > > > Anyway, no, please do not do this.  Please do not dump large hex values
> > > > > > like this to the kernel log, it does not help anyone.
> > > > > > 
> > > > > > You can do this while debugging, sure, but not for "real" kernel code.
> > > > > 
> > > > > As used by this driver, it is definitely called for debugging only and
> > > > > must be explicitly enabled via a module param. But having the ability
> > > > > for folks to easily generate and print out debugging info has proven
> > > > > quite valuable.
> > > > 
> > > > We have dynamic debugging, no need for module parameters at all.  This
> > > > isn't the 1990's anymore :)
> > > 
> > > I am aware of dynamic debugging, but there are several issues with it
> > > from the perspective of the logging I'm doing here (I mentioned these
> > > in response to an earlier review already):
> > > 
> > >   1. Dynamic debugging can't be enabled at a function or line level on
> > >      the kernel command line, so this means that to debug issues
> > >      during boot you have to enable everything, which can be way too
> > >      verbose
> > 
> > You can, and should enable it at a function or line level by writing to
> > the proper kernel file in debugfs.
> > 
> > You have read Documentation/admin-guide/dynamic-debug-howto.rst, right?
> 
> Yes, and I've played with the parameters quite a bit.
> 
> > No need to do anything on the command line, that's so old-school :)
> 
> Sorry if I'm being unduly dense, but then how to enable debugging
> during early boot? The only other alternative I see is modifying the
> initrd, and asking folks to do that is noticeably more complicated
> than having them add something to the command line in grub. So from my
> perspective I find kernel params far from old-school :-)

You can do dynamic debugging from the kernel command line, if your code
is built into the kernel (but why would a tiny driver under testing like
this, not be built into the kernel?) what specifically did not work for you?

> > >   2. The expressions to enable the individual logging statements are
> > >      quite brittle (in particular the line-based ones) since they
> > >      (may) change any time the code is changed - having stable
> > >      commands to give to users and put in documentation (e.g.
> > >      "echo 0x200 > /sys/module/applespi/parameters/debug") is
> > >      quite valuable.
> > > 
> > >      One way to work around this would be to put every single logging
> > >      statement in a function of its own, thereby ensuring a stable
> > >      name is associated with each one.
> > 
> > Again, read the documentation, this works today as-is.
> 
> I have read it (we're talking about the dynamic debug docs here), but
> I just don't see how it addresses this in any way.

You can enable/disable logging per-function, which is what you want,
right?


Anyway, I'm glad tracepoints work for you, that should be all that is
now needed.

good luck with your driver!

greg k-h
Life is hard, and then you die April 7, 2019, 1:46 a.m. UTC | #9
> On Mon, Apr 01, 2019 at 07:47:14PM -0700, Life is hard, and then you die wrote:
> > 
> > On Thu, Mar 28, 2019 at 12:29:52PM +0100, Greg Kroah-Hartman wrote:
> > > On Thu, Mar 28, 2019 at 03:27:55AM -0700, Life is hard, and then you die wrote:
> > > > 
> > > > On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> > > > > On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > > > > > 
> > > > > > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > > > > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:
> > > > > > > > This is the dev_xxx() analog to print_hex_dump(), using dev_printk()
> > > > > > > > instead of straight printk() to match other dev_xxx() logging functions.
> > > > > > > > ---
> > > > > > > >  drivers/base/core.c    | 43 ++++++++++++++++++++++++++++++++++++++++++
> > > > > > > >  include/linux/device.h | 15 +++++++++++++++
> > > > > > > >  2 files changed, 58 insertions(+)
> > [snip]
> > > > > > > Anyway, no, please do not do this.  Please do not dump large hex values
> > > > > > > like this to the kernel log, it does not help anyone.
> > > > > > > 
> > > > > > > You can do this while debugging, sure, but not for "real" kernel code.
> > > > > > 
> > > > > > As used by this driver, it is definitely called for debugging only and
> > > > > > must be explicitly enabled via a module param. But having the ability
> > > > > > for folks to easily generate and print out debugging info has proven
> > > > > > quite valuable.
> > > > > 
> > > > > We have dynamic debugging, no need for module parameters at all.  This
> > > > > isn't the 1990's anymore :)
> > > > 
> > > > I am aware of dynamic debugging, but there are several issues with it
> > > > from the perspective of the logging I'm doing here (I mentioned these
> > > > in response to an earlier review already):
> > > > 
> > > >   1. Dynamic debugging can't be enabled at a function or line level on
> > > >      the kernel command line, so this means that to debug issues
> > > >      during boot you have to enable everything, which can be way too
> > > >      verbose
> > > 
> > > You can, and should enable it at a function or line level by writing to
> > > the proper kernel file in debugfs.
> > > 
> > > You have read Documentation/admin-guide/dynamic-debug-howto.rst, right?
> > 
> > Yes, and I've played with the parameters quite a bit.
> > 
> > > No need to do anything on the command line, that's so old-school :)
> > 
> > Sorry if I'm being unduly dense, but then how to enable debugging
> > during early boot? The only other alternative I see is modifying the
> > initrd, and asking folks to do that is noticeably more complicated
> > than having them add something to the command line in grub. So from my
> > perspective I find kernel params far from old-school :-)
> 
> You can do dynamic debugging from the kernel command line, if your code
> is built into the kernel (but why would a tiny driver under testing like
> this, not be built into the kernel?) what specifically did not work for you?

This may be part of our disconnect: there's almost no reason (and
several downsides) to building it into the kernel instead of as a
module:

- When developing, being able to just reload the module instead of
  rebooting is just so much faster and more convenient.

- For other users, having them build the driver as a dkms managed
  module is also by far the simplest and least error-prone approach -
  explaning to users how to rebuild their kernel (something most of
  them have never done) takes a bunch of time and effort on both
  sides for essentially no gain.

- Once the driver is part of the regular kernel, practically all
  distro's will build it as a module (at least I'm fairly certain
  about this).

In the case where a problem happens during early boot, if I can
reproduce myself then of course I can build the driver into the kernel
and debug it; but if I need others to test/debug things, then this is
a much harder sell.

In my experience, every time you make something even a little harder
for a user to do, the chance of them doing it and you getting useful
feedback goes down exponentially and the amount of work you need to do
to handhold them goes up significantly. So I think it's absolutely
vital to try and keep things as simple as possible.

> > > >   2. The expressions to enable the individual logging statements are
> > > >      quite brittle (in particular the line-based ones) since they
> > > >      (may) change any time the code is changed - having stable
> > > >      commands to give to users and put in documentation (e.g.
> > > >      "echo 0x200 > /sys/module/applespi/parameters/debug") is
> > > >      quite valuable.
> > > > 
> > > >      One way to work around this would be to put every single logging
> > > >      statement in a function of its own, thereby ensuring a stable
> > > >      name is associated with each one.
> > > 
> > > Again, read the documentation, this works today as-is.
> > 
> > I have read it (we're talking about the dynamic debug docs here), but
> > I just don't see how it addresses this in any way.
> 
> You can enable/disable logging per-function, which is what you want,
> right?

Yes'ish: the problem is that if they are just part of regular
functions, A) the chances are higher that the function may get renamed
and hence any existing debug instructions broken, and B) this doesn't
work if there are multiple debug statements in a function. Hence my
assertion that for this work well (and yes, it can work well) you
basically need to create a separate function for each debug statement
(which that contains just that debug statement) (a sort of stable
labelling of each debug statement).


  Cheers,

  Ronald
Andy Shevchenko April 8, 2019, 12:07 p.m. UTC | #10
On Sat, Apr 06, 2019 at 06:46:13PM -0700, Life is hard, and then you die wrote:
> > On Mon, Apr 01, 2019 at 07:47:14PM -0700, Life is hard, and then you die wrote:
> > > On Thu, Mar 28, 2019 at 12:29:52PM +0100, Greg Kroah-Hartman wrote:
> > > > On Thu, Mar 28, 2019 at 03:27:55AM -0700, Life is hard, and then you die wrote:
> > > > > On Thu, Mar 28, 2019 at 06:29:17AM +0100, Greg Kroah-Hartman wrote:
> > > > > > On Wed, Mar 27, 2019 at 05:28:17PM -0700, Life is hard, and then you die wrote:
> > > > > > > On Wed, Mar 27, 2019 at 11:37:57AM +0900, Greg Kroah-Hartman wrote:
> > > > > > > > On Tue, Mar 26, 2019 at 06:48:06PM -0700, Ronald Tschalär wrote:

> > You can do dynamic debugging from the kernel command line, if your code
> > is built into the kernel (but why would a tiny driver under testing like
> > this, not be built into the kernel?) what specifically did not work for you?
> 
> This may be part of our disconnect: there's almost no reason (and
> several downsides) to building it into the kernel instead of as a
> module:
> 
> - When developing, being able to just reload the module instead of
>   rebooting is just so much faster and more convenient.

modprobe -r foo
modprobe foo dyndbg=...

Not an argument.

> - For other users, having them build the driver as a dkms managed
>   module is also by far the simplest and least error-prone approach -
>   explaning to users how to rebuild their kernel (something most of
>   them have never done) takes a bunch of time and effort on both
>   sides for essentially no gain.
> 
> - Once the driver is part of the regular kernel, practically all
>   distro's will build it as a module (at least I'm fairly certain
>   about this).

Above seems a sub-items to the first one. So, reloading module with dyndbg
parameter is quite flexible. What else?

> > You can enable/disable logging per-function, which is what you want,
> > right?
> 
> Yes'ish: the problem is that if they are just part of regular
> functions, A) the chances are higher that the function may get renamed
> and hence any existing debug instructions broken, and B) this doesn't
> work if there are multiple debug statements in a function. Hence my
> assertion that for this work well (and yes, it can work well) you
> basically need to create a separate function for each debug statement
> (which that contains just that debug statement) (a sort of stable
> labelling of each debug statement).

I guess you tried and have an examples?
diff mbox series

Patch

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 0073b09bb99f..eb260d482750 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -3097,6 +3097,49 @@  define_dev_printk_level(_dev_warn, KERN_WARNING);
 define_dev_printk_level(_dev_notice, KERN_NOTICE);
 define_dev_printk_level(_dev_info, KERN_INFO);
 
+static void
+print_to_dev_printk(const char *level, void *arg, const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+
+	va_start(args, fmt);
+
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	__dev_printk(level, (const struct device *)arg, &vaf);
+
+	va_end(args);
+}
+
+/**
+ * _dev_print_hex_dump - print a text hex dump to syslog for a binary blob of
+ * data
+ * @level: kernel log level (e.g. KERN_DEBUG)
+ * @dev: the device to which this log message pertains
+ * @prefix_str: string to prefix each line with;
+ *  caller supplies trailing spaces for alignment if desired
+ * @prefix_type: controls whether prefix of an offset, address, or none
+ *  is printed (%DUMP_PREFIX_OFFSET, %DUMP_PREFIX_ADDRESS, %DUMP_PREFIX_NONE)
+ * @rowsize: number of bytes to print per line; must be 16 or 32
+ * @groupsize: number of bytes to print at a time (1, 2, 4, 8; default = 1)
+ * @buf: data blob to dump
+ * @len: number of bytes in the @buf
+ * @ascii: include ASCII after the hex output
+ *
+ * See print_hex_dump() for additional details and examples.
+ */
+void _dev_print_hex_dump(const char *level, const struct device *dev,
+			 const char *prefix_str, int prefix_type,
+			 int rowsize, int groupsize,
+			 const void *buf, size_t len, bool ascii)
+{
+	print_hex_dump_to_cb(level, prefix_str, prefix_type, rowsize, groupsize,
+			     buf, len, ascii, print_to_dev_printk, (void *)dev);
+}
+EXPORT_SYMBOL(_dev_print_hex_dump);
+
 #endif
 
 static inline bool fwnode_is_primary(struct fwnode_handle *fwnode)
diff --git a/include/linux/device.h b/include/linux/device.h
index 6cb4640b6160..dc6fcae3002a 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -1405,6 +1405,10 @@  __printf(2, 3)
 void _dev_notice(const struct device *dev, const char *fmt, ...);
 __printf(2, 3)
 void _dev_info(const struct device *dev, const char *fmt, ...);
+void _dev_print_hex_dump(const char *level, const struct device *dev,
+			 const char *prefix_str, int prefix_type,
+			 int rowsize, int groupsize,
+			 const void *buf, size_t len, bool ascii);
 
 #else
 
@@ -1445,6 +1449,12 @@  void _dev_notice(const struct device *dev, const char *fmt, ...)
 static inline __printf(2, 3)
 void _dev_info(const struct device *dev, const char *fmt, ...)
 {}
+static inline
+void _dev_print_hex_dump(const char *level, const struct device *dev,
+			 const char *prefix_str, int prefix_type,
+			 int rowsize, int groupsize,
+			 const void *buf, size_t len, bool ascii);
+{}
 
 #endif
 
@@ -1467,6 +1477,11 @@  void _dev_info(const struct device *dev, const char *fmt, ...)
 	_dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__)
 #define dev_info(dev, fmt, ...)						\
 	_dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__)
+#define dev_print_hex_dump(level, dev, prefix_str, prefix_type,		\
+			   rowsize, groupsize, buf, len, ascii)		\
+	_dev_print_hex_dump(level, dev, dev_fmt(prefix_str),		\
+			    prefix_type, rowsize, groupsize, buf, len,	\
+			    ascii);
 
 #if defined(CONFIG_DYNAMIC_DEBUG)
 #define dev_dbg(dev, fmt, ...)						\