diff mbox series

[RFC,1/1] v4l: async: Add some debug prints

Message ID 20230209221634.35239-1-sakari.ailus@linux.intel.com (mailing list archive)
State New, archived
Headers show
Series [RFC,1/1] v4l: async: Add some debug prints | expand

Commit Message

Sakari Ailus Feb. 9, 2023, 10:16 p.m. UTC
Just add some debug prints for V4L2 async sub-device matching process. These
might come useful in figuring out why things don't work as expected.

Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
---
Frieder,

Can you try this? It prints what is being matched with what. Perhaps this
could be merged in a bit more refined form if it proves useful.

Not tested in any way.

 drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
 1 file changed, 36 insertions(+), 5 deletions(-)

Comments

Laurent Pinchart Feb. 9, 2023, 10:34 p.m. UTC | #1
Hi Sakari,

Thank you for the patch.

On Fri, Feb 10, 2023 at 12:16:34AM +0200, Sakari Ailus wrote:
> Just add some debug prints for V4L2 async sub-device matching process. These
> might come useful in figuring out why things don't work as expected.
> 
> Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> ---
> Frieder,
> 
> Can you try this? It prints what is being matched with what. Perhaps this
> could be merged in a bit more refined form if it proves useful.
> 
> Not tested in any way.
> 
>  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
>  1 file changed, 36 insertions(+), 5 deletions(-)
> 
> diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> index 2f1b718a9189..6c13a9488415 100644
> --- a/drivers/media/v4l2-core/v4l2-async.c
> +++ b/drivers/media/v4l2-core/v4l2-async.c
> @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  	bool sd_fwnode_is_ep;
>  	struct device *dev;
>  
> +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> +		asd->match.fwnode);

Let's be more explicit:

	dev_dbg(sd->dev, "async fwnode match: need %pfw, trying %pfw\n",
		sd_fwnode, asd->match.fwnode);

(feel free to adjust, as long as we differentiate what we're looking for
from what we're testing)

> +
>  	/*
>  	 * Both the subdev and the async subdev can provide either an endpoint
>  	 * fwnode or a device fwnode. Start with the simple case of direct
>  	 * fwnode matching.
>  	 */
> -	if (sd_fwnode == asd->match.fwnode)
> +	if (sd_fwnode == asd->match.fwnode) {
> +		dev_dbg(sd->dev, "true\n");

		dev_dbg(sd->dev, "direct match found\n");

>  		return true;
> +	}
>  
>  	/*
>  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
>  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
>  
> -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> +		asd->match.fwnode);

You've already printed this above, no need to repeat it.

> +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> +		dev_dbg(sd->dev, "unmatching node types (false)\n");

		dev_dbg(sd->dev, "direct match not found\n");

>  		return false;
> +	}
>  
>  	/*
>  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  		other_fwnode = sd_fwnode;
>  	}
>  
> +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> +		dev_fwnode, other_fwnode);

Same comment as above regarding "vs." not telling which is which.

> +
>  	fwnode_handle_put(dev_fwnode);
>  
> -	if (dev_fwnode != other_fwnode)
> +	if (dev_fwnode != other_fwnode) {
> +		dev_dbg(sd->dev, "false\n");

		dev_dbg(sd->dev, "compat match not found\n");

>  		return false;
> +	}
>  
>  	/*
>  	 * We have a heterogeneous match. Retrieve the struct device of the side
> @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  			   dev->driver->name);
>  	}
>  
> +	dev_dbg(sd->dev, "true\n");

	dev_dbg(sd->dev, "compat match found\n");

> +
>  	return true;
>  }
>  
> @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
>  			v4l2_async_find_subdev_notifier(sd);
>  
>  		if (subdev_notifier &&
> -		    !v4l2_async_nf_can_complete(subdev_notifier))
> +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> +			if (subdev_notifier->sd)
> +				deb_dbg(subdev_notifier->sd->dev,
> +					"cannot complete\n");

I'd add a reference to v4l2-async, either directly in the string, or
with a "%s: ", __func__ prefix. Otherwise the message will be easy to
miss. Same in other messages. Maybe a "v4l2-async: " prefix for all
debug messages ?

>  			return false;
>  	}
>  
> @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
>  	if (!list_empty(&notifier->waiting))
>  		return 0;
>  
> +	if (notifier->sd)
> +		deb_dbg(notifier->sd->dev, "trying to complete\n");
> +
>  	/* Check the entire notifier tree; find the root notifier first. */
>  	while (notifier->parent)
>  		notifier = notifier->parent;
>  
>  	/* This is root if it has v4l2_dev. */
> -	if (!notifier->v4l2_dev)
> +	if (!notifier->v4l2_dev) {
> +		if (notifier->sd)
> +			deb_dbg(notifier->sd->dev,
> +				"V4L2 device not available\n");
>  		return 0;
> +	}
>  
>  	/* Is everything ready? */
>  	if (!v4l2_async_nf_can_complete(notifier))
>  		return 0;
>  
> +	deb_dbg(notifier->sd->dev, "complete\n");

You guard against notifier->sd being NULL above, but not here. At least
one of the two is wrong.

> +
>  	return v4l2_async_nf_call_complete(notifier);
>  }
>  
> @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
>  			continue;
>  
>  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
> +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> +			ret);
>  		if (ret < 0)
>  			return ret;
>
Frieder Schrempf Feb. 14, 2023, 10:25 a.m. UTC | #2
Hi Sakari,

On 09.02.23 23:16, Sakari Ailus wrote:
> Just add some debug prints for V4L2 async sub-device matching process. These
> might come useful in figuring out why things don't work as expected.
> 
> Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> ---
> Frieder,
> 
> Can you try this? It prints what is being matched with what. Perhaps this
> could be merged in a bit more refined form if it proves useful.
> 
> Not tested in any way.
> 

Thanks for the patch!

I fixed a few issues (see below) and gave this patch a try. Though in my
case it doesn't seem to help much as the problem is somewhere before the
matching actually happens. The only output from this patch I get is:

[    1.536479] imx219 1-0010: trying to complete
[    1.540856] imx219 1-0010: V4L2 device not available

Thanks
Frieder

