On Fri, Mar 17, 2017 at 10:28:34PM +0800, Icenowy Zheng wrote:
> > It's warning that the device has resources associated with it on
> > probe. There gotta be something fishy going on with the probing
> > sequence. How reproducible is the problem?
>
> Do you mean in the first probing trial the driver didn't clean up well?
Possibly but devres should have released all resources after the
previous probe failure or driver disassociation, so I have no idea how
there can be resources left on that list.
> With the same driver I didn't see this problem in 4.11-rc{1,2}.
devres hasn't changed, so I have no idea what changed that. Which
kernels are affected? Can you bisect if the problem is easily
reproducible?
Thanks.
--
tejun
On Fri, Mar 17, 2017 at 10:44:22AM -0400, Tejun Heo wrote:
> On Fri, Mar 17, 2017 at 10:28:34PM +0800, Icenowy Zheng wrote:
> > > It's warning that the device has resources associated with it on
> > > probe. There gotta be something fishy going on with the probing
> > > sequence. How reproducible is the problem?
> >
> > Do you mean in the first probing trial the driver didn't clean up well?
>
> Possibly but devres should have released all resources after the
> previous probe failure or driver disassociation, so I have no idea how
> there can be resources left on that list.
>
> > With the same driver I didn't see this problem in 4.11-rc{1,2}.
>
> devres hasn't changed, so I have no idea what changed that. Which
> kernels are affected?
It's a not-yet-mainlined part (that's why I sent the report to Icenowy and
Andre Przywara -- they work on the DT bindings and the driver itself).
The exact kernel is based on [email protected]:Icenowy/linux.git
(icenowy/sunxi64-4.11-rc1); I've removed all additional commits that could
possibly be related. I need at the very least a f2fs fix to boot this
machine (without reformatting). I did not bother trimming things that are
obviously irrelevant (n_tty, vt, btrfs, sd); lemme retry with 4.11-rc2 that
has just the f2fs fix and "#define DEBUG" in drivers/base/dd.c to be sure.
I've first noticed the warning on pre-4.11 -next; because of very intense
work in these areas Icenowy, Andre and the rest are doing the pine64 parts
are hard to naively rebase -- and thus I haven't run intermediate versions.
> Can you bisect if the problem is easily reproducible?
While it reproduces 100%, the churn in required commits atop mainline would
make bisecting pretty tricky. Do you have some other ideas over debugging
the hard way? (I don't know these parts of the kernel myself thus I
reported first.)
In case my exact .config and tree are relevant:
https://angband.pl/tmp/config-kb-ice-4.11-rc1.xz
[email protected]:kilobyte/linux.git kb-ice-4.11-rc1
--
⢀⣴⠾⠻⢶⣦⠀ Meow!
⣾⠁⢠⠒⠀⣿⡁
⢿⡄⠘⠷⠚⠋⠀ Collisions shmolisions, let's see them find a collision or second
⠈⠳⣄⠀⠀⠀⠀ preimage for double rot13!
Hi,
On 17/03/17 14:44, Tejun Heo wrote:
> On Fri, Mar 17, 2017 at 10:28:34PM +0800, Icenowy Zheng wrote:
>>> It's warning that the device has resources associated with it on
>>> probe. There gotta be something fishy going on with the probing
>>> sequence. How reproducible is the problem?
>>
>> Do you mean in the first probing trial the driver didn't clean up well?
>
> Possibly but devres should have released all resources after the
> previous probe failure or driver disassociation, so I have no idea how
> there can be resources left on that list.
>
>> With the same driver I didn't see this problem in 4.11-rc{1,2}.
>
> devres hasn't changed, so I have no idea what changed that. Which
> kernels are affected? Can you bisect if the problem is easily
> reproducible?
So I see this problem easily now - on every boot - with an unpatched
4.11-rc3 kernel and the (arm64) defconfig on a Pine64 or BananaPi M64.
I enabled devres.log and see that pinctrl probes early, but apparently
gets deferred, pretty late actually (after 43 ADDs).
Now what sticks out from the sequence (see the attached log) is that
there are two un-matches ADDs with a devm_kmalloc of size 0:
sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84200
devm_kzalloc_release (0 bytes)
sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84100
devm_kzalloc_release (0 bytes)
While all the other ADDs have a matching REL, those two have not. I
guess it's due to the size being 0. Does that ring a bell?
Or is due to the fact that these two ADDs are after the RELs have
already started, so at a point where the driver is already cleaned up?
The last two successful actions are the devm_pinctrl_register() and the
following devm_kzalloc() for struct gpiochip (312 bytes) (in
drivers/pinctrl/sunxi/pinctrl-sunxi.c). The it calls
gpiochip_add_data(), which apparently returns -EPROBE_DEFER.
I am pretty clueless when it comes to the internals of devm and devres,
and TBH couldn't easily see where the it could fail in
drivers/base/devres.c.
So does any of you have a clue?
Cheers,
Andre.
Hello,
On Mon, Apr 03, 2017 at 12:48:16AM +0100, Andr? Przywara wrote:
> So I see this problem easily now - on every boot - with an unpatched
> 4.11-rc3 kernel and the (arm64) defconfig on a Pine64 or BananaPi M64.
> I enabled devres.log and see that pinctrl probes early, but apparently
> gets deferred, pretty late actually (after 43 ADDs).
>
> Now what sticks out from the sequence (see the attached log) is that
> there are two un-matches ADDs with a devm_kmalloc of size 0:
> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84200
> devm_kzalloc_release (0 bytes)
> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84100
> devm_kzalloc_release (0 bytes)
>
> While all the other ADDs have a matching REL, those two have not. I
> guess it's due to the size being 0. Does that ring a bell?
AFAICS, 0 size allocs should be fine.
> Or is due to the fact that these two ADDs are after the RELs have
> already started, so at a point where the driver is already cleaned up?
But this sounds problematic to me. So, these zero length allocations
are happening after release of the device is initiated? Where are
they coming from?
Thanks.
--
tejun
Hi,
On 18/04/17 08:25, Tejun Heo wrote:
> Hello,
>
> On Mon, Apr 03, 2017 at 12:48:16AM +0100, Andr? Przywara wrote:
>> So I see this problem easily now - on every boot - with an unpatched
>> 4.11-rc3 kernel and the (arm64) defconfig on a Pine64 or BananaPi M64.
>> I enabled devres.log and see that pinctrl probes early, but apparently
>> gets deferred, pretty late actually (after 43 ADDs).
>>
>> Now what sticks out from the sequence (see the attached log) is that
>> there are two un-matches ADDs with a devm_kmalloc of size 0:
>> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84200
>> devm_kzalloc_release (0 bytes)
>> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84100
>> devm_kzalloc_release (0 bytes)
>>
>> While all the other ADDs have a matching REL, those two have not. I
>> guess it's due to the size being 0. Does that ring a bell?
>
> AFAICS, 0 size allocs should be fine.
>
>> Or is due to the fact that these two ADDs are after the RELs have
>> already started, so at a point where the driver is already cleaned up?
>
> But this sounds problematic to me. So, these zero length allocations
> are happening after release of the device is initiated? Where are
> they coming from?
Yeah, so I stack-dumped on the zero allocations and indeed they are
called from cleanup functions:
drivers/pinctrl/pinmux.c:pinmux_generic_free_functions():
devm_kzalloc(sizeof(*indices) * pctldev->num_functions, ...)
(and another one I don't know from the top of the my head, logs at home)
So my hunch was that once EPROBE_DEFER triggers the devres cleanup, it
uses some reverse list traversal to release all allocated resources
(backwards!), so missing those which get (appended) during the process.
But I don't think that would not work with the locking.
So I have to dig deeper tonight in my logs.
Just curious why this does (or did) not happen for other users, because
the affected code paths seem rather generic to me.
Is that due to probing order being unfortunate in our case and the
pinctrl driver is never released due to DEFER anywhere else?
Cheers,
Andre.
于 2017年4月18日 GMT+08:00 下午3:25:05, Tejun Heo <[email protected]> 写到:
>Hello,
>
>On Mon, Apr 03, 2017 at 12:48:16AM +0100, André Przywara wrote:
>> So I see this problem easily now - on every boot - with an unpatched
>> 4.11-rc3 kernel and the (arm64) defconfig on a Pine64 or BananaPi
>M64.
>> I enabled devres.log and see that pinctrl probes early, but
>apparently
>> gets deferred, pretty late actually (after 43 ADDs).
>>
>> Now what sticks out from the sequence (see the attached log) is that
>> there are two un-matches ADDs with a devm_kmalloc of size 0:
>> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84200
>> devm_kzalloc_release (0 bytes)
>> sun50i-a64-pinctrl 1c20800.pinctrl: DEVRES ADD ffff80007bd84100
>> devm_kzalloc_release (0 bytes)
P.S. mysteriously the warn disappeared in newest -next, but still exist in 4.11-rc.
>>
>> While all the other ADDs have a matching REL, those two have not. I
>> guess it's due to the size being 0. Does that ring a bell?
>
>AFAICS, 0 size allocs should be fine.
>
>> Or is due to the fact that these two ADDs are after the RELs have
>> already started, so at a point where the driver is already cleaned
>up?
>
>But this sounds problematic to me. So, these zero length allocations
>are happening after release of the device is initiated? Where are
>they coming from?
>
>Thanks.
Hello,
On Tue, Apr 18, 2017 at 10:12:16AM +0100, Andre Przywara wrote:
> Yeah, so I stack-dumped on the zero allocations and indeed they are
> called from cleanup functions:
> drivers/pinctrl/pinmux.c:pinmux_generic_free_functions():
> devm_kzalloc(sizeof(*indices) * pctldev->num_functions, ...)
> (and another one I don't know from the top of the my head, logs at home)
>
> So my hunch was that once EPROBE_DEFER triggers the devres cleanup, it
> uses some reverse list traversal to release all allocated resources
> (backwards!), so missing those which get (appended) during the process.
> But I don't think that would not work with the locking.
> So I have to dig deeper tonight in my logs.
If this is a valid use case, we can change devm to repeat till empty
but it's a weird thing to do to allocate from a release function.
So, something like this. Only compile tested.
Thanks.
diff --git a/drivers/base/devres.c b/drivers/base/devres.c
index 71d5770..d2a9f34 100644
--- a/drivers/base/devres.c
+++ b/drivers/base/devres.c
@@ -509,13 +509,21 @@ static int release_nodes(struct device *dev, struct list_head *first,
int devres_release_all(struct device *dev)
{
unsigned long flags;
+ int cnt = 0, ret;
/* Looks like an uninitialized device structure */
if (WARN_ON(dev->devres_head.next == NULL))
return -ENODEV;
- spin_lock_irqsave(&dev->devres_lock, flags);
- return release_nodes(dev, dev->devres_head.next, &dev->devres_head,
- flags);
+
+ /* Release callbacks may create new nodes, repeat till empty */
+ do {
+ spin_lock_irqsave(&dev->devres_lock, flags);
+ ret = release_nodes(dev, dev->devres_head.next,
+ &dev->devres_head, flags);
+ cnt += ret;
+ } while (ret);
+
+ return cnt;
}
/**
On Fri, Apr 28, 2017 at 06:03:14PM -0400, Tejun Heo wrote:
> On Tue, Apr 18, 2017 at 10:12:16AM +0100, Andre Przywara wrote:
> > Yeah, so I stack-dumped on the zero allocations and indeed they are
> > called from cleanup functions:
> > drivers/pinctrl/pinmux.c:pinmux_generic_free_functions():
> > devm_kzalloc(sizeof(*indices) * pctldev->num_functions, ...)
> > (and another one I don't know from the top of the my head, logs at home)
> >
> > So my hunch was that once EPROBE_DEFER triggers the devres cleanup, it
> > uses some reverse list traversal to release all allocated resources
> > (backwards!), so missing those which get (appended) during the process.
> > But I don't think that would not work with the locking.
> > So I have to dig deeper tonight in my logs.
>
> If this is a valid use case, we can change devm to repeat till empty
> but it's a weird thing to do to allocate from a release function.
>
> So, something like this. Only compile tested.
I've tested this, and the results are mixed. It _does_ make the WARN go
away, but on the other hand, much later during the boot, another driver
(sun8i-emac) gets deferred and never undefers.
Without the patch, there's:
[ ok ] Synthesizing the initial hotplug events...done.
[ 6.666984] bus: 'platform': driver_probe_device: matched device 1c30000.ethernet with driver sun8i-emac
[ 6.676520] bus: 'platform': really_probe: probing driver sun8i-emac with device 1c30000.ethernet
[ 6.686479] driver: 'sun8i-emac': driver_bound: bound to device '1c30000.ethernet'
[....] [ 6.694132] bus: 'platform': really_probe: bound device 1c30000.ethernet to driver sun8i-emac
[ ok ng for /dev to be fully populated...done.
<snip>
[....] Configuring network interfaces...[ 11.414884] libphy: 1c30000.ethernet: probed
[ 11.449742] bus: 'mdio_bus': driver_probe_device: matched device 1c30000.ethernet-0:00 with driver RTL8211E Gigabit Ethernet
[ 11.461013] bus: 'mdio_bus': really_probe: probing driver RTL8211E Gigabit Ethernet with device 1c30000.ethernet-0:00
[ 11.471666] driver: 'RTL8211E Gigabit Ethernet': driver_bound: bound to device '1c30000.ethernet-0:00'
[ 11.481007] bus: 'mdio_bus': really_probe: bound device 1c30000.ethernet-0:00 to driver RTL8211E Gigabit Ethernet
[ 11.491527] RTL8211E Gigabit Ethernet 1c30000.ethernet-0:00: attached PHY driver [RTL8211E Gigabit Ethernet] (mii_bus:phy_addr=1c30000.ethernet-0:00, irq=-1)
[ 11.505608] sun8i-emac 1c30000.ethernet: device MAC address slot 0 02:ba:8f:9e:44:8f
With the patch:
[ ok ] Synthesizing the initial hotplug events...done.
[....] Waiting for /dev to be fully populated...[ 6.325314] bus: 'platform': driver_probe_device: matched device 1c30000.ethernet with driver sun8i-emac
[ 6.334842] bus: 'platform': really_probe: probing driver sun8i-emac with device 1c30000.ethernet
[ 6.344253] platform 1c30000.ethernet: Driver sun8i-emac requests probe deferral
[ 6.351662] platform 1c30000.ethernet: Added to deferred list
done.
<snip>
[....] Configuring network interfaces...Cannot find device "eth0"
ifup: failed to bring up eth0
failed.
There's a concern, though, that this second driver is not in mainline (and
won't ever be -- it's being replaced by dwmac-sun8i, but the latter is not
yet up to scratch), thus I'm not sure how relevant this is.
The second concern is that I'm using the same tree
(icenowy/sunxi64-4.11-rc7) and config (plus filesystems) as Icenowy, on the
same hardware, yet I did see this warning in versions much earlier than her,
and it doesn't go away in -next for me either. All that differs are
toolchain versions (I'm on Debian unstable) and perhaps some u-boot bits.
Because of the amount of churn in sunxi land and the driver's mainlining
status, I think it'd be good to wait after the merge window that starts
tomorrow, and re-test then.
Full console output with the patch applied attached.
Meow!
> diff --git a/drivers/base/devres.c b/drivers/base/devres.c
> index 71d5770..d2a9f34 100644
> --- a/drivers/base/devres.c
> +++ b/drivers/base/devres.c
> @@ -509,13 +509,21 @@ static int release_nodes(struct device *dev, struct list_head *first,
> int devres_release_all(struct device *dev)
> {
> unsigned long flags;
> + int cnt = 0, ret;
>
> /* Looks like an uninitialized device structure */
> if (WARN_ON(dev->devres_head.next == NULL))
> return -ENODEV;
> - spin_lock_irqsave(&dev->devres_lock, flags);
> - return release_nodes(dev, dev->devres_head.next, &dev->devres_head,
> - flags);
> +
> + /* Release callbacks may create new nodes, repeat till empty */
> + do {
> + spin_lock_irqsave(&dev->devres_lock, flags);
> + ret = release_nodes(dev, dev->devres_head.next,
> + &dev->devres_head, flags);
> + cnt += ret;
> + } while (ret);
> +
> + return cnt;
> }
>
> /**
>
--
Don't be racist. White, amber or black, all beers should be judged based
solely on their merits. Heck, even if occasionally a cider applies for a
beer's job, why not?
On the other hand, corpo lager is not a race.
On 29/04/17 22:28, Adam Borowski wrote:
> On Fri, Apr 28, 2017 at 06:03:14PM -0400, Tejun Heo wrote:
>> On Tue, Apr 18, 2017 at 10:12:16AM +0100, Andre Przywara wrote:
>>> Yeah, so I stack-dumped on the zero allocations and indeed they are
>>> called from cleanup functions:
>>> drivers/pinctrl/pinmux.c:pinmux_generic_free_functions():
>>> devm_kzalloc(sizeof(*indices) * pctldev->num_functions, ...)
>>> (and another one I don't know from the top of the my head, logs at home)
>>>
>>> So my hunch was that once EPROBE_DEFER triggers the devres cleanup, it
>>> uses some reverse list traversal to release all allocated resources
>>> (backwards!), so missing those which get (appended) during the process.
>>> But I don't think that would not work with the locking.
>>> So I have to dig deeper tonight in my logs.
>>
>> If this is a valid use case, we can change devm to repeat till empty
>> but it's a weird thing to do to allocate from a release function.
>>
>> So, something like this. Only compile tested.
I was wondering if using devm_*alloc in a _release_ function is valid at
all, given that it is called as part of the DEFER clean-up routine.
Looking at pinmux_generic_free_functions() it looks like we could
replace it with a (non-devm_) kmalloc version and it would still work
(given we add a kfree at the end).
Either that or we bail out early if pctldev->num_functions is zero.
> I've tested this, and the results are mixed. It _does_ make the WARN go
> away, but on the other hand, much later during the boot, another driver
> (sun8i-emac) gets deferred and never undefers.
>
> Without the patch, there's:
> [ ok ] Synthesizing the initial hotplug events...done.
> [ 6.666984] bus: 'platform': driver_probe_device: matched device 1c30000.ethernet with driver sun8i-emac
> [ 6.676520] bus: 'platform': really_probe: probing driver sun8i-emac with device 1c30000.ethernet
> [ 6.686479] driver: 'sun8i-emac': driver_bound: bound to device '1c30000.ethernet'
> [....] [ 6.694132] bus: 'platform': really_probe: bound device 1c30000.ethernet to driver sun8i-emac
> [ ok ng for /dev to be fully populated...done.
> <snip>
> [....] Configuring network interfaces...[ 11.414884] libphy: 1c30000.ethernet: probed
> [ 11.449742] bus: 'mdio_bus': driver_probe_device: matched device 1c30000.ethernet-0:00 with driver RTL8211E Gigabit Ethernet
> [ 11.461013] bus: 'mdio_bus': really_probe: probing driver RTL8211E Gigabit Ethernet with device 1c30000.ethernet-0:00
> [ 11.471666] driver: 'RTL8211E Gigabit Ethernet': driver_bound: bound to device '1c30000.ethernet-0:00'
> [ 11.481007] bus: 'mdio_bus': really_probe: bound device 1c30000.ethernet-0:00 to driver RTL8211E Gigabit Ethernet
> [ 11.491527] RTL8211E Gigabit Ethernet 1c30000.ethernet-0:00: attached PHY driver [RTL8211E Gigabit Ethernet] (mii_bus:phy_addr=1c30000.ethernet-0:00, irq=-1)
> [ 11.505608] sun8i-emac 1c30000.ethernet: device MAC address slot 0 02:ba:8f:9e:44:8f
>
> With the patch:
> [ ok ] Synthesizing the initial hotplug events...done.
> [....] Waiting for /dev to be fully populated...[ 6.325314] bus: 'platform': driver_probe_device: matched device 1c30000.ethernet with driver sun8i-emac
> [ 6.334842] bus: 'platform': really_probe: probing driver sun8i-emac with device 1c30000.ethernet
> [ 6.344253] platform 1c30000.ethernet: Driver sun8i-emac requests probe deferral
> [ 6.351662] platform 1c30000.ethernet: Added to deferred list
> done.
> <snip>
> [....] Configuring network interfaces...Cannot find device "eth0"
> ifup: failed to bring up eth0
> failed.
>
>
> There's a concern, though, that this second driver is not in mainline (and
> won't ever be -- it's being replaced by dwmac-sun8i, but the latter is not
> yet up to scratch), thus I'm not sure how relevant this is.
>
> The second concern is that I'm using the same tree
> (icenowy/sunxi64-4.11-rc7) and config (plus filesystems) as Icenowy, on the
> same hardware, yet I did see this warning in versions much earlier than her,
> and it doesn't go away in -next for me either. All that differs are
> toolchain versions (I'm on Debian unstable) and perhaps some u-boot bits.
My understanding is that the probing order is determined during link
time of the kernel - at least for functions using the same initcall
level. For drivers in the same subsystem this is mostly set by the order
in the Makefile, but for drivers from different subsystems their order
might by slightly different depending on parallel compilation. So on
some builds the pinctrl driver gets called late and everything is fine,
whereas on other build it gets called early and returns with -EDEFER,
leading to the issue.
> Because of the amount of churn in sunxi land and the driver's mainlining
> status, I think it'd be good to wait after the merge window that starts
> tomorrow, and re-test then.
Well, I see this issue with pure mainline and defconfig, so no sunxi
specialities here.
Will do more investigation tomorrow.
Cheers,
Andre.
>
> Full console output with the patch applied attached.
>
>
> Meow!
>
>
>> diff --git a/drivers/base/devres.c b/drivers/base/devres.c
>> index 71d5770..d2a9f34 100644
>> --- a/drivers/base/devres.c
>> +++ b/drivers/base/devres.c
>> @@ -509,13 +509,21 @@ static int release_nodes(struct device *dev, struct list_head *first,
>> int devres_release_all(struct device *dev)
>> {
>> unsigned long flags;
>> + int cnt = 0, ret;
>>
>> /* Looks like an uninitialized device structure */
>> if (WARN_ON(dev->devres_head.next == NULL))
>> return -ENODEV;
>> - spin_lock_irqsave(&dev->devres_lock, flags);
>> - return release_nodes(dev, dev->devres_head.next, &dev->devres_head,
>> - flags);
>> +
>> + /* Release callbacks may create new nodes, repeat till empty */
>> + do {
>> + spin_lock_irqsave(&dev->devres_lock, flags);
>> + ret = release_nodes(dev, dev->devres_head.next,
>> + &dev->devres_head, flags);
>> + cnt += ret;
>> + } while (ret);
>> +
>> + return cnt;
>> }
>>
>> /**
>>
>