proper struct device selection for dev_printk()

proper struct device selection for dev_printk()

[Greg KH]

Hi Kay,

I've been working on removing the old err() and dbg() functions in usb.h
that have been there since the 2.2 kernel and replace them with calls to
dev_err() and dev_dbg(), as that's what we want to have, especially with
your dev_printk() reworks.

In some recent changes in the input drivers, Dmitry noted that I was
picking the "wrong" struct device to pass to these functions.  I was
using the "farthest down the tree" struct device that I could get to, in
the USB input driver's case, the struct device for the input device, a
"class" device.

But that seems to produce an output that is less than helpful.  Dmitry
used this as an example output to show this for a serio device:
	dev_warn(&input_dev->dev, "warning using input device\n");
	dev_warn(&serio->dev, "warning using parent serio device\n");

Produces:
	[    1.903608] input input6: warning using input device
	[    1.903612] psmouse serio1: warning using parent serio device

Here it seems that the "one up from the lowest struct device" works
best.

So I tried this out with a usb to serial device, and got the following
results.  With the code:
	dev_err(&port->dev, "dev_err port->dev output\n");
	dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
	dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
	dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");

I get:
	[   68.519639] pl2303 ttyUSB0: dev_err port->dev output
	[   68.519645] usb 2-1.2: dev_err serial->dev->dev output
	[   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
	[   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output

All of these "describe" the device being operated on in one fashion or
the other, as they are struct devices that are easily accessable from
the driver.

My question is, what is the "best" thing to be doing here?

I still think the "lowest" struct device would be best (in this case,
the last line above from the port->port.tty->dev pointer), but what do
you think is best for userspace to have here?

And, in my conversions, I've realized that I need wrapper functions for
this for each subsystem, I'm tired of typing long -> -> -> pointer
chains for every debug message, that's madness and fragile to get right,
but that's something that I can work on later.

thanks,

greg k-h

Re: proper struct device selection for dev_printk()

[Dmitry Torokhov]

On Thu, May 03, 2012 at 09:09:37AM -0700, Greg KH wrote:
> Hi Kay,
> 
> I've been working on removing the old err() and dbg() functions in usb.h
> that have been there since the 2.2 kernel and replace them with calls to
> dev_err() and dev_dbg(), as that's what we want to have, especially with
> your dev_printk() reworks.
> 
> In some recent changes in the input drivers, Dmitry noted that I was
> picking the "wrong" struct device to pass to these functions.  I was
> using the "farthest down the tree" struct device that I could get to, in
> the USB input driver's case, the struct device for the input device, a
> "class" device.
> 
> But that seems to produce an output that is less than helpful.  Dmitry
> used this as an example output to show this for a serio device:
> 	dev_warn(&input_dev->dev, "warning using input device\n");
> 	dev_warn(&serio->dev, "warning using parent serio device\n");
> 
> Produces:
> 	[    1.903608] input input6: warning using input device
> 	[    1.903612] psmouse serio1: warning using parent serio device
> 
> Here it seems that the "one up from the lowest struct device" works
> best.
> 
> So I tried this out with a usb to serial device, and got the following
> results.  With the code:
> 	dev_err(&port->dev, "dev_err port->dev output\n");
> 	dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
> 	dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
> 	dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");
> 
> I get:
> 	[   68.519639] pl2303 ttyUSB0: dev_err port->dev output
> 	[   68.519645] usb 2-1.2: dev_err serial->dev->dev output
> 	[   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
> 	[   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output
> 
> All of these "describe" the device being operated on in one fashion or
> the other, as they are struct devices that are easily accessable from
> the driver.
> 
> My question is, what is the "best" thing to be doing here?
> 
> I still think the "lowest" struct device would be best (in this case,
> the last line above from the port->port.tty->dev pointer), but what do
> you think is best for userspace to have here?

My $.02:

In general, drivers should emit messages for the devices they bind to.
This way driver like psmouse (which is serio subsystem driver) will emit
messages using serio port it is bound (or attempting to bind to):

	[    1.903612] psmouse serio1: warning using parent serio device

and drivers like wacom which bind to a USB interface will emit messages
using USB intraface, like:

	[    1.234567] wacom 2-1.2:1.0: some error happened

The benefit of using the device we are binding to is that it allows us
to crearly identify the driver that emits the error and we are using the
same device throughout (leaf device might not have been created yet and
we already need to emit an error or a warning).

Thanks.

-- 
Dmitry

Re: proper struct device selection for dev_printk()

[Alan Stern]

On Thu, 3 May 2012, Dmitry Torokhov wrote:

> On Thu, May 03, 2012 at 09:09:37AM -0700, Greg KH wrote:
> > Hi Kay,
> > 
> > I've been working on removing the old err() and dbg() functions in usb.h
> > that have been there since the 2.2 kernel and replace them with calls to
> > dev_err() and dev_dbg(), as that's what we want to have, especially with
> > your dev_printk() reworks.
> > 
> > In some recent changes in the input drivers, Dmitry noted that I was
> > picking the "wrong" struct device to pass to these functions.  I was
> > using the "farthest down the tree" struct device that I could get to, in
> > the USB input driver's case, the struct device for the input device, a
> > "class" device.
> > 
> > But that seems to produce an output that is less than helpful.  Dmitry
> > used this as an example output to show this for a serio device:
> > 	dev_warn(&input_dev->dev, "warning using input device\n");
> > 	dev_warn(&serio->dev, "warning using parent serio device\n");
> > 
> > Produces:
> > 	[    1.903608] input input6: warning using input device
> > 	[    1.903612] psmouse serio1: warning using parent serio device
> > 
> > Here it seems that the "one up from the lowest struct device" works
> > best.
> > 
> > So I tried this out with a usb to serial device, and got the following
> > results.  With the code:
> > 	dev_err(&port->dev, "dev_err port->dev output\n");
> > 	dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
> > 	dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
> > 	dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");
> > 
> > I get:
> > 	[   68.519639] pl2303 ttyUSB0: dev_err port->dev output
> > 	[   68.519645] usb 2-1.2: dev_err serial->dev->dev output
> > 	[   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
> > 	[   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output
> > 
> > All of these "describe" the device being operated on in one fashion or
> > the other, as they are struct devices that are easily accessable from
> > the driver.
> > 
> > My question is, what is the "best" thing to be doing here?
> > 
> > I still think the "lowest" struct device would be best (in this case,
> > the last line above from the port->port.tty->dev pointer), but what do
> > you think is best for userspace to have here?
> 
> My $.02:
> 
> In general, drivers should emit messages for the devices they bind to.
> This way driver like psmouse (which is serio subsystem driver) will emit
> messages using serio port it is bound (or attempting to bind to):
> 
> 	[    1.903612] psmouse serio1: warning using parent serio device
> 
> and drivers like wacom which bind to a USB interface will emit messages
> using USB intraface, like:
> 
> 	[    1.234567] wacom 2-1.2:1.0: some error happened
> 
> The benefit of using the device we are binding to is that it allows us
> to crearly identify the driver that emits the error and we are using the
> same device throughout (leaf device might not have been created yet and
> we already need to emit an error or a warning).

That's just what I was going to say.

So for example, in the USB-serial example, the

	usb 2-1.2: dev_err serial->dev->dev output

line isn't specific enough because it doesn't say which interface it 
applies to.  The

	tty ttyUSB0: dev_err port->port.tty->dev output

line is appropriate for a message emanating from the tty core, but not 
from a usb-serial driver.

As for the other two:

	pl2303 ttyUSB0: dev_err port->dev output
	pl2303 2-1.2:1.0: dev_err serial->interface->dev output

either one would be okay.  You could choose between them depending on 
what part of the driver is involved.  A part that handles the tty 
functions would use the first and a part that handles the USB 
communication would use the second.

Alan Stern

Re: proper struct device selection for dev_printk()

[Kay Sievers]

On Thu, May 3, 2012 at 7:21 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
> On Thu, 3 May 2012, Dmitry Torokhov wrote:
>> On Thu, May 03, 2012 at 09:09:37AM -0700, Greg KH wrote:
>> > I've been working on removing the old err() and dbg() functions in usb.h
>> > that have been there since the 2.2 kernel and replace them with calls to
>> > dev_err() and dev_dbg(), as that's what we want to have, especially with
>> > your dev_printk() reworks.
>> >
>> > In some recent changes in the input drivers, Dmitry noted that I was
>> > picking the "wrong" struct device to pass to these functions.  I was
>> > using the "farthest down the tree" struct device that I could get to, in
>> > the USB input driver's case, the struct device for the input device, a
>> > "class" device.
>> >
>> > But that seems to produce an output that is less than helpful.  Dmitry
>> > used this as an example output to show this for a serio device:
>> >     dev_warn(&input_dev->dev, "warning using input device\n");
>> >     dev_warn(&serio->dev, "warning using parent serio device\n");
>> >
>> > Produces:
>> >     [    1.903608] input input6: warning using input device
>> >     [    1.903612] psmouse serio1: warning using parent serio device
>> >
>> > Here it seems that the "one up from the lowest struct device" works
>> > best.
>> >
>> > So I tried this out with a usb to serial device, and got the following
>> > results.  With the code:
>> >     dev_err(&port->dev, "dev_err port->dev output\n");
>> >     dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
>> >     dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
>> >     dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");
>> >
>> > I get:
>> >     [   68.519639] pl2303 ttyUSB0: dev_err port->dev output
>> >     [   68.519645] usb 2-1.2: dev_err serial->dev->dev output
>> >     [   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
>> >     [   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output
>> >
>> > All of these "describe" the device being operated on in one fashion or
>> > the other, as they are struct devices that are easily accessable from
>> > the driver.
>> >
>> > My question is, what is the "best" thing to be doing here?
>> >
>> > I still think the "lowest" struct device would be best (in this case,
>> > the last line above from the port->port.tty->dev pointer), but what do
>> > you think is best for userspace to have here?
>>
>> My $.02:
>>
>> In general, drivers should emit messages for the devices they bind to.
>> This way driver like psmouse (which is serio subsystem driver) will emit
>> messages using serio port it is bound (or attempting to bind to):

>> The benefit of using the device we are binding to is that it allows us
>> to crearly identify the driver that emits the error and we are using the
>> same device throughout (leaf device might not have been created yet and
>> we already need to emit an error or a warning).
>
> That's just what I was going to say.
>
> So for example, in the USB-serial example, the
>
>        usb 2-1.2: dev_err serial->dev->dev output
>
> line isn't specific enough because it doesn't say which interface it
> applies to.  The
>
>        tty ttyUSB0: dev_err port->port.tty->dev output
>
> line is appropriate for a message emanating from the tty core, but not
> from a usb-serial driver.
>
> As for the other two:
>
>        pl2303 ttyUSB0: dev_err port->dev output
>        pl2303 2-1.2:1.0: dev_err serial->interface->dev output
>
> either one would be okay.  You could choose between them depending on
> what part of the driver is involved.  A part that handles the tty
> functions would use the first and a part that handles the USB
> communication would use the second.

Well, it's easy for userspace to find the parent devices and the
drivers and the buses of all involved chained parent devices, but
often impossible to find the child device which is interesting, if
only a parent is given.

As long as there is only one child, it might all work to guess that
from userspace, but in general userspace does not care about any bus
devices, but only about the stuff that is visible to userspace.

I don't think such rules about using the parent device can really be
made, regarding the general usefulness of log messages. The driver and
all the kernel internals really does not matter at all for the
(generic) userspace consumption side; all that matters is the device
providing the interface that is accessed by userspace.

In short: "psmouse serio1" is entirely worthless for userspace, unless
you are debugging the kernel input stack; while "event6" is all
userspace cares about and what it can make sense of.

I guess it all depends who is the consumer of the messages, and I
would say if userspace is the intended consumer, always use the device
that provides the access/interface to userspace. It's easy to walk up
the tree and find out about the other things.

If there is no clear definition to make, messages should just be
emitted for the device where the context of the emitted message
applies closest to.

General rules like: always use the parent, or always the bus device,
don't sound right to me.

Kay

Re: proper struct device selection for dev_printk()

[Dmitry Torokhov]

On Thu, May 03, 2012 at 07:50:52PM +0200, Kay Sievers wrote:
> On Thu, May 3, 2012 at 7:21 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
> > On Thu, 3 May 2012, Dmitry Torokhov wrote:
> >> On Thu, May 03, 2012 at 09:09:37AM -0700, Greg KH wrote:
> >> > I've been working on removing the old err() and dbg() functions in usb.h
> >> > that have been there since the 2.2 kernel and replace them with calls to
> >> > dev_err() and dev_dbg(), as that's what we want to have, especially with
> >> > your dev_printk() reworks.
> >> >
> >> > In some recent changes in the input drivers, Dmitry noted that I was
> >> > picking the "wrong" struct device to pass to these functions.  I was
> >> > using the "farthest down the tree" struct device that I could get to, in
> >> > the USB input driver's case, the struct device for the input device, a
> >> > "class" device.
> >> >
> >> > But that seems to produce an output that is less than helpful.  Dmitry
> >> > used this as an example output to show this for a serio device:
> >> >     dev_warn(&input_dev->dev, "warning using input device\n");
> >> >     dev_warn(&serio->dev, "warning using parent serio device\n");
> >> >
> >> > Produces:
> >> >     [    1.903608] input input6: warning using input device
> >> >     [    1.903612] psmouse serio1: warning using parent serio device
> >> >
> >> > Here it seems that the "one up from the lowest struct device" works
> >> > best.
> >> >
> >> > So I tried this out with a usb to serial device, and got the following
> >> > results.  With the code:
> >> >     dev_err(&port->dev, "dev_err port->dev output\n");
> >> >     dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
> >> >     dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
> >> >     dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");
> >> >
> >> > I get:
> >> >     [   68.519639] pl2303 ttyUSB0: dev_err port->dev output
> >> >     [   68.519645] usb 2-1.2: dev_err serial->dev->dev output
> >> >     [   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
> >> >     [   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output
> >> >
> >> > All of these "describe" the device being operated on in one fashion or
> >> > the other, as they are struct devices that are easily accessable from
> >> > the driver.
> >> >
> >> > My question is, what is the "best" thing to be doing here?
> >> >
> >> > I still think the "lowest" struct device would be best (in this case,
> >> > the last line above from the port->port.tty->dev pointer), but what do
> >> > you think is best for userspace to have here?
> >>
> >> My $.02:
> >>
> >> In general, drivers should emit messages for the devices they bind to.
> >> This way driver like psmouse (which is serio subsystem driver) will emit
> >> messages using serio port it is bound (or attempting to bind to):
> 
> >> The benefit of using the device we are binding to is that it allows us
> >> to crearly identify the driver that emits the error and we are using the
> >> same device throughout (leaf device might not have been created yet and
> >> we already need to emit an error or a warning).
> >
> > That's just what I was going to say.
> >
> > So for example, in the USB-serial example, the
> >
> >        usb 2-1.2: dev_err serial->dev->dev output
> >
> > line isn't specific enough because it doesn't say which interface it
> > applies to.  The
> >
> >        tty ttyUSB0: dev_err port->port.tty->dev output
> >
> > line is appropriate for a message emanating from the tty core, but not
> > from a usb-serial driver.
> >
> > As for the other two:
> >
> >        pl2303 ttyUSB0: dev_err port->dev output
> >        pl2303 2-1.2:1.0: dev_err serial->interface->dev output
> >
> > either one would be okay.  You could choose between them depending on
> > what part of the driver is involved.  A part that handles the tty
> > functions would use the first and a part that handles the USB
> > communication would use the second.
> 
> Well, it's easy for userspace to find the parent devices and the
> drivers and the buses of all involved chained parent devices, but
> often impossible to find the child device which is interesting, if
> only a parent is given.
> 
> As long as there is only one child, it might all work to guess that
> from userspace, but in general userspace does not care about any bus
> devices, but only about the stuff that is visible to userspace.
> 
> I don't think such rules about using the parent device can really be
> made, regarding the general usefulness of log messages. The driver and
> all the kernel internals really does not matter at all for the
> (generic) userspace consumption side; all that matters is the device
> providing the interface that is accessed by userspace.
> 
> In short: "psmouse serio1" is entirely worthless for userspace, unless
> you are debugging the kernel input stack; while "event6" is all
> userspace cares about and what it can make sense of.
> 
> I guess it all depends who is the consumer of the messages, and I
> would say if userspace is the intended consumer, always use the device
> that provides the access/interface to userspace. It's easy to walk up
> the tree and find out about the other things.

This would be:

1. Impossible in most cases
2. If it was possible it woudl have to be layer violation.

Taking psmouse as an example you have no idea which interface to use to
report errors - mouse2, event6 or js1 - these are what visible from
userspace and all of them could report to the same input device. We
however know exactly what serio port we had trouble with.

Now consider error happending on i8042 level. Do we descend into
serio layer and reportan error there? Why? Serio layer is perfectly
fine, and besides why would we confuse user that psmouse driver had an
issue whereas it was i8042 that needs to be looked at?

Also, I do not think that vague "userspace" is consumer for these
messages; this is really something a human needs to look at and analyze.

Thanks.

-- 
Dmitry

Re: proper struct device selection for dev_printk()

[Kay Sievers]

On Thu, May 3, 2012 at 8:47 PM, Dmitry Torokhov
<dmitry.torokhov@gmail.com> wrote:
> On Thu, May 03, 2012 at 07:50:52PM +0200, Kay Sievers wrote:

>> I guess it all depends who is the consumer of the messages, and I
>> would say if userspace is the intended consumer, always use the device
>> that provides the access/interface to userspace. It's easy to walk up
>> the tree and find out about the other things.
>
> This would be:
>
> 1. Impossible in most cases
> 2. If it was possible it woudl have to be layer violation.

Yeah, if it would be easy, Greg would not have written the mail. :)

> Taking psmouse as an example you have no idea which interface to use to
> report errors - mouse2, event6 or js1 - these are what visible from
> userspace and all of them could report to the same input device.

True, if the error does not propagate up to the class device, it does
not sound right to do that. But it's still the case that userspace or
any automated message consumer cannot make much sense out of the
message then. It's still targeted at a human.

> We
> however know exactly what serio port we had trouble with.

Sure, if the error occurs in that context, it should be logged with
exactly that context. If it propagates up to the higher devices they
should log themselves.

The point I tried to make was, that we should not in general walk up
to the next bus device for logging, and that the parent devices are
not more useful in general. I wanted to express that a rule like: "In
general, drivers should emit messages for the devices they bind to."
is not the right thing to do, if we *can* establish a context to the
device that is used in userspace.

But sure, if the error can not be propagated to the child devices, we
should not fake anything here either, but the stuff should stay where
it happened.

> Now consider error happending on i8042 level. Do we descend into
> serio layer and reportan error there? Why? Serio layer is perfectly
> fine, and besides why would we confuse user that psmouse driver had an
> issue whereas it was i8042 that needs to be looked at?

As said, it all depends on the intended consumer. Messages about
i8042 devices are not interesting at all for userspace or for
automatic log analysis.

> Also, I do not think that vague "userspace" is consumer for these
> messages; this is really something a human needs to look at and analyze.

Right, they are mainly useful for a human being only. So the attached
metadata does not really matter that much.

Kay

Re: proper struct device selection for dev_printk()

[Greg KH]

On Thu, May 03, 2012 at 09:12:43PM +0200, Kay Sievers wrote:
> On Thu, May 3, 2012 at 8:47 PM, Dmitry Torokhov
> <dmitry.torokhov@gmail.com> wrote:
> > On Thu, May 03, 2012 at 07:50:52PM +0200, Kay Sievers wrote:
> 
> >> I guess it all depends who is the consumer of the messages, and I
> >> would say if userspace is the intended consumer, always use the device
> >> that provides the access/interface to userspace. It's easy to walk up
> >> the tree and find out about the other things.
> >
> > This would be:
> >
> > 1. Impossible in most cases
> > 2. If it was possible it woudl have to be layer violation.
> 
> Yeah, if it would be easy, Greg would not have written the mail. :)
> 
> > Taking psmouse as an example you have no idea which interface to use to
> > report errors - mouse2, event6 or js1 - these are what visible from
> > userspace and all of them could report to the same input device.
> 
> True, if the error does not propagate up to the class device, it does
> not sound right to do that. But it's still the case that userspace or
> any automated message consumer cannot make much sense out of the
> message then. It's still targeted at a human.

Yes, that's the point here, what is a human supposed to do with this?

> > We
> > however know exactly what serio port we had trouble with.
> 
> Sure, if the error occurs in that context, it should be logged with
> exactly that context. If it propagates up to the higher devices they
> should log themselves.
> 
> The point I tried to make was, that we should not in general walk up
> to the next bus device for logging, and that the parent devices are
> not more useful in general. I wanted to express that a rule like: "In
> general, drivers should emit messages for the devices they bind to."
> is not the right thing to do, if we *can* establish a context to the
> device that is used in userspace.
> 
> But sure, if the error can not be propagated to the child devices, we
> should not fake anything here either, but the stuff should stay where
> it happened.

Ok, so it is probably best to use the struct device that the piece of
code has control over.  Which sometimes is not the lowest one, but
sometimes it is.  That's a good rule to go by, thanks everyone.

In my original example, out of:
        dev_err(&port->dev, "dev_err port->dev output\n");
        dev_err(&serial->dev->dev, "dev_err serial->dev->dev output\n");
        dev_err(&serial->interface->dev, "dev_err serial->interface->dev output\n");
        dev_err(port->port.tty->dev, "dev_err port->port.tty->dev output\n");
        [   68.519639] pl2303 ttyUSB0: dev_err port->dev output
        [   68.519645] usb 2-1.2: dev_err serial->dev->dev output
        [   68.519649] pl2303 2-1.2:1.0: dev_err serial->interface->dev output
        [   68.519653] tty ttyUSB0: dev_err port->port.tty->dev output

I will choose the first one, "&port->dev" as that is what the driver
controls at this point in time.  Sometimes, it's only the USB interface
that it knows about (like in the probe() and release() USB callbacks),
but for the most part, it will be consistant.

So, Dmitry, this agrees with your original complaint as well, the input
device isn't the right thing to do, but the USB interface is.  I'll go
rework those patches again (third times a charm, right?) to do it that
way.

thanks,

greg k-h