>  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
>  1 file changed, 36 insertions(+), 5 deletions(-)
> 
> diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> index 2f1b718a9189..6c13a9488415 100644
> --- a/drivers/media/v4l2-core/v4l2-async.c
> +++ b/drivers/media/v4l2-core/v4l2-async.c
> @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  	bool sd_fwnode_is_ep;
>  	struct device *dev;
>  
> +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> +		asd->match.fwnode);
> +
>  	/*
>  	 * Both the subdev and the async subdev can provide either an endpoint
>  	 * fwnode or a device fwnode. Start with the simple case of direct
>  	 * fwnode matching.
>  	 */
> -	if (sd_fwnode == asd->match.fwnode)
> +	if (sd_fwnode == asd->match.fwnode) {
> +		dev_dbg(sd->dev, "true\n");
>  		return true;
> +	}
>  
>  	/*
>  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
>  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
>  
> -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> +		asd->match.fwnode);
> +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> +		dev_dbg(sd->dev, "unmatching node types (false)\n");
>  		return false;
> +	}
>  
>  	/*
>  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  		other_fwnode = sd_fwnode;
>  	}
>  
> +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> +		dev_fwnode, other_fwnode);
> +
>  	fwnode_handle_put(dev_fwnode);
>  
> -	if (dev_fwnode != other_fwnode)
> +	if (dev_fwnode != other_fwnode) {
> +		dev_dbg(sd->dev, "false\n");
>  		return false;
> +	}
>  
>  	/*
>  	 * We have a heterogeneous match. Retrieve the struct device of the side
> @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
>  			   dev->driver->name);
>  	}
>  
> +	dev_dbg(sd->dev, "true\n");
> +
>  	return true;
>  }
>  
> @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
>  			v4l2_async_find_subdev_notifier(sd);
>  
>  		if (subdev_notifier &&
> -		    !v4l2_async_nf_can_complete(subdev_notifier))
> +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> +			if (subdev_notifier->sd)
> +				deb_dbg(subdev_notifier->sd->dev,

dev_dbg()

> +					"cannot complete\n");
>  			return false;

missing }

>  	}
>  
> @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
>  	if (!list_empty(&notifier->waiting))
>  		return 0;
>  
> +	if (notifier->sd)
> +		deb_dbg(notifier->sd->dev, "trying to complete\n");

dev_dbg()

> +
>  	/* Check the entire notifier tree; find the root notifier first. */
>  	while (notifier->parent)
>  		notifier = notifier->parent;
>  
>  	/* This is root if it has v4l2_dev. */
> -	if (!notifier->v4l2_dev)
> +	if (!notifier->v4l2_dev) {
> +		if (notifier->sd)
> +			deb_dbg(notifier->sd->dev,

dev_dbg()

> +				"V4L2 device not available\n");
>  		return 0;
> +	}
>  
>  	/* Is everything ready? */
>  	if (!v4l2_async_nf_can_complete(notifier))
>  		return 0;
>  
> +	deb_dbg(notifier->sd->dev, "complete\n");

missing guard "if (notifier->sd)"
dev_dbg()

> +
>  	return v4l2_async_nf_call_complete(notifier);
>  }
>  
> @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
>  			continue;
>  
>  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",

dev_dbg()

> +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> +			ret);
>  		if (ret < 0)
>  			return ret;
>
Sakari Ailus Feb. 14, 2023, 2:56 p.m. UTC | #3
On Tue, Feb 14, 2023 at 11:25:20AM +0100, Frieder Schrempf wrote:
> Hi Sakari,
> 
> On 09.02.23 23:16, Sakari Ailus wrote:
> > Just add some debug prints for V4L2 async sub-device matching process. These
> > might come useful in figuring out why things don't work as expected.
> > 
> > Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> > ---
> > Frieder,
> > 
> > Can you try this? It prints what is being matched with what. Perhaps this
> > could be merged in a bit more refined form if it proves useful.
> > 
> > Not tested in any way.
> > 
> 
> Thanks for the patch!
> 
> I fixed a few issues (see below) and gave this patch a try. Though in my
> case it doesn't seem to help much as the problem is somewhere before the
> matching actually happens. The only output from this patch I get is:
> 
> [    1.536479] imx219 1-0010: trying to complete
> [    1.540856] imx219 1-0010: V4L2 device not available

Yeah, the problem, as I understand, is a driver bug combined with a DTS
bug... oh well.

So not a V4L2 async problem at all. :-)
Frieder Schrempf Feb. 14, 2023, 2:57 p.m. UTC | #4
On 14.02.23 15:56, Sakari Ailus wrote:
> On Tue, Feb 14, 2023 at 11:25:20AM +0100, Frieder Schrempf wrote:
>> Hi Sakari,
>>
>> On 09.02.23 23:16, Sakari Ailus wrote:
>>> Just add some debug prints for V4L2 async sub-device matching process. These
>>> might come useful in figuring out why things don't work as expected.
>>>
>>> Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
>>> ---
>>> Frieder,
>>>
>>> Can you try this? It prints what is being matched with what. Perhaps this
>>> could be merged in a bit more refined form if it proves useful.
>>>
>>> Not tested in any way.
>>>
>>
>> Thanks for the patch!
>>
>> I fixed a few issues (see below) and gave this patch a try. Though in my
>> case it doesn't seem to help much as the problem is somewhere before the
>> matching actually happens. The only output from this patch I get is:
>>
>> [    1.536479] imx219 1-0010: trying to complete
>> [    1.540856] imx219 1-0010: V4L2 device not available
> 
> Yeah, the problem, as I understand, is a driver bug combined with a DTS
> bug... oh well.
> 
> So not a V4L2 async problem at all. :-)

Correct! Thanks for your help anyway!
Sakari Ailus Feb. 15, 2023, noon UTC | #5
Hi Laurent,

On Fri, Feb 10, 2023 at 12:34:01AM +0200, Laurent Pinchart wrote:
> Thank you for the patch.

Thanks for the review!

This was indeed hastily written, to help debugging a particular issue. But
I hope it'll be useful for other purposes, too. V4L2 async is about to get
more complicated soon.

> 
> On Fri, Feb 10, 2023 at 12:16:34AM +0200, Sakari Ailus wrote:
> > Just add some debug prints for V4L2 async sub-device matching process. These
> > might come useful in figuring out why things don't work as expected.
> > 
> > Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> > ---
> > Frieder,
> > 
> > Can you try this? It prints what is being matched with what. Perhaps this
> > could be merged in a bit more refined form if it proves useful.
> > 
> > Not tested in any way.
> > 
> >  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
> >  1 file changed, 36 insertions(+), 5 deletions(-)
> > 
> > diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> > index 2f1b718a9189..6c13a9488415 100644
> > --- a/drivers/media/v4l2-core/v4l2-async.c
> > +++ b/drivers/media/v4l2-core/v4l2-async.c
> > @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> >  	bool sd_fwnode_is_ep;
> >  	struct device *dev;
> >  
> > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > +		asd->match.fwnode);
> 
> Let's be more explicit:
> 
> 	dev_dbg(sd->dev, "async fwnode match: need %pfw, trying %pfw\n",
> 		sd_fwnode, asd->match.fwnode);
> 
> (feel free to adjust, as long as we differentiate what we're looking for
> from what we're testing)

Yes.

> 
> > +
> >  	/*
> >  	 * Both the subdev and the async subdev can provide either an endpoint
> >  	 * fwnode or a device fwnode. Start with the simple case of direct
> >  	 * fwnode matching.
> >  	 */
> > -	if (sd_fwnode == asd->match.fwnode)
> > +	if (sd_fwnode == asd->match.fwnode) {
> > +		dev_dbg(sd->dev, "true\n");
> 
> 		dev_dbg(sd->dev, "direct match found\n");
> 
> >  		return true;
> > +	}
> >  
> >  	/*
> >  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> > @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> >  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
> >  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
> >  
> > -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > +		asd->match.fwnode);
> 
> You've already printed this above, no need to repeat it.
> 
> > +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> > +		dev_dbg(sd->dev, "unmatching node types (false)\n");
> 
> 		dev_dbg(sd->dev, "direct match not found\n");
> 
> >  		return false;
> > +	}
> >  
> >  	/*
> >  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> > @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> >  		other_fwnode = sd_fwnode;
> >  	}
> >  
> > +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> > +		dev_fwnode, other_fwnode);
> 
> Same comment as above regarding "vs." not telling which is which.
> 
> > +
> >  	fwnode_handle_put(dev_fwnode);
> >  
> > -	if (dev_fwnode != other_fwnode)
> > +	if (dev_fwnode != other_fwnode) {
> > +		dev_dbg(sd->dev, "false\n");
> 
> 		dev_dbg(sd->dev, "compat match not found\n");
> 
> >  		return false;
> > +	}
> >  
> >  	/*
> >  	 * We have a heterogeneous match. Retrieve the struct device of the side
> > @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> >  			   dev->driver->name);
> >  	}
> >  
> > +	dev_dbg(sd->dev, "true\n");
> 
> 	dev_dbg(sd->dev, "compat match found\n");
> 
> > +
> >  	return true;
> >  }
> >  
> > @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
> >  			v4l2_async_find_subdev_notifier(sd);
> >  
> >  		if (subdev_notifier &&
> > -		    !v4l2_async_nf_can_complete(subdev_notifier))
> > +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> > +			if (subdev_notifier->sd)
> > +				deb_dbg(subdev_notifier->sd->dev,
> > +					"cannot complete\n");
> 
> I'd add a reference to v4l2-async, either directly in the string, or
> with a "%s: ", __func__ prefix. Otherwise the message will be easy to
> miss. Same in other messages. Maybe a "v4l2-async: " prefix for all
> debug messages ?

How about just "async: " for all of these? It's shorther, still unique, and
these lines will be long.

> 
> >  			return false;
> >  	}
> >  
> > @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
> >  	if (!list_empty(&notifier->waiting))
> >  		return 0;
> >  
> > +	if (notifier->sd)
> > +		deb_dbg(notifier->sd->dev, "trying to complete\n");
> > +
> >  	/* Check the entire notifier tree; find the root notifier first. */
> >  	while (notifier->parent)
> >  		notifier = notifier->parent;
> >  
> >  	/* This is root if it has v4l2_dev. */
> > -	if (!notifier->v4l2_dev)
> > +	if (!notifier->v4l2_dev) {
> > +		if (notifier->sd)
> > +			deb_dbg(notifier->sd->dev,
> > +				"V4L2 device not available\n");
> >  		return 0;
> > +	}
> >  
> >  	/* Is everything ready? */
> >  	if (!v4l2_async_nf_can_complete(notifier))
> >  		return 0;
> >  
> > +	deb_dbg(notifier->sd->dev, "complete\n");
> 
> You guard against notifier->sd being NULL above, but not here. At least
> one of the two is wrong.

I'll add a helper function to get the device safely.

> 
> > +
> >  	return v4l2_async_nf_call_complete(notifier);
> >  }
> >  
> > @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
> >  			continue;
> >  
> >  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> > +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
> > +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> > +			ret);
> >  		if (ret < 0)
> >  			return ret;
> >  
>
Laurent Pinchart Feb. 15, 2023, 7:23 p.m. UTC | #6
Hi Sakari,

On Wed, Feb 15, 2023 at 02:00:46PM +0200, Sakari Ailus wrote:
> On Fri, Feb 10, 2023 at 12:34:01AM +0200, Laurent Pinchart wrote:
> > Thank you for the patch.
> 
> Thanks for the review!
> 
> This was indeed hastily written, to help debugging a particular issue. But
> I hope it'll be useful for other purposes, too. V4L2 async is about to get
> more complicated soon.

Could it get simpler instead ? :-) Maybe one day v4l2-async may cross
the threshold of how much pain I can bear, and I'll rewrite it...

> > On Fri, Feb 10, 2023 at 12:16:34AM +0200, Sakari Ailus wrote:
> > > Just add some debug prints for V4L2 async sub-device matching process. These
> > > might come useful in figuring out why things don't work as expected.
> > > 
> > > Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> > > ---
> > > Frieder,
> > > 
> > > Can you try this? It prints what is being matched with what. Perhaps this
> > > could be merged in a bit more refined form if it proves useful.
> > > 
> > > Not tested in any way.
> > > 
> > >  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
> > >  1 file changed, 36 insertions(+), 5 deletions(-)
> > > 
> > > diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> > > index 2f1b718a9189..6c13a9488415 100644
> > > --- a/drivers/media/v4l2-core/v4l2-async.c
> > > +++ b/drivers/media/v4l2-core/v4l2-async.c
> > > @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > >  	bool sd_fwnode_is_ep;
> > >  	struct device *dev;
> > >  
> > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > +		asd->match.fwnode);
> > 
> > Let's be more explicit:
> > 
> > 	dev_dbg(sd->dev, "async fwnode match: need %pfw, trying %pfw\n",
> > 		sd_fwnode, asd->match.fwnode);
> > 
> > (feel free to adjust, as long as we differentiate what we're looking for
> > from what we're testing)
> 
> Yes.
> 
> > > +
> > >  	/*
> > >  	 * Both the subdev and the async subdev can provide either an endpoint
> > >  	 * fwnode or a device fwnode. Start with the simple case of direct
> > >  	 * fwnode matching.
> > >  	 */
> > > -	if (sd_fwnode == asd->match.fwnode)
> > > +	if (sd_fwnode == asd->match.fwnode) {
> > > +		dev_dbg(sd->dev, "true\n");
> > 
> > 		dev_dbg(sd->dev, "direct match found\n");
> > 
> > >  		return true;
> > > +	}
> > >  
> > >  	/*
> > >  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> > > @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > >  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
> > >  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
> > >  
> > > -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > +		asd->match.fwnode);
> > 
> > You've already printed this above, no need to repeat it.
> > 
> > > +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> > > +		dev_dbg(sd->dev, "unmatching node types (false)\n");
> > 
> > 		dev_dbg(sd->dev, "direct match not found\n");
> > 
> > >  		return false;
> > > +	}
> > >  
> > >  	/*
> > >  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> > > @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > >  		other_fwnode = sd_fwnode;
> > >  	}
> > >  
> > > +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> > > +		dev_fwnode, other_fwnode);
> > 
> > Same comment as above regarding "vs." not telling which is which.
> > 
> > > +
> > >  	fwnode_handle_put(dev_fwnode);
> > >  
> > > -	if (dev_fwnode != other_fwnode)
> > > +	if (dev_fwnode != other_fwnode) {
> > > +		dev_dbg(sd->dev, "false\n");
> > 
> > 		dev_dbg(sd->dev, "compat match not found\n");
> > 
> > >  		return false;
> > > +	}
> > >  
> > >  	/*
> > >  	 * We have a heterogeneous match. Retrieve the struct device of the side
> > > @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > >  			   dev->driver->name);
> > >  	}
> > >  
> > > +	dev_dbg(sd->dev, "true\n");
> > 
> > 	dev_dbg(sd->dev, "compat match found\n");
> > 
> > > +
> > >  	return true;
> > >  }
> > >  
> > > @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
> > >  			v4l2_async_find_subdev_notifier(sd);
> > >  
> > >  		if (subdev_notifier &&
> > > -		    !v4l2_async_nf_can_complete(subdev_notifier))
> > > +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> > > +			if (subdev_notifier->sd)
> > > +				deb_dbg(subdev_notifier->sd->dev,
> > > +					"cannot complete\n");
> > 
> > I'd add a reference to v4l2-async, either directly in the string, or
> > with a "%s: ", __func__ prefix. Otherwise the message will be easy to
> > miss. Same in other messages. Maybe a "v4l2-async: " prefix for all
> > debug messages ?
> 
> How about just "async: " for all of these? It's shorther, still unique, and
> these lines will be long.

"async" is a bit vague, I think you should mention V4L2 too. If this
ends up printing

3-0010 async: cannot complete

someone may wonder what it relates to. We're talking about debugging
messages here, let's make sure they improve debugging as much as
possible.

> > >  			return false;
> > >  	}
> > >  
> > > @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
> > >  	if (!list_empty(&notifier->waiting))
> > >  		return 0;
> > >  
> > > +	if (notifier->sd)
> > > +		deb_dbg(notifier->sd->dev, "trying to complete\n");
> > > +
> > >  	/* Check the entire notifier tree; find the root notifier first. */
> > >  	while (notifier->parent)
> > >  		notifier = notifier->parent;
> > >  
> > >  	/* This is root if it has v4l2_dev. */
> > > -	if (!notifier->v4l2_dev)
> > > +	if (!notifier->v4l2_dev) {
> > > +		if (notifier->sd)
> > > +			deb_dbg(notifier->sd->dev,
> > > +				"V4L2 device not available\n");
> > >  		return 0;
> > > +	}
> > >  
> > >  	/* Is everything ready? */
> > >  	if (!v4l2_async_nf_can_complete(notifier))
> > >  		return 0;
> > >  
> > > +	deb_dbg(notifier->sd->dev, "complete\n");
> > 
> > You guard against notifier->sd being NULL above, but not here. At least
> > one of the two is wrong.
> 
> I'll add a helper function to get the device safely.
> 
> > > +
> > >  	return v4l2_async_nf_call_complete(notifier);
> > >  }
> > >  
> > > @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
> > >  			continue;
> > >  
> > >  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> > > +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
> > > +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> > > +			ret);
> > >  		if (ret < 0)
> > >  			return ret;
> > >
Sakari Ailus Feb. 16, 2023, 8:12 a.m. UTC | #7
Hi Laurent,

On Wed, Feb 15, 2023 at 09:23:05PM +0200, Laurent Pinchart wrote:
> Hi Sakari,
> 
> On Wed, Feb 15, 2023 at 02:00:46PM +0200, Sakari Ailus wrote:
> > On Fri, Feb 10, 2023 at 12:34:01AM +0200, Laurent Pinchart wrote:
> > > Thank you for the patch.
> > 
> > Thanks for the review!
> > 
> > This was indeed hastily written, to help debugging a particular issue. But
> > I hope it'll be useful for other purposes, too. V4L2 async is about to get
> > more complicated soon.
> 
> Could it get simpler instead ? :-) Maybe one day v4l2-async may cross
> the threshold of how much pain I can bear, and I'll rewrite it...

I wish it could, but often supporting complex needs is complicated.
"Simplicated" is not even a proper word after all. Let's see.

> 
> > > On Fri, Feb 10, 2023 at 12:16:34AM +0200, Sakari Ailus wrote:
> > > > Just add some debug prints for V4L2 async sub-device matching process. These
> > > > might come useful in figuring out why things don't work as expected.
> > > > 
> > > > Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> > > > ---
> > > > Frieder,
> > > > 
> > > > Can you try this? It prints what is being matched with what. Perhaps this
> > > > could be merged in a bit more refined form if it proves useful.
> > > > 
> > > > Not tested in any way.
> > > > 
> > > >  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
> > > >  1 file changed, 36 insertions(+), 5 deletions(-)
> > > > 
> > > > diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> > > > index 2f1b718a9189..6c13a9488415 100644
> > > > --- a/drivers/media/v4l2-core/v4l2-async.c
> > > > +++ b/drivers/media/v4l2-core/v4l2-async.c
> > > > @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > >  	bool sd_fwnode_is_ep;
> > > >  	struct device *dev;
> > > >  
> > > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > > +		asd->match.fwnode);
> > > 
> > > Let's be more explicit:
> > > 
> > > 	dev_dbg(sd->dev, "async fwnode match: need %pfw, trying %pfw\n",
> > > 		sd_fwnode, asd->match.fwnode);
> > > 
> > > (feel free to adjust, as long as we differentiate what we're looking for
> > > from what we're testing)
> > 
> > Yes.
> > 
> > > > +
> > > >  	/*
> > > >  	 * Both the subdev and the async subdev can provide either an endpoint
> > > >  	 * fwnode or a device fwnode. Start with the simple case of direct
> > > >  	 * fwnode matching.
> > > >  	 */
> > > > -	if (sd_fwnode == asd->match.fwnode)
> > > > +	if (sd_fwnode == asd->match.fwnode) {
> > > > +		dev_dbg(sd->dev, "true\n");
> > > 
> > > 		dev_dbg(sd->dev, "direct match found\n");
> > > 
> > > >  		return true;
> > > > +	}
> > > >  
> > > >  	/*
> > > >  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> > > > @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > >  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
> > > >  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
> > > >  
> > > > -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> > > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > > +		asd->match.fwnode);
> > > 
> > > You've already printed this above, no need to repeat it.
> > > 
> > > > +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> > > > +		dev_dbg(sd->dev, "unmatching node types (false)\n");
> > > 
> > > 		dev_dbg(sd->dev, "direct match not found\n");
> > > 
> > > >  		return false;
> > > > +	}
> > > >  
> > > >  	/*
> > > >  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> > > > @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > >  		other_fwnode = sd_fwnode;
> > > >  	}
> > > >  
> > > > +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> > > > +		dev_fwnode, other_fwnode);
> > > 
> > > Same comment as above regarding "vs." not telling which is which.
> > > 
> > > > +
> > > >  	fwnode_handle_put(dev_fwnode);
> > > >  
> > > > -	if (dev_fwnode != other_fwnode)
> > > > +	if (dev_fwnode != other_fwnode) {
> > > > +		dev_dbg(sd->dev, "false\n");
> > > 
> > > 		dev_dbg(sd->dev, "compat match not found\n");
> > > 
> > > >  		return false;
> > > > +	}
> > > >  
> > > >  	/*
> > > >  	 * We have a heterogeneous match. Retrieve the struct device of the side
> > > > @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > >  			   dev->driver->name);
> > > >  	}
> > > >  
> > > > +	dev_dbg(sd->dev, "true\n");
> > > 
> > > 	dev_dbg(sd->dev, "compat match found\n");
> > > 
> > > > +
> > > >  	return true;
> > > >  }
> > > >  
> > > > @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
> > > >  			v4l2_async_find_subdev_notifier(sd);
> > > >  
> > > >  		if (subdev_notifier &&
> > > > -		    !v4l2_async_nf_can_complete(subdev_notifier))
> > > > +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> > > > +			if (subdev_notifier->sd)
> > > > +				deb_dbg(subdev_notifier->sd->dev,
> > > > +					"cannot complete\n");
> > > 
> > > I'd add a reference to v4l2-async, either directly in the string, or
> > > with a "%s: ", __func__ prefix. Otherwise the message will be easy to
> > > miss. Same in other messages. Maybe a "v4l2-async: " prefix for all
> > > debug messages ?
> > 
> > How about just "async: " for all of these? It's shorther, still unique, and
> > these lines will be long.
> 
> "async" is a bit vague, I think you should mention V4L2 too. If this
> ends up printing
> 
> 3-0010 async: cannot complete
> 
> someone may wonder what it relates to. We're talking about debugging
> messages here, let's make sure they improve debugging as much as
> possible.

These messages include the device name which already implies what it is
about, so I'm frankly not concerned about this. Also these messages tend to
occur in series. Having them shorter, instead, is a small plus. An example:

[    5.716093] dw9807 i2c-PRP0001:01: async: matching for notifier \_SB.PCI0.CIO2, sd \_SB.PCI0.I2C2.VCM0
[    5.716109] dw9807 i2c-PRP0001:01: async: fwnode match: need \_SB.PCI0.I2C2.VCM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
[    5.716123] dw9807 i2c-PRP0001:01: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB.PCI0.I2C2.VCM0
[    5.716131] dw9807 i2c-PRP0001:01: async: compat match not found
[   30.333138] imx258 i2c-SONY258A:00: async: matching for notifier \_SB.PCI0.CIO2, sd \_SB.PCI0.I2C2.CAM0
[   30.333154] imx258 i2c-SONY258A:00: async: fwnode match: need \_SB.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
[   30.333168] imx258 i2c-SONY258A:00: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB.PCI0.I2C2.CAM0
[   30.333175] imx258 i2c-SONY258A:00: async: compat match not found
[   30.333178] imx258 i2c-SONY258A:00: async: trying secondary fwnode match
[   30.333181] imx258 i2c-SONY258A:00: async: fwnode match: need \_SB_.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
[   30.333189] imx258 i2c-SONY258A:00: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0
[   30.333196] imx258 i2c-SONY258A:00: async: compat match found
[   30.333214] dw9807 i2c-PRP0001:01: async: matching for notifier \_SB.PCI0.I2C2.CAM0, sd \_SB.PCI0.I2C2.VCM0
[   30.333225] dw9807 i2c-PRP0001:01: async: fwnode match: need \_SB.PCI0.I2C2.VCM0, trying \_SB.PCI0.I2C2.VCM0
[   30.333235] dw9807 i2c-PRP0001:01: async: direct match found
[   30.333248] dw9807 i2c-PRP0001:01: async: bound to i2c-SONY258A:00's notifier (ret 0)
[   30.333252] ipu3-cio2 0000:00:14.3: async: complete

> 
> > > >  			return false;
> > > >  	}
> > > >  
> > > > @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
> > > >  	if (!list_empty(&notifier->waiting))
> > > >  		return 0;
> > > >  
> > > > +	if (notifier->sd)
> > > > +		deb_dbg(notifier->sd->dev, "trying to complete\n");
> > > > +
> > > >  	/* Check the entire notifier tree; find the root notifier first. */
> > > >  	while (notifier->parent)
> > > >  		notifier = notifier->parent;
> > > >  
> > > >  	/* This is root if it has v4l2_dev. */
> > > > -	if (!notifier->v4l2_dev)
> > > > +	if (!notifier->v4l2_dev) {
> > > > +		if (notifier->sd)
> > > > +			deb_dbg(notifier->sd->dev,
> > > > +				"V4L2 device not available\n");
> > > >  		return 0;
> > > > +	}
> > > >  
> > > >  	/* Is everything ready? */
> > > >  	if (!v4l2_async_nf_can_complete(notifier))
> > > >  		return 0;
> > > >  
> > > > +	deb_dbg(notifier->sd->dev, "complete\n");
> > > 
> > > You guard against notifier->sd being NULL above, but not here. At least
> > > one of the two is wrong.
> > 
> > I'll add a helper function to get the device safely.
> > 
> > > > +
> > > >  	return v4l2_async_nf_call_complete(notifier);
> > > >  }
> > > >  
> > > > @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
> > > >  			continue;
> > > >  
> > > >  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> > > > +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
> > > > +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> > > > +			ret);
> > > >  		if (ret < 0)
> > > >  			return ret;
> > > >
Laurent Pinchart Feb. 16, 2023, 11:11 p.m. UTC | #8
Hi Sakari,

On Thu, Feb 16, 2023 at 10:12:22AM +0200, Sakari Ailus wrote:
> On Wed, Feb 15, 2023 at 09:23:05PM +0200, Laurent Pinchart wrote:
> > On Wed, Feb 15, 2023 at 02:00:46PM +0200, Sakari Ailus wrote:
> > > On Fri, Feb 10, 2023 at 12:34:01AM +0200, Laurent Pinchart wrote:
> > > > Thank you for the patch.
> > > 
> > > Thanks for the review!
> > > 
> > > This was indeed hastily written, to help debugging a particular issue. But
> > > I hope it'll be useful for other purposes, too. V4L2 async is about to get
> > > more complicated soon.
> > 
> > Could it get simpler instead ? :-) Maybe one day v4l2-async may cross
> > the threshold of how much pain I can bear, and I'll rewrite it...
> 
> I wish it could, but often supporting complex needs is complicated.
> "Simplicated" is not even a proper word after all. Let's see.

Don't try to lure me into rewriting it sooner than later ;-)

> > > > On Fri, Feb 10, 2023 at 12:16:34AM +0200, Sakari Ailus wrote:
> > > > > Just add some debug prints for V4L2 async sub-device matching process. These
> > > > > might come useful in figuring out why things don't work as expected.
> > > > > 
> > > > > Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
> > > > > ---
> > > > > Frieder,
> > > > > 
> > > > > Can you try this? It prints what is being matched with what. Perhaps this
> > > > > could be merged in a bit more refined form if it proves useful.
> > > > > 
> > > > > Not tested in any way.
> > > > > 
> > > > >  drivers/media/v4l2-core/v4l2-async.c | 41 ++++++++++++++++++++++++----
> > > > >  1 file changed, 36 insertions(+), 5 deletions(-)
> > > > > 
> > > > > diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
> > > > > index 2f1b718a9189..6c13a9488415 100644
> > > > > --- a/drivers/media/v4l2-core/v4l2-async.c
> > > > > +++ b/drivers/media/v4l2-core/v4l2-async.c
> > > > > @@ -86,13 +86,18 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > > >  	bool sd_fwnode_is_ep;
> > > > >  	struct device *dev;
> > > > >  
> > > > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > > > +		asd->match.fwnode);
> > > > 
> > > > Let's be more explicit:
> > > > 
> > > > 	dev_dbg(sd->dev, "async fwnode match: need %pfw, trying %pfw\n",
> > > > 		sd_fwnode, asd->match.fwnode);
> > > > 
> > > > (feel free to adjust, as long as we differentiate what we're looking for
> > > > from what we're testing)
> > > 
> > > Yes.
> > > 
> > > > > +
> > > > >  	/*
> > > > >  	 * Both the subdev and the async subdev can provide either an endpoint
> > > > >  	 * fwnode or a device fwnode. Start with the simple case of direct
> > > > >  	 * fwnode matching.
> > > > >  	 */
> > > > > -	if (sd_fwnode == asd->match.fwnode)
> > > > > +	if (sd_fwnode == asd->match.fwnode) {
> > > > > +		dev_dbg(sd->dev, "true\n");
> > > > 
> > > > 		dev_dbg(sd->dev, "direct match found\n");
> > > > 
> > > > >  		return true;
> > > > > +	}
> > > > >  
> > > > >  	/*
> > > > >  	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
> > > > > @@ -105,8 +110,12 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > > >  	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
> > > > >  	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
> > > > >  
> > > > > -	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
> > > > > +	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
> > > > > +		asd->match.fwnode);
> > > > 
> > > > You've already printed this above, no need to repeat it.
> > > > 
> > > > > +	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
> > > > > +		dev_dbg(sd->dev, "unmatching node types (false)\n");
> > > > 
> > > > 		dev_dbg(sd->dev, "direct match not found\n");
> > > > 
> > > > >  		return false;
> > > > > +	}
> > > > >  
> > > > >  	/*
> > > > >  	 * The sd and asd fwnodes are of different types. Get the device fwnode
> > > > > @@ -120,10 +129,15 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > > >  		other_fwnode = sd_fwnode;
> > > > >  	}
> > > > >  
> > > > > +	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
> > > > > +		dev_fwnode, other_fwnode);
> > > > 
> > > > Same comment as above regarding "vs." not telling which is which.
> > > > 
> > > > > +
> > > > >  	fwnode_handle_put(dev_fwnode);
> > > > >  
> > > > > -	if (dev_fwnode != other_fwnode)
> > > > > +	if (dev_fwnode != other_fwnode) {
> > > > > +		dev_dbg(sd->dev, "false\n");
> > > > 
> > > > 		dev_dbg(sd->dev, "compat match not found\n");
> > > > 
> > > > >  		return false;
> > > > > +	}
> > > > >  
> > > > >  	/*
> > > > >  	 * We have a heterogeneous match. Retrieve the struct device of the side
> > > > > @@ -143,6 +157,8 @@ match_fwnode_one(struct v4l2_async_notifier *notifier,
> > > > >  			   dev->driver->name);
> > > > >  	}
> > > > >  
> > > > > +	dev_dbg(sd->dev, "true\n");
> > > > 
> > > > 	dev_dbg(sd->dev, "compat match found\n");
> > > > 
> > > > > +
> > > > >  	return true;
> > > > >  }
> > > > >  
> > > > > @@ -255,7 +271,10 @@ v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
> > > > >  			v4l2_async_find_subdev_notifier(sd);
> > > > >  
> > > > >  		if (subdev_notifier &&
> > > > > -		    !v4l2_async_nf_can_complete(subdev_notifier))
> > > > > +		    !v4l2_async_nf_can_complete(subdev_notifier)) {
> > > > > +			if (subdev_notifier->sd)
> > > > > +				deb_dbg(subdev_notifier->sd->dev,
> > > > > +					"cannot complete\n");
> > > > 
> > > > I'd add a reference to v4l2-async, either directly in the string, or
> > > > with a "%s: ", __func__ prefix. Otherwise the message will be easy to
> > > > miss. Same in other messages. Maybe a "v4l2-async: " prefix for all
> > > > debug messages ?
> > > 
> > > How about just "async: " for all of these? It's shorther, still unique, and
> > > these lines will be long.
> > 
> > "async" is a bit vague, I think you should mention V4L2 too. If this
> > ends up printing
> > 
> > 3-0010 async: cannot complete
> > 
> > someone may wonder what it relates to. We're talking about debugging
> > messages here, let's make sure they improve debugging as much as
> > possible.
> 
> These messages include the device name which already implies what it is
> about, so I'm frankly not concerned about this. Also these messages tend to
> occur in series. Having them shorter, instead, is a small plus. An example:
> 
> [    5.716093] dw9807 i2c-PRP0001:01: async: matching for notifier \_SB.PCI0.CIO2, sd \_SB.PCI0.I2C2.VCM0
> [    5.716109] dw9807 i2c-PRP0001:01: async: fwnode match: need \_SB.PCI0.I2C2.VCM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
> [    5.716123] dw9807 i2c-PRP0001:01: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB.PCI0.I2C2.VCM0
> [    5.716131] dw9807 i2c-PRP0001:01: async: compat match not found
> [   30.333138] imx258 i2c-SONY258A:00: async: matching for notifier \_SB.PCI0.CIO2, sd \_SB.PCI0.I2C2.CAM0
> [   30.333154] imx258 i2c-SONY258A:00: async: fwnode match: need \_SB.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
> [   30.333168] imx258 i2c-SONY258A:00: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB.PCI0.I2C2.CAM0
> [   30.333175] imx258 i2c-SONY258A:00: async: compat match not found
> [   30.333178] imx258 i2c-SONY258A:00: async: trying secondary fwnode match
> [   30.333181] imx258 i2c-SONY258A:00: async: fwnode match: need \_SB_.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0/port@0/endpoint@0
> [   30.333189] imx258 i2c-SONY258A:00: async: fwnode compat match, need \_SB_.PCI0.I2C2.CAM0, trying \_SB_.PCI0.I2C2.CAM0
> [   30.333196] imx258 i2c-SONY258A:00: async: compat match found
> [   30.333214] dw9807 i2c-PRP0001:01: async: matching for notifier \_SB.PCI0.I2C2.CAM0, sd \_SB.PCI0.I2C2.VCM0
> [   30.333225] dw9807 i2c-PRP0001:01: async: fwnode match: need \_SB.PCI0.I2C2.VCM0, trying \_SB.PCI0.I2C2.VCM0
> [   30.333235] dw9807 i2c-PRP0001:01: async: direct match found
> [   30.333248] dw9807 i2c-PRP0001:01: async: bound to i2c-SONY258A:00's notifier (ret 0)
> [   30.333252] ipu3-cio2 0000:00:14.3: async: complete

I would still prefer v4l2-async, but I won't nack the patch just for
that.

> > > > >  			return false;
> > > > >  	}
> > > > >  
> > > > > @@ -273,18 +292,27 @@ v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
> > > > >  	if (!list_empty(&notifier->waiting))
> > > > >  		return 0;
> > > > >  
> > > > > +	if (notifier->sd)
> > > > > +		deb_dbg(notifier->sd->dev, "trying to complete\n");
> > > > > +
> > > > >  	/* Check the entire notifier tree; find the root notifier first. */
> > > > >  	while (notifier->parent)
> > > > >  		notifier = notifier->parent;
> > > > >  
> > > > >  	/* This is root if it has v4l2_dev. */
> > > > > -	if (!notifier->v4l2_dev)
> > > > > +	if (!notifier->v4l2_dev) {
> > > > > +		if (notifier->sd)
> > > > > +			deb_dbg(notifier->sd->dev,
> > > > > +				"V4L2 device not available\n");
> > > > >  		return 0;
> > > > > +	}
> > > > >  
> > > > >  	/* Is everything ready? */
> > > > >  	if (!v4l2_async_nf_can_complete(notifier))
> > > > >  		return 0;
> > > > >  
> > > > > +	deb_dbg(notifier->sd->dev, "complete\n");
> > > > 
> > > > You guard against notifier->sd being NULL above, but not here. At least
> > > > one of the two is wrong.
> > > 
> > > I'll add a helper function to get the device safely.
> > > 
> > > > > +
> > > > >  	return v4l2_async_nf_call_complete(notifier);
> > > > >  }
> > > > >  
> > > > > @@ -386,6 +414,9 @@ v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
> > > > >  			continue;
> > > > >  
> > > > >  		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
> > > > > +		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
> > > > > +			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
> > > > > +			ret);
> > > > >  		if (ret < 0)
> > > > >  			return ret;
> > > > >
Sakari Ailus Feb. 17, 2023, 11:39 a.m. UTC | #9
Hi Laurent,

On Fri, Feb 17, 2023 at 01:11:05AM +0200, Laurent Pinchart wrote:
> Hi Sakari,
> 
> On Thu, Feb 16, 2023 at 10:12:22AM +0200, Sakari Ailus wrote:
> > On Wed, Feb 15, 2023 at 09:23:05PM +0200, Laurent Pinchart wrote:
> > > On Wed, Feb 15, 2023 at 02:00:46PM +0200, Sakari Ailus wrote:
> > > > On Fri, Feb 10, 2023 at 12:34:01AM +0200, Laurent Pinchart wrote:
> > > > > Thank you for the patch.
> > > > 
> > > > Thanks for the review!
> > > > 
> > > > This was indeed hastily written, to help debugging a particular issue. But
> > > > I hope it'll be useful for other purposes, too. V4L2 async is about to get
> > > > more complicated soon.
> > > 
> > > Could it get simpler instead ? :-) Maybe one day v4l2-async may cross
> > > the threshold of how much pain I can bear, and I'll rewrite it...
> > 
> > I wish it could, but often supporting complex needs is complicated.
> > "Simplicated" is not even a proper word after all. Let's see.
> 
> Don't try to lure me into rewriting it sooner than later ;-)

This could be all avoided if drivers got all what they need during probe.

It would require vast changes accross a large number of drivers and might
never happen.

Also this is related to not exposing access any hardware before all of it
is available.
diff mbox series

Patch

diff --git a/drivers/media/v4l2-core/v4l2-async.c b/drivers/media/v4l2-core/v4l2-async.c
index 2f1b718a9189..6c13a9488415 100644
--- a/drivers/media/v4l2-core/v4l2-async.c
+++ b/drivers/media/v4l2-core/v4l2-async.c
@@ -86,13 +86,18 @@  match_fwnode_one(struct v4l2_async_notifier *notifier,
 	bool sd_fwnode_is_ep;
 	struct device *dev;
 
+	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
+		asd->match.fwnode);
+
 	/*
 	 * Both the subdev and the async subdev can provide either an endpoint
 	 * fwnode or a device fwnode. Start with the simple case of direct
 	 * fwnode matching.
 	 */
-	if (sd_fwnode == asd->match.fwnode)
+	if (sd_fwnode == asd->match.fwnode) {
+		dev_dbg(sd->dev, "true\n");
 		return true;
+	}
 
 	/*
 	 * Otherwise, check if the sd fwnode and the asd fwnode refer to an
@@ -105,8 +110,12 @@  match_fwnode_one(struct v4l2_async_notifier *notifier,
 	sd_fwnode_is_ep = fwnode_graph_is_endpoint(sd_fwnode);
 	asd_fwnode_is_ep = fwnode_graph_is_endpoint(asd->match.fwnode);
 
-	if (sd_fwnode_is_ep == asd_fwnode_is_ep)
+	dev_dbg(sd->dev, "async fwnode match %pfw vs. %pfw\n", sd_fwnode,
+		asd->match.fwnode);
+	if (sd_fwnode_is_ep == asd_fwnode_is_ep) {
+		dev_dbg(sd->dev, "unmatching node types (false)\n");
 		return false;
+	}
 
 	/*
 	 * The sd and asd fwnodes are of different types. Get the device fwnode
@@ -120,10 +129,15 @@  match_fwnode_one(struct v4l2_async_notifier *notifier,
 		other_fwnode = sd_fwnode;
 	}
 
+	dev_dbg(sd->dev, "async fwnode (compat) match %pfw vs. %pfw\n",
+		dev_fwnode, other_fwnode);
+
 	fwnode_handle_put(dev_fwnode);
 
-	if (dev_fwnode != other_fwnode)
+	if (dev_fwnode != other_fwnode) {
+		dev_dbg(sd->dev, "false\n");
 		return false;
+	}
 
 	/*
 	 * We have a heterogeneous match. Retrieve the struct device of the side
@@ -143,6 +157,8 @@  match_fwnode_one(struct v4l2_async_notifier *notifier,
 			   dev->driver->name);
 	}
 
+	dev_dbg(sd->dev, "true\n");
+
 	return true;
 }
 
@@ -255,7 +271,10 @@  v4l2_async_nf_can_complete(struct v4l2_async_notifier *notifier)
 			v4l2_async_find_subdev_notifier(sd);
 
 		if (subdev_notifier &&
-		    !v4l2_async_nf_can_complete(subdev_notifier))
+		    !v4l2_async_nf_can_complete(subdev_notifier)) {
+			if (subdev_notifier->sd)
+				deb_dbg(subdev_notifier->sd->dev,
+					"cannot complete\n");
 			return false;
 	}
 
@@ -273,18 +292,27 @@  v4l2_async_nf_try_complete(struct v4l2_async_notifier *notifier)
 	if (!list_empty(&notifier->waiting))
 		return 0;
 
+	if (notifier->sd)
+		deb_dbg(notifier->sd->dev, "trying to complete\n");
+
 	/* Check the entire notifier tree; find the root notifier first. */
 	while (notifier->parent)
 		notifier = notifier->parent;
 
 	/* This is root if it has v4l2_dev. */
-	if (!notifier->v4l2_dev)
+	if (!notifier->v4l2_dev) {
+		if (notifier->sd)
+			deb_dbg(notifier->sd->dev,
+				"V4L2 device not available\n");
 		return 0;
+	}
 
 	/* Is everything ready? */
 	if (!v4l2_async_nf_can_complete(notifier))
 		return 0;
 
+	deb_dbg(notifier->sd->dev, "complete\n");
+
 	return v4l2_async_nf_call_complete(notifier);
 }
 
@@ -386,6 +414,9 @@  v4l2_async_nf_try_all_subdevs(struct v4l2_async_notifier *notifier)
 			continue;
 
 		ret = v4l2_async_match_notify(notifier, v4l2_dev, sd, asd);
+		deb_dbg(sd->dev, "bound to %s's notifier (ret %d)\n",
+			notifier->sd ? dev_name(notifier->sd->dev) : "no-dev",
+			ret);
 		if (ret < 0)
 			return ret;