Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1421608 > unrolled thread
| Started by | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| First post | 2016-06-14 08:30 +0200 |
| Last post | 2016-06-23 05:00 +0200 |
| Articles | 18 — 3 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-14 08:30 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Geert Uytterhoeven <geert@linux-m68k.org> - 2016-06-14 09:40 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-14 10:10 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Geert Uytterhoeven <geert@linux-m68k.org> - 2016-06-14 12:50 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-15 04:30 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Geert Uytterhoeven <geert@linux-m68k.org> - 2016-06-15 10:40 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-20 08:40 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-20 15:20 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-21 09:00 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-21 15:00 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-22 02:50 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-22 05:30 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Geert Uytterhoeven <geert@linux-m68k.org> - 2016-06-22 17:10 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-22 21:10 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-23 02:50 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) Joonsoo Kim <iamjoonsoo.kim@lge.com> - 2016-06-23 04:40 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-23 04:50 +0200
Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-06-23 05:00 +0200
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-14 08:30 +0200 |
| Subject | Re: Boot failure on emev2/kzm9d (was: Re: [PATCH v2 11/11] mm/slab: lockless decision to grow cache) |
| Message-ID | <rJQ1k-YJ-15@gated-at.bofh.it> |
On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> Hi Joonsoo,
Hello,
>
> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >
> > To check whther free objects exist or not precisely, we need to grab a
> > lock. But, accuracy isn't that important because race window would be
> > even small and if there is too much free object, cache reaper would reap
> > it. So, this patch makes the check for free object exisistence not to
> > hold a lock. This will reduce lock contention in heavily allocation case.
> >
> > Note that until now, n->shared can be freed during the processing by
> > writing slabinfo, but, with some trick in this patch, we can access it
> > freely within interrupt disabled period.
> >
> > Below is the result of concurrent allocation/free in slab allocation
> > benchmark made by Christoph a long time ago. I make the output simpler.
> > The number shows cycle count during alloc/free respectively so less is
> > better.
> >
> > * Before
> > Kmalloc N*alloc N*free(32): Average=248/966
> > Kmalloc N*alloc N*free(64): Average=261/949
> > Kmalloc N*alloc N*free(128): Average=314/1016
> > Kmalloc N*alloc N*free(256): Average=741/1061
> > Kmalloc N*alloc N*free(512): Average=1246/1152
> > Kmalloc N*alloc N*free(1024): Average=2437/1259
> > Kmalloc N*alloc N*free(2048): Average=4980/1800
> > Kmalloc N*alloc N*free(4096): Average=9000/2078
> >
> > * After
> > Kmalloc N*alloc N*free(32): Average=344/792
> > Kmalloc N*alloc N*free(64): Average=347/882
> > Kmalloc N*alloc N*free(128): Average=390/959
> > Kmalloc N*alloc N*free(256): Average=393/1067
> > Kmalloc N*alloc N*free(512): Average=683/1229
> > Kmalloc N*alloc N*free(1024): Average=1295/1325
> > Kmalloc N*alloc N*free(2048): Average=2513/1664
> > Kmalloc N*alloc N*free(4096): Average=4742/2172
> >
> > It shows that allocation performance decreases for the object size up to
> > 128 and it may be due to extra checks in cache_alloc_refill(). But, with
> > considering improvement of free performance, net result looks the same.
> > Result for other size class looks very promising, roughly, 50% performance
> > improvement.
> >
> > v2: replace kick_all_cpus_sync() with synchronize_sched().
> >
> > Signed-off-by: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>
> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> (Renesas dual Cortex A9) to this patch, which is upstream commit
> 801faf0db8947e01877920e848a4d338dd7a99e7.
>
> I've attached my .config. I don't know if it also happens with
> shmobile_defconfig, as something went wrong with my remote access to the board,
> preventing further testing. I also couldn't verify if the issue persists in
> v4.7-rc3.
>
> Do you have a clue?
I don't have yet. Could you help me to narrow down the problem?
Following diff is half-revert change to check that synchronize_sched()
has no problem.
Thanks.
----->8-----
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..257a0eb 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -3016,9 +3016,6 @@ static void *cache_alloc_refill(struct kmem_cache *cachep, gfp_t flags)
n = get_node(cachep, node);
BUG_ON(ac->avail > 0 || !n);
- shared = READ_ONCE(n->shared);
- if (!n->free_objects && (!shared || !shared->avail))
- goto direct_grow;
spin_lock(&n->list_lock);
shared = READ_ONCE(n->shared);
@@ -3047,7 +3044,6 @@ alloc_done:
spin_unlock(&n->list_lock);
fixup_objfreelist_debug(cachep, &list);
-direct_grow:
if (unlikely(!ac->avail)) {
/* Check if we can use obj in pfmemalloc slab */
if (sk_memalloc_socks()) {
[toc] | [next] | [standalone]
| From | Geert Uytterhoeven <geert@linux-m68k.org> |
|---|---|
| Date | 2016-06-14 09:40 +0200 |
| Message-ID | <rJR73-1H3-9@gated-at.bofh.it> |
| In reply to | #1421608 |
Hi Joonsoo,
On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
>> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
>> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>> > To check whther free objects exist or not precisely, we need to grab a
>> > lock. But, accuracy isn't that important because race window would be
>> > even small and if there is too much free object, cache reaper would reap
>> > it. So, this patch makes the check for free object exisistence not to
>> > hold a lock. This will reduce lock contention in heavily allocation case.
>> >
>> > Note that until now, n->shared can be freed during the processing by
>> > writing slabinfo, but, with some trick in this patch, we can access it
>> > freely within interrupt disabled period.
>> >
>> > Below is the result of concurrent allocation/free in slab allocation
>> > benchmark made by Christoph a long time ago. I make the output simpler.
>> > The number shows cycle count during alloc/free respectively so less is
>> > better.
>> >
>> > * Before
>> > Kmalloc N*alloc N*free(32): Average=248/966
>> > Kmalloc N*alloc N*free(64): Average=261/949
>> > Kmalloc N*alloc N*free(128): Average=314/1016
>> > Kmalloc N*alloc N*free(256): Average=741/1061
>> > Kmalloc N*alloc N*free(512): Average=1246/1152
>> > Kmalloc N*alloc N*free(1024): Average=2437/1259
>> > Kmalloc N*alloc N*free(2048): Average=4980/1800
>> > Kmalloc N*alloc N*free(4096): Average=9000/2078
>> >
>> > * After
>> > Kmalloc N*alloc N*free(32): Average=344/792
>> > Kmalloc N*alloc N*free(64): Average=347/882
>> > Kmalloc N*alloc N*free(128): Average=390/959
>> > Kmalloc N*alloc N*free(256): Average=393/1067
>> > Kmalloc N*alloc N*free(512): Average=683/1229
>> > Kmalloc N*alloc N*free(1024): Average=1295/1325
>> > Kmalloc N*alloc N*free(2048): Average=2513/1664
>> > Kmalloc N*alloc N*free(4096): Average=4742/2172
>> >
>> > It shows that allocation performance decreases for the object size up to
>> > 128 and it may be due to extra checks in cache_alloc_refill(). But, with
>> > considering improvement of free performance, net result looks the same.
>> > Result for other size class looks very promising, roughly, 50% performance
>> > improvement.
>> >
>> > v2: replace kick_all_cpus_sync() with synchronize_sched().
>> >
>> > Signed-off-by: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>>
>> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
>> (Renesas dual Cortex A9) to this patch, which is upstream commit
>> 801faf0db8947e01877920e848a4d338dd7a99e7.
>>
>> I've attached my .config. I don't know if it also happens with
>> shmobile_defconfig, as something went wrong with my remote access to the board,
>> preventing further testing. I also couldn't verify if the issue persists in
>> v4.7-rc3.
In the mean time, I've verified it also happens with shmobile_defconfig.
>>
>> Do you have a clue?
>
> I don't have yet. Could you help me to narrow down the problem?
> Following diff is half-revert change to check that synchronize_sched()
> has no problem.
Thanks!
Unfortunately the half revert is not sufficient. The full revert is.
> ----->8-----
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..257a0eb 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -3016,9 +3016,6 @@ static void *cache_alloc_refill(struct kmem_cache *cachep, gfp_t flags)
> n = get_node(cachep, node);
>
> BUG_ON(ac->avail > 0 || !n);
> - shared = READ_ONCE(n->shared);
> - if (!n->free_objects && (!shared || !shared->avail))
> - goto direct_grow;
>
> spin_lock(&n->list_lock);
> shared = READ_ONCE(n->shared);
> @@ -3047,7 +3044,6 @@ alloc_done:
> spin_unlock(&n->list_lock);
> fixup_objfreelist_debug(cachep, &list);
>
> -direct_grow:
> if (unlikely(!ac->avail)) {
> /* Check if we can use obj in pfmemalloc slab */
> if (sk_memalloc_socks()) {
Gr{oetje,eeting}s,
Geert
--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-14 10:10 +0200 |
| Message-ID | <rJRA5-28Y-5@gated-at.bofh.it> |
| In reply to | #1421633 |
On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> Hi Joonsoo,
>
> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >> > To check whther free objects exist or not precisely, we need to grab a
> >> > lock. But, accuracy isn't that important because race window would be
> >> > even small and if there is too much free object, cache reaper would reap
> >> > it. So, this patch makes the check for free object exisistence not to
> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> >> >
> >> > Note that until now, n->shared can be freed during the processing by
> >> > writing slabinfo, but, with some trick in this patch, we can access it
> >> > freely within interrupt disabled period.
> >> >
> >> > Below is the result of concurrent allocation/free in slab allocation
> >> > benchmark made by Christoph a long time ago. I make the output simpler.
> >> > The number shows cycle count during alloc/free respectively so less is
> >> > better.
> >> >
> >> > * Before
> >> > Kmalloc N*alloc N*free(32): Average=248/966
> >> > Kmalloc N*alloc N*free(64): Average=261/949
> >> > Kmalloc N*alloc N*free(128): Average=314/1016
> >> > Kmalloc N*alloc N*free(256): Average=741/1061
> >> > Kmalloc N*alloc N*free(512): Average=1246/1152
> >> > Kmalloc N*alloc N*free(1024): Average=2437/1259
> >> > Kmalloc N*alloc N*free(2048): Average=4980/1800
> >> > Kmalloc N*alloc N*free(4096): Average=9000/2078
> >> >
> >> > * After
> >> > Kmalloc N*alloc N*free(32): Average=344/792
> >> > Kmalloc N*alloc N*free(64): Average=347/882
> >> > Kmalloc N*alloc N*free(128): Average=390/959
> >> > Kmalloc N*alloc N*free(256): Average=393/1067
> >> > Kmalloc N*alloc N*free(512): Average=683/1229
> >> > Kmalloc N*alloc N*free(1024): Average=1295/1325
> >> > Kmalloc N*alloc N*free(2048): Average=2513/1664
> >> > Kmalloc N*alloc N*free(4096): Average=4742/2172
> >> >
> >> > It shows that allocation performance decreases for the object size up to
> >> > 128 and it may be due to extra checks in cache_alloc_refill(). But, with
> >> > considering improvement of free performance, net result looks the same.
> >> > Result for other size class looks very promising, roughly, 50% performance
> >> > improvement.
> >> >
> >> > v2: replace kick_all_cpus_sync() with synchronize_sched().
> >> >
> >> > Signed-off-by: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >>
> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> >>
> >> I've attached my .config. I don't know if it also happens with
> >> shmobile_defconfig, as something went wrong with my remote access to the board,
> >> preventing further testing. I also couldn't verify if the issue persists in
> >> v4.7-rc3.
>
> In the mean time, I've verified it also happens with shmobile_defconfig.
>
> >>
> >> Do you have a clue?
> >
> > I don't have yet. Could you help me to narrow down the problem?
> > Following diff is half-revert change to check that synchronize_sched()
> > has no problem.
>
> Thanks!
>
> Unfortunately the half revert is not sufficient. The full revert is.
Thanks for quick testing!
Could I ask one more time to check that synchronize_sched() is root
cause of the problem? Testing following two diffs will be helpful to me.
Thanks.
------->8--------
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..d892364 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -965,7 +965,7 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
* freed after synchronize_sched().
*/
if (force_change)
- synchronize_sched();
+ kick_all_cpus_sync();
fail:
kfree(old_shared);
------->8------
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..38d99c2 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -964,8 +964,6 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
* guaranteed to be valid until irq is re-enabled, because it will be
* freed after synchronize_sched().
*/
- if (force_change)
- synchronize_sched();
fail:
kfree(old_shared);
[toc] | [prev] | [next] | [standalone]
| From | Geert Uytterhoeven <geert@linux-m68k.org> |
|---|---|
| Date | 2016-06-14 12:50 +0200 |
| Message-ID | <rJU4W-3FD-31@gated-at.bofh.it> |
| In reply to | #1421643 |
Hi Joonsoo,
On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
>> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
>> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
>> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
>> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>> >> > To check whther free objects exist or not precisely, we need to grab a
>> >> > lock. But, accuracy isn't that important because race window would be
>> >> > even small and if there is too much free object, cache reaper would reap
>> >> > it. So, this patch makes the check for free object exisistence not to
>> >> > hold a lock. This will reduce lock contention in heavily allocation case.
>> >> >
>> >> > Note that until now, n->shared can be freed during the processing by
>> >> > writing slabinfo, but, with some trick in this patch, we can access it
>> >> > freely within interrupt disabled period.
>> >> >
>> >> > Below is the result of concurrent allocation/free in slab allocation
>> >> > benchmark made by Christoph a long time ago. I make the output simpler.
>> >> > The number shows cycle count during alloc/free respectively so less is
>> >> > better.
>> >> >
>> >> > * Before
>> >> > Kmalloc N*alloc N*free(32): Average=248/966
>> >> > Kmalloc N*alloc N*free(64): Average=261/949
>> >> > Kmalloc N*alloc N*free(128): Average=314/1016
>> >> > Kmalloc N*alloc N*free(256): Average=741/1061
>> >> > Kmalloc N*alloc N*free(512): Average=1246/1152
>> >> > Kmalloc N*alloc N*free(1024): Average=2437/1259
>> >> > Kmalloc N*alloc N*free(2048): Average=4980/1800
>> >> > Kmalloc N*alloc N*free(4096): Average=9000/2078
>> >> >
>> >> > * After
>> >> > Kmalloc N*alloc N*free(32): Average=344/792
>> >> > Kmalloc N*alloc N*free(64): Average=347/882
>> >> > Kmalloc N*alloc N*free(128): Average=390/959
>> >> > Kmalloc N*alloc N*free(256): Average=393/1067
>> >> > Kmalloc N*alloc N*free(512): Average=683/1229
>> >> > Kmalloc N*alloc N*free(1024): Average=1295/1325
>> >> > Kmalloc N*alloc N*free(2048): Average=2513/1664
>> >> > Kmalloc N*alloc N*free(4096): Average=4742/2172
>> >> >
>> >> > It shows that allocation performance decreases for the object size up to
>> >> > 128 and it may be due to extra checks in cache_alloc_refill(). But, with
>> >> > considering improvement of free performance, net result looks the same.
>> >> > Result for other size class looks very promising, roughly, 50% performance
>> >> > improvement.
>> >> >
>> >> > v2: replace kick_all_cpus_sync() with synchronize_sched().
>> >> >
>> >> > Signed-off-by: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>> >>
>> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
>> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
>> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
>> >>
>> >> I've attached my .config. I don't know if it also happens with
>> >> shmobile_defconfig, as something went wrong with my remote access to the board,
>> >> preventing further testing. I also couldn't verify if the issue persists in
>> >> v4.7-rc3.
>>
>> In the mean time, I've verified it also happens with shmobile_defconfig.
>>
>> >> Do you have a clue?
>> >
>> > I don't have yet. Could you help me to narrow down the problem?
>> > Following diff is half-revert change to check that synchronize_sched()
>> > has no problem.
>>
>> Thanks!
>>
>> Unfortunately the half revert is not sufficient. The full revert is.
>
> Thanks for quick testing!
>
> Could I ask one more time to check that synchronize_sched() is root
> cause of the problem? Testing following two diffs will be helpful to me.
>
> Thanks.
>
> ------->8--------
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..d892364 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -965,7 +965,7 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * freed after synchronize_sched().
> */
> if (force_change)
> - synchronize_sched();
> + kick_all_cpus_sync();
>
> fail:
> kfree(old_shared);
Works.
> ------->8------
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..38d99c2 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -964,8 +964,6 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * guaranteed to be valid until irq is re-enabled, because it will be
> * freed after synchronize_sched().
> */
> - if (force_change)
> - synchronize_sched();
>
> fail:
> kfree(old_shared);
>
Also works.
Note that I do not see this problem on any of the other boards I use, one
of which is also a dual Cortex A9.
Gr{oetje,eeting}s,
Geert
--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-15 04:30 +0200 |
| Message-ID | <rK8KH-4TL-21@gated-at.bofh.it> |
| In reply to | #1421765 |
On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> Hi Joonsoo,
>
> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >> >> > To check whther free objects exist or not precisely, we need to grab a
> >> >> > lock. But, accuracy isn't that important because race window would be
> >> >> > even small and if there is too much free object, cache reaper would reap
> >> >> > it. So, this patch makes the check for free object exisistence not to
> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> >> >> >
> >> >> > Note that until now, n->shared can be freed during the processing by
> >> >> > writing slabinfo, but, with some trick in this patch, we can access it
> >> >> > freely within interrupt disabled period.
> >> >> >
> >> >> > Below is the result of concurrent allocation/free in slab allocation
> >> >> > benchmark made by Christoph a long time ago. I make the output simpler.
> >> >> > The number shows cycle count during alloc/free respectively so less is
> >> >> > better.
> >> >> >
> >> >> > * Before
> >> >> > Kmalloc N*alloc N*free(32): Average=248/966
> >> >> > Kmalloc N*alloc N*free(64): Average=261/949
> >> >> > Kmalloc N*alloc N*free(128): Average=314/1016
> >> >> > Kmalloc N*alloc N*free(256): Average=741/1061
> >> >> > Kmalloc N*alloc N*free(512): Average=1246/1152
> >> >> > Kmalloc N*alloc N*free(1024): Average=2437/1259
> >> >> > Kmalloc N*alloc N*free(2048): Average=4980/1800
> >> >> > Kmalloc N*alloc N*free(4096): Average=9000/2078
> >> >> >
> >> >> > * After
> >> >> > Kmalloc N*alloc N*free(32): Average=344/792
> >> >> > Kmalloc N*alloc N*free(64): Average=347/882
> >> >> > Kmalloc N*alloc N*free(128): Average=390/959
> >> >> > Kmalloc N*alloc N*free(256): Average=393/1067
> >> >> > Kmalloc N*alloc N*free(512): Average=683/1229
> >> >> > Kmalloc N*alloc N*free(1024): Average=1295/1325
> >> >> > Kmalloc N*alloc N*free(2048): Average=2513/1664
> >> >> > Kmalloc N*alloc N*free(4096): Average=4742/2172
> >> >> >
> >> >> > It shows that allocation performance decreases for the object size up to
> >> >> > 128 and it may be due to extra checks in cache_alloc_refill(). But, with
> >> >> > considering improvement of free performance, net result looks the same.
> >> >> > Result for other size class looks very promising, roughly, 50% performance
> >> >> > improvement.
> >> >> >
> >> >> > v2: replace kick_all_cpus_sync() with synchronize_sched().
> >> >> >
> >> >> > Signed-off-by: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >> >>
> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> >> >>
> >> >> I've attached my .config. I don't know if it also happens with
> >> >> shmobile_defconfig, as something went wrong with my remote access to the board,
> >> >> preventing further testing. I also couldn't verify if the issue persists in
> >> >> v4.7-rc3.
> >>
> >> In the mean time, I've verified it also happens with shmobile_defconfig.
> >>
> >> >> Do you have a clue?
> >> >
> >> > I don't have yet. Could you help me to narrow down the problem?
> >> > Following diff is half-revert change to check that synchronize_sched()
> >> > has no problem.
> >>
> >> Thanks!
> >>
> >> Unfortunately the half revert is not sufficient. The full revert is.
> >
> > Thanks for quick testing!
> >
> > Could I ask one more time to check that synchronize_sched() is root
> > cause of the problem? Testing following two diffs will be helpful to me.
> >
> > Thanks.
> >
> > ------->8--------
> > diff --git a/mm/slab.c b/mm/slab.c
> > index 763096a..d892364 100644
> > --- a/mm/slab.c
> > +++ b/mm/slab.c
> > @@ -965,7 +965,7 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > * freed after synchronize_sched().
> > */
> > if (force_change)
> > - synchronize_sched();
> > + kick_all_cpus_sync();
> >
> > fail:
> > kfree(old_shared);
>
> Works.
>
> > ------->8------
> > diff --git a/mm/slab.c b/mm/slab.c
> > index 763096a..38d99c2 100644
> > --- a/mm/slab.c
> > +++ b/mm/slab.c
> > @@ -964,8 +964,6 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > * guaranteed to be valid until irq is re-enabled, because it will be
> > * freed after synchronize_sched().
> > */
> > - if (force_change)
> > - synchronize_sched();
> >
> > fail:
> > kfree(old_shared);
> >
>
> Also works.
>
> Note that I do not see this problem on any of the other boards I use, one
> of which is also a dual Cortex A9.
Thanks for your help!
It's curious that synchronize_sched() has some effect in this early
phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
First, I'd like to confirm that num_online_cpus() is correct.
Could you try following patch and give me a dmesg?
Thanks.
------->8----------
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..5b7300a 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
* guaranteed to be valid until irq is re-enabled, because it will be
* freed after synchronize_sched().
*/
- if (force_change)
- synchronize_sched();
+ if (force_change) {
+ WARN_ON_ONCE(num_online_cpus() <= 1);
+ WARN_ON_ONCE(num_online_cpus() > 1);
+ }
fail:
kfree(old_shared);
[toc] | [prev] | [next] | [standalone]
| From | Geert Uytterhoeven <geert@linux-m68k.org> |
|---|---|
| Date | 2016-06-15 10:40 +0200 |
| Message-ID | <rKewG-a9-5@gated-at.bofh.it> |
| In reply to | #1422506 |
Hi Joonsoo,
On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
>> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
>> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
>> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
>> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
>> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
>> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
>> >> >> > To check whther free objects exist or not precisely, we need to grab a
>> >> >> > lock. But, accuracy isn't that important because race window would be
>> >> >> > even small and if there is too much free object, cache reaper would reap
>> >> >> > it. So, this patch makes the check for free object exisistence not to
>> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
>> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
>> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
>> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> It's curious that synchronize_sched() has some effect in this early
> phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
>
> It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
>
> First, I'd like to confirm that num_online_cpus() is correct.
> Could you try following patch and give me a dmesg?
>
> Thanks.
>
> ------->8----------
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..5b7300a 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * guaranteed to be valid until irq is re-enabled, because it will be
> * freed after synchronize_sched().
> */
> - if (force_change)
> - synchronize_sched();
> + if (force_change) {
> + WARN_ON_ONCE(num_online_cpus() <= 1);
> + WARN_ON_ONCE(num_online_cpus() > 1);
> + }
Full dmesg output below.
I also tested whether it's the call to synchronize_sched() before or after
secondary CPU bringup that hangs.
if (force_change && num_online_cpus() <= 1)
synchronize_sched();
boots.
if (force_change && num_online_cpus() > 1)
synchronize_sched();
hangs.
Booting Linux on physical CPU 0x0
Linux version 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty (geert@ramsan)
(gcc version 4.9.0 (GCC) ) #84 SMP Wed Jun 15 10:20:12 CEST 2016
CPU: ARMv7 Processor [411fc093] revision 3 (ARMv7), cr=10c5387d
CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Machine model: EMEV2 KZM9D Board
debug: ignoring loglevel setting.
Memory policy: Data cache writealloc
On node 0 totalpages: 32768
free_area_init_node: node 0, pgdat c09286c0, node_mem_map c7efa000
Normal zone: 256 pages used for memmap
Normal zone: 0 pages reserved
Normal zone: 32768 pages, LIFO batch:7
percpu: Embedded 12 pages/cpu @c7ed9000 s19264 r8192 d21696 u49152
pcpu-alloc: s19264 r8192 d21696 u49152 alloc=12*4096
pcpu-alloc: [0] 0 [0] 1
Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
Kernel command line: console=ttyS1,115200n81 ignore_loglevel
root=/dev/nfs ip=dhcp
PID hash table entries: 512 (order: -1, 2048 bytes)
Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
Memory: 121144K/131072K available (4243K kernel code, 165K rwdata,
1344K rodata, 2048K init, 264K bss, 9928K reserved, 0K cma-reserved,
0K highmem)
Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xc8800000 - 0xff800000 ( 880 MB)
lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
.text : 0xc0008000 - 0xc0674eb8 (6580 kB)
.init : 0xc0700000 - 0xc0900000 (2048 kB)
.data : 0xc0900000 - 0xc0929420 ( 166 kB)
.bss : 0xc092b000 - 0xc096d1e8 ( 265 kB)
Hierarchical RCU implementation.
Build-time adjustment of leaf fanout to 32.
RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
NR_IRQS:16 nr_irqs:16 16
clocksource_probe: no matching clocksources found
sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every
21474836475000000ns
------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at mm/slab.c:975 setup_kmem_cache_node+0x160/0x1c8
Modules linked in:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted
4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
[<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
[<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
[<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
[<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
[<c011fad0>] (warn_slowpath_null) from [<c01ced4c>]
(setup_kmem_cache_node+0x160/0x1c8)
[<c01ced4c>] (setup_kmem_cache_node) from [<c01cf02c>]
(__do_tune_cpucache+0xf4/0x114)
[<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
[<c01cf0b0>] (enable_cpucache) from [<c0710324>]
(kmem_cache_init_late+0x40/0x84)
[<c0710324>] (kmem_cache_init_late) from [<c0700af8>] (start_kernel+0x238/0x36c)
[<c0700af8>] (start_kernel) from [<4000807c>] (0x4000807c)
---[ end trace cb88537fdc8fa200 ]---
Console: colour dummy device 80x30
Calibrating delay loop (skipped) preset value.. 1066.00 BogoMIPS (lpj=5330000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Setting up static identity map for 0x40100000 - 0x40100058
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
Brought up 2 CPUs
SMP: Total of 2 processors activated (2132.00 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at mm/slab.c:976 setup_kmem_cache_node+0x198/0x1c8
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
[<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
[<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
[<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
[<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
[<c011fad0>] (warn_slowpath_null) from [<c01ced84>]
(setup_kmem_cache_node+0x198/0x1c8)
[<c01ced84>] (setup_kmem_cache_node) from [<c01cf02c>]
(__do_tune_cpucache+0xf4/0x114)
[<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
[<c01cf0b0>] (enable_cpucache) from [<c01cf4cc>]
(__kmem_cache_create+0x1a0/0x1c8)
[<c01cf4cc>] (__kmem_cache_create) from [<c01b2904>]
(kmem_cache_create+0xbc/0x190)
[<c01b2904>] (kmem_cache_create) from [<c070d724>] (shmem_init+0x34/0xb0)
[<c070d724>] (shmem_init) from [<c0700cc4>] (kernel_init_freeable+0x98/0x1ec)
[<c0700cc4>] (kernel_init_freeable) from [<c0497760>] (kernel_init+0x8/0x110)
[<c0497760>] (kernel_init) from [<c0106c78>] (ret_from_fork+0x14/0x3c)
---[ end trace cb88537fdc8fa201 ]---
devtmpfs: initialized
VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
max_idle_ns: 19112604462750000 ns
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
sh-pfc e0140200.pfc: emev2_pfc support registered
gpiochip_find_base: found new base at 992
gpio gpiochip0: (e0050000.gpio): created GPIO range 0->31 ==>
e0140200.pfc PIN 0->31
gpio gpiochip0: (e0050000.gpio): added GPIO chardev (254:0)
gpiochip_setup_dev: registered GPIOs 992 to 1023 on device: gpiochip0
(e0050000.gpio)
gpiochip_find_base: found new base at 960
gpio gpiochip1: (e0050080.gpio): created GPIO range 0->31 ==>
e0140200.pfc PIN 32->63
gpio gpiochip1: (e0050080.gpio): added GPIO chardev (254:1)
gpiochip_setup_dev: registered GPIOs 960 to 991 on device: gpiochip1
(e0050080.gpio)
gpiochip_find_base: found new base at 928
gpio gpiochip2: (e0050100.gpio): created GPIO range 0->31 ==>
e0140200.pfc PIN 64->95
gpio gpiochip2: (e0050100.gpio): added GPIO chardev (254:2)
gpiochip_setup_dev: registered GPIOs 928 to 959 on device: gpiochip2
(e0050100.gpio)
gpiochip_find_base: found new base at 896
gpio gpiochip3: (e0050180.gpio): created GPIO range 0->31 ==>
e0140200.pfc PIN 96->127
gpio gpiochip3: (e0050180.gpio): added GPIO chardev (254:3)
gpiochip_setup_dev: registered GPIOs 896 to 927 on device: gpiochip3
(e0050180.gpio)
gpiochip_find_base: found new base at 865
gpio gpiochip4: (e0050200.gpio): created GPIO range 0->30 ==>
e0140200.pfc PIN 128->158
gpio gpiochip4: (e0050200.gpio): added GPIO chardev (254:4)
gpiochip_setup_dev: registered GPIOs 865 to 895 on device: gpiochip4
(e0050200.gpio)
gio: map hw irq = 1, irq = 35
gio: sense irq = 1, mode = 8
No ATAGs?
hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 4 bytes.
of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@0[0]'
of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@1[0]'
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
em_sti e0180000.timer: used for clock events
em_sti e0180000.timer: used for oneshot clock events
em_sti e0180000.timer: used as clock source
clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
0x1ef4687b1, max_idle_ns: 3697658158765000000 ns
Advanced Linux Sound Architecture Driver Initialized.
NET: Registered protocol family 23
clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
0x1ef4687b1, max_idle_ns: 112843571739654 ns
clocksource: Switched to clocksource e0180000.timer
NET: Registered protocol family 2
TCP established hash table entries: 1024 (order: 0, 4096 bytes)
TCP bind hash table entries: 1024 (order: 2, 20480 bytes)
TCP: Hash tables configured (established 1024 bind 1024)
UDP hash table entries: 256 (order: 1, 12288 bytes)
UDP-Lite hash table entries: 256 (order: 1, 12288 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
Clockevents: could not switch to one-shot mode:
Clockevents: could not switch to one-shot mode: dummy_timer is not functional.
Could not switch to high resolution mode on CPU 0
dummy_timer is not functional.
Could not switch to high resolution mode on CPU 1
hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
futex hash table entries: 512 (order: 3, 32768 bytes)
workingset: timestamp_bits=28 max_order=15 bucket_order=0
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
nfs4filelayout_init: NFSv4 File Layout Driver Registering...
io scheduler noop registered (default)
Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
e1020000.serial: ttyS0 at MMIO 0xe1020000 (irq = 19, base_baud =
796444) is a 16550A
e1030000.serial: ttyS1 at MMIO 0xe1030000 (irq = 20, base_baud =
7168000) is a 16550A
console [ttyS1] enabled
e1040000.serial: ttyS2 at MMIO 0xe1040000 (irq = 21, base_baud =
14336000) is a 16550A
e1050000.serial: ttyS3 at MMIO 0xe1050000 (irq = 22, base_baud =
2389333) is a 16550A
gio: sense irq = 1, mode = 8
libphy: smsc911x-mdio: probed
Generic PHY 20000000.etherne:01: attached PHY driver [Generic PHY]
(mii_bus:phy_addr=20000000.etherne:01, irq=-1)
smsc911x 20000000.ethernet eth0: MAC Address: 00:01:9b:04:03:cf
usbcore: registered new interface driver usb-storage
i2c /dev entries driver
em-i2c e0070000.i2c: Added i2c controller 0, irq 33
em-i2c e10a0000.i2c: Added i2c controller 1, irq 34
cpu cpu0: failed to get clock: -2
cpufreq-dt: probe of cpufreq-dt failed with error -2
ledtrig-cpu: registered to indicate activity on CPUs
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
NET: Registered protocol family 17
Key type dns_resolver registered
Registering SWP/SWPB emulation handler
of_get_named_gpiod_flags: parsed 'gpios' property of node
'/gpio_keys/button@1[0]' - status (0)
of_get_named_gpiod_flags: parsed 'gpios' property of node
'/gpio_keys/button@2[0]' - status (0)
of_get_named_gpiod_flags: parsed 'gpios' property of node
'/gpio_keys/button@3[0]' - status (0)
of_get_named_gpiod_flags: parsed 'gpios' property of node
'/gpio_keys/button@4[0]' - status (0)
gpio-1006 (DSW2-1): gpiod_set_debounce: missing set() or
set_debounce() operations
gio: map hw irq = 14, irq = 36
gio: sense irq = 14, mode = 12
gpio-1007 (DSW2-2): gpiod_set_debounce: missing set() or
set_debounce() operations
gio: map hw irq = 15, irq = 37
gio: sense irq = 15, mode = 12
gpio-1008 (DSW2-3): gpiod_set_debounce: missing set() or
set_debounce() operations
gio: map hw irq = 16, irq = 38
gio: sense irq = 16, mode = 12
gpio-1009 (DSW2-4): gpiod_set_debounce: missing set() or
set_debounce() operations
gio: map hw irq = 17, irq = 39
gio: sense irq = 17, mode = 12
input: gpio_keys as /devices/platform/gpio_keys/input/input0
hctosys: unable to open rtc device (rtc0)
smsc911x 20000000.ethernet eth0: SMSC911x/921x identified at 0xc8880000, IRQ: 35
Sending DHCP requests .., OK
IP-Config: Got DHCP answer from 192.168.97.254, my address is 192.168.97.215
IP-Config: Complete:
device=eth0, hwaddr=00:01:9b:04:03:cf, ipaddr=192.168.97.215,
mask=255.255.255.0, gw=192.168.97.254
host=192.168.97.215, domain=of.borg, nis-domain=(none)
bootserver=192.168.97.254, rootserver=192.168.97.254, rootpath=
nameserver0=192.168.97.254
ALSA device list:
No soundcards found.
Freeing unused kernel memory: 2048K (c0700000 - c0900000)
sysctl: error: 'kernel.hotplug' is an unknown key
Gr{oetje,eeting}s,
Geert
--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-20 08:40 +0200 |
| Message-ID | <rM12h-4Jh-5@gated-at.bofh.it> |
| In reply to | #1422784 |
CCing Paul to ask some question.
On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> Hi Joonsoo,
>
> On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> >> >> >> > lock. But, accuracy isn't that important because race window would be
> >> >> >> > even small and if there is too much free object, cache reaper would reap
> >> >> >> > it. So, this patch makes the check for free object exisistence not to
> >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
>
> >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
>
> > It's curious that synchronize_sched() has some effect in this early
> > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> >
> > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> >
> > First, I'd like to confirm that num_online_cpus() is correct.
> > Could you try following patch and give me a dmesg?
> >
> > Thanks.
> >
> > ------->8----------
> > diff --git a/mm/slab.c b/mm/slab.c
> > index 763096a..5b7300a 100644
> > --- a/mm/slab.c
> > +++ b/mm/slab.c
> > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > * guaranteed to be valid until irq is re-enabled, because it will be
> > * freed after synchronize_sched().
> > */
> > - if (force_change)
> > - synchronize_sched();
> > + if (force_change) {
> > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > + WARN_ON_ONCE(num_online_cpus() > 1);
> > + }
>
> Full dmesg output below.
>
> I also tested whether it's the call to synchronize_sched() before or after
> secondary CPU bringup that hangs.
>
> if (force_change && num_online_cpus() <= 1)
> synchronize_sched();
>
> boots.
>
> if (force_change && num_online_cpus() > 1)
> synchronize_sched();
>
> hangs.
Hello, Paul.
I changed slab.c to use synchronize_sched() for full memory barrier. First
call happens on kmem_cache_init_late() and it would not be a problem
because, at this time, num_online_cpus() <= 1 and synchronize_sched()
would return immediately. Second call site would be shmem_init()
and it seems that system hangs on it. Since smp is already initialized
at that time, there would be some effect of synchronize_sched() but I
can't imagine what's wrong here. Is it invalid moment to call
synchronize_sched()?
Note that my x86 virtual machine works fine even if
synchronize_sched() is called in shmem_init() but Geert's some ARM
machines (not all ARM machine) don't work well with it.
Thanks.
>
> Booting Linux on physical CPU 0x0
> Linux version 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty (geert@ramsan)
> (gcc version 4.9.0 (GCC) ) #84 SMP Wed Jun 15 10:20:12 CEST 2016
> CPU: ARMv7 Processor [411fc093] revision 3 (ARMv7), cr=10c5387d
> CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> Machine model: EMEV2 KZM9D Board
> debug: ignoring loglevel setting.
> Memory policy: Data cache writealloc
> On node 0 totalpages: 32768
> free_area_init_node: node 0, pgdat c09286c0, node_mem_map c7efa000
> Normal zone: 256 pages used for memmap
> Normal zone: 0 pages reserved
> Normal zone: 32768 pages, LIFO batch:7
> percpu: Embedded 12 pages/cpu @c7ed9000 s19264 r8192 d21696 u49152
> pcpu-alloc: s19264 r8192 d21696 u49152 alloc=12*4096
> pcpu-alloc: [0] 0 [0] 1
> Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
> Kernel command line: console=ttyS1,115200n81 ignore_loglevel
> root=/dev/nfs ip=dhcp
> PID hash table entries: 512 (order: -1, 2048 bytes)
> Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> Memory: 121144K/131072K available (4243K kernel code, 165K rwdata,
> 1344K rodata, 2048K init, 264K bss, 9928K reserved, 0K cma-reserved,
> 0K highmem)
> Virtual kernel memory layout:
> vector : 0xffff0000 - 0xffff1000 ( 4 kB)
> fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
> vmalloc : 0xc8800000 - 0xff800000 ( 880 MB)
> lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
> pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
> modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
> .text : 0xc0008000 - 0xc0674eb8 (6580 kB)
> .init : 0xc0700000 - 0xc0900000 (2048 kB)
> .data : 0xc0900000 - 0xc0929420 ( 166 kB)
> .bss : 0xc092b000 - 0xc096d1e8 ( 265 kB)
> Hierarchical RCU implementation.
> Build-time adjustment of leaf fanout to 32.
> RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
> RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
> NR_IRQS:16 nr_irqs:16 16
> clocksource_probe: no matching clocksources found
> sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every
> 21474836475000000ns
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 0 at mm/slab.c:975 setup_kmem_cache_node+0x160/0x1c8
> Modules linked in:
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted
> 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> [<c011fad0>] (warn_slowpath_null) from [<c01ced4c>]
> (setup_kmem_cache_node+0x160/0x1c8)
> [<c01ced4c>] (setup_kmem_cache_node) from [<c01cf02c>]
> (__do_tune_cpucache+0xf4/0x114)
> [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> [<c01cf0b0>] (enable_cpucache) from [<c0710324>]
> (kmem_cache_init_late+0x40/0x84)
> [<c0710324>] (kmem_cache_init_late) from [<c0700af8>] (start_kernel+0x238/0x36c)
> [<c0700af8>] (start_kernel) from [<4000807c>] (0x4000807c)
> ---[ end trace cb88537fdc8fa200 ]---
> Console: colour dummy device 80x30
> Calibrating delay loop (skipped) preset value.. 1066.00 BogoMIPS (lpj=5330000)
> pid_max: default: 32768 minimum: 301
> Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
> Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
> CPU: Testing write buffer coherency: ok
> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> Setting up static identity map for 0x40100000 - 0x40100058
> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> Brought up 2 CPUs
> SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> CPU: All CPU(s) started in SVC mode.
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 1 at mm/slab.c:976 setup_kmem_cache_node+0x198/0x1c8
> Modules linked in:
> CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
> 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> [<c011fad0>] (warn_slowpath_null) from [<c01ced84>]
> (setup_kmem_cache_node+0x198/0x1c8)
> [<c01ced84>] (setup_kmem_cache_node) from [<c01cf02c>]
> (__do_tune_cpucache+0xf4/0x114)
> [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> [<c01cf0b0>] (enable_cpucache) from [<c01cf4cc>]
> (__kmem_cache_create+0x1a0/0x1c8)
> [<c01cf4cc>] (__kmem_cache_create) from [<c01b2904>]
> (kmem_cache_create+0xbc/0x190)
> [<c01b2904>] (kmem_cache_create) from [<c070d724>] (shmem_init+0x34/0xb0)
> [<c070d724>] (shmem_init) from [<c0700cc4>] (kernel_init_freeable+0x98/0x1ec)
> [<c0700cc4>] (kernel_init_freeable) from [<c0497760>] (kernel_init+0x8/0x110)
> [<c0497760>] (kernel_init) from [<c0106c78>] (ret_from_fork+0x14/0x3c)
> ---[ end trace cb88537fdc8fa201 ]---
> devtmpfs: initialized
> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
> max_idle_ns: 19112604462750000 ns
> pinctrl core: initialized pinctrl subsystem
> NET: Registered protocol family 16
> DMA: preallocated 256 KiB pool for atomic coherent allocations
> sh-pfc e0140200.pfc: emev2_pfc support registered
> gpiochip_find_base: found new base at 992
> gpio gpiochip0: (e0050000.gpio): created GPIO range 0->31 ==>
> e0140200.pfc PIN 0->31
> gpio gpiochip0: (e0050000.gpio): added GPIO chardev (254:0)
> gpiochip_setup_dev: registered GPIOs 992 to 1023 on device: gpiochip0
> (e0050000.gpio)
> gpiochip_find_base: found new base at 960
> gpio gpiochip1: (e0050080.gpio): created GPIO range 0->31 ==>
> e0140200.pfc PIN 32->63
> gpio gpiochip1: (e0050080.gpio): added GPIO chardev (254:1)
> gpiochip_setup_dev: registered GPIOs 960 to 991 on device: gpiochip1
> (e0050080.gpio)
> gpiochip_find_base: found new base at 928
> gpio gpiochip2: (e0050100.gpio): created GPIO range 0->31 ==>
> e0140200.pfc PIN 64->95
> gpio gpiochip2: (e0050100.gpio): added GPIO chardev (254:2)
> gpiochip_setup_dev: registered GPIOs 928 to 959 on device: gpiochip2
> (e0050100.gpio)
> gpiochip_find_base: found new base at 896
> gpio gpiochip3: (e0050180.gpio): created GPIO range 0->31 ==>
> e0140200.pfc PIN 96->127
> gpio gpiochip3: (e0050180.gpio): added GPIO chardev (254:3)
> gpiochip_setup_dev: registered GPIOs 896 to 927 on device: gpiochip3
> (e0050180.gpio)
> gpiochip_find_base: found new base at 865
> gpio gpiochip4: (e0050200.gpio): created GPIO range 0->30 ==>
> e0140200.pfc PIN 128->158
> gpio gpiochip4: (e0050200.gpio): added GPIO chardev (254:4)
> gpiochip_setup_dev: registered GPIOs 865 to 895 on device: gpiochip4
> (e0050200.gpio)
> gio: map hw irq = 1, irq = 35
> gio: sense irq = 1, mode = 8
> No ATAGs?
> hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> hw-breakpoint: maximum watchpoint size is 4 bytes.
> of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@0[0]'
> of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@1[0]'
> SCSI subsystem initialized
> usbcore: registered new interface driver usbfs
> usbcore: registered new interface driver hub
> usbcore: registered new device driver usb
> em_sti e0180000.timer: used for clock events
> em_sti e0180000.timer: used for oneshot clock events
> em_sti e0180000.timer: used as clock source
> clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> 0x1ef4687b1, max_idle_ns: 3697658158765000000 ns
> Advanced Linux Sound Architecture Driver Initialized.
> NET: Registered protocol family 23
> clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> 0x1ef4687b1, max_idle_ns: 112843571739654 ns
> clocksource: Switched to clocksource e0180000.timer
> NET: Registered protocol family 2
> TCP established hash table entries: 1024 (order: 0, 4096 bytes)
> TCP bind hash table entries: 1024 (order: 2, 20480 bytes)
> TCP: Hash tables configured (established 1024 bind 1024)
> UDP hash table entries: 256 (order: 1, 12288 bytes)
> UDP-Lite hash table entries: 256 (order: 1, 12288 bytes)
> NET: Registered protocol family 1
> RPC: Registered named UNIX socket transport module.
> RPC: Registered udp transport module.
> RPC: Registered tcp transport module.
> RPC: Registered tcp NFSv4.1 backchannel transport module.
> Clockevents: could not switch to one-shot mode:
> Clockevents: could not switch to one-shot mode: dummy_timer is not functional.
> Could not switch to high resolution mode on CPU 0
> dummy_timer is not functional.
> Could not switch to high resolution mode on CPU 1
> hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> futex hash table entries: 512 (order: 3, 32768 bytes)
> workingset: timestamp_bits=28 max_order=15 bucket_order=0
> NFS: Registering the id_resolver key type
> Key type id_resolver registered
> Key type id_legacy registered
> nfs4filelayout_init: NFSv4 File Layout Driver Registering...
> io scheduler noop registered (default)
> Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> e1020000.serial: ttyS0 at MMIO 0xe1020000 (irq = 19, base_baud =
> 796444) is a 16550A
> e1030000.serial: ttyS1 at MMIO 0xe1030000 (irq = 20, base_baud =
> 7168000) is a 16550A
> console [ttyS1] enabled
> e1040000.serial: ttyS2 at MMIO 0xe1040000 (irq = 21, base_baud =
> 14336000) is a 16550A
> e1050000.serial: ttyS3 at MMIO 0xe1050000 (irq = 22, base_baud =
> 2389333) is a 16550A
> gio: sense irq = 1, mode = 8
> libphy: smsc911x-mdio: probed
> Generic PHY 20000000.etherne:01: attached PHY driver [Generic PHY]
> (mii_bus:phy_addr=20000000.etherne:01, irq=-1)
> smsc911x 20000000.ethernet eth0: MAC Address: 00:01:9b:04:03:cf
> usbcore: registered new interface driver usb-storage
> i2c /dev entries driver
> em-i2c e0070000.i2c: Added i2c controller 0, irq 33
> em-i2c e10a0000.i2c: Added i2c controller 1, irq 34
> cpu cpu0: failed to get clock: -2
> cpufreq-dt: probe of cpufreq-dt failed with error -2
> ledtrig-cpu: registered to indicate activity on CPUs
> usbcore: registered new interface driver usbhid
> usbhid: USB HID core driver
> NET: Registered protocol family 17
> Key type dns_resolver registered
> Registering SWP/SWPB emulation handler
> of_get_named_gpiod_flags: parsed 'gpios' property of node
> '/gpio_keys/button@1[0]' - status (0)
> of_get_named_gpiod_flags: parsed 'gpios' property of node
> '/gpio_keys/button@2[0]' - status (0)
> of_get_named_gpiod_flags: parsed 'gpios' property of node
> '/gpio_keys/button@3[0]' - status (0)
> of_get_named_gpiod_flags: parsed 'gpios' property of node
> '/gpio_keys/button@4[0]' - status (0)
> gpio-1006 (DSW2-1): gpiod_set_debounce: missing set() or
> set_debounce() operations
> gio: map hw irq = 14, irq = 36
> gio: sense irq = 14, mode = 12
> gpio-1007 (DSW2-2): gpiod_set_debounce: missing set() or
> set_debounce() operations
> gio: map hw irq = 15, irq = 37
> gio: sense irq = 15, mode = 12
> gpio-1008 (DSW2-3): gpiod_set_debounce: missing set() or
> set_debounce() operations
> gio: map hw irq = 16, irq = 38
> gio: sense irq = 16, mode = 12
> gpio-1009 (DSW2-4): gpiod_set_debounce: missing set() or
> set_debounce() operations
> gio: map hw irq = 17, irq = 39
> gio: sense irq = 17, mode = 12
> input: gpio_keys as /devices/platform/gpio_keys/input/input0
> hctosys: unable to open rtc device (rtc0)
> smsc911x 20000000.ethernet eth0: SMSC911x/921x identified at 0xc8880000, IRQ: 35
> Sending DHCP requests .., OK
> IP-Config: Got DHCP answer from 192.168.97.254, my address is 192.168.97.215
> IP-Config: Complete:
> device=eth0, hwaddr=00:01:9b:04:03:cf, ipaddr=192.168.97.215,
> mask=255.255.255.0, gw=192.168.97.254
> host=192.168.97.215, domain=of.borg, nis-domain=(none)
> bootserver=192.168.97.254, rootserver=192.168.97.254, rootpath=
> nameserver0=192.168.97.254
> ALSA device list:
> No soundcards found.
> Freeing unused kernel memory: 2048K (c0700000 - c0900000)
> sysctl: error: 'kernel.hotplug' is an unknown key
>
> Gr{oetje,eeting}s,
>
> Geert
>
> --
> Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
>
> In personal conversations with technical people, I call myself a hacker. But
> when I'm talking to journalists I just say "programmer" or something like that.
> -- Linus Torvalds
>
> --
> To unsubscribe, send a message with 'unsubscribe linux-mm' in
> the body to majordomo@kvack.org. For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-20 15:20 +0200 |
| Message-ID | <rM7ho-gv-31@gated-at.bofh.it> |
| In reply to | #1426245 |
On Mon, Jun 20, 2016 at 03:39:43PM +0900, Joonsoo Kim wrote:
> CCing Paul to ask some question.
>
> On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> > Hi Joonsoo,
> >
> > On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> > >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> > >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> > >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> > >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> > >> >> >> > lock. But, accuracy isn't that important because race window would be
> > >> >> >> > even small and if there is too much free object, cache reaper would reap
> > >> >> >> > it. So, this patch makes the check for free object exisistence not to
> > >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> >
> > >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> > >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> > >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> >
> > > It's curious that synchronize_sched() has some effect in this early
> > > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> > >
> > > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> > >
> > > First, I'd like to confirm that num_online_cpus() is correct.
> > > Could you try following patch and give me a dmesg?
> > >
> > > Thanks.
> > >
> > > ------->8----------
> > > diff --git a/mm/slab.c b/mm/slab.c
> > > index 763096a..5b7300a 100644
> > > --- a/mm/slab.c
> > > +++ b/mm/slab.c
> > > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > * freed after synchronize_sched().
> > > */
> > > - if (force_change)
> > > - synchronize_sched();
> > > + if (force_change) {
> > > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > > + WARN_ON_ONCE(num_online_cpus() > 1);
> > > + }
> >
> > Full dmesg output below.
> >
> > I also tested whether it's the call to synchronize_sched() before or after
> > secondary CPU bringup that hangs.
> >
> > if (force_change && num_online_cpus() <= 1)
> > synchronize_sched();
> >
> > boots.
> >
> > if (force_change && num_online_cpus() > 1)
> > synchronize_sched();
> >
> > hangs.
>
> Hello, Paul.
>
> I changed slab.c to use synchronize_sched() for full memory barrier. First
> call happens on kmem_cache_init_late() and it would not be a problem
> because, at this time, num_online_cpus() <= 1 and synchronize_sched()
> would return immediately. Second call site would be shmem_init()
> and it seems that system hangs on it. Since smp is already initialized
> at that time, there would be some effect of synchronize_sched() but I
> can't imagine what's wrong here. Is it invalid moment to call
> synchronize_sched()?
>
> Note that my x86 virtual machine works fine even if
> synchronize_sched() is called in shmem_init() but Geert's some ARM
> machines (not all ARM machine) don't work well with it.
Color me confused.
Is Geert's ARM system somehow adding the second CPU before
rcu_spawn_gp_kthread() is called, that is, before or during
early_initcall() time?
RCU does assume that its kthreads are created before the second
CPU shows up.
Thanx, Paul
> Thanks.
>
> >
> > Booting Linux on physical CPU 0x0
> > Linux version 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty (geert@ramsan)
> > (gcc version 4.9.0 (GCC) ) #84 SMP Wed Jun 15 10:20:12 CEST 2016
> > CPU: ARMv7 Processor [411fc093] revision 3 (ARMv7), cr=10c5387d
> > CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> > Machine model: EMEV2 KZM9D Board
> > debug: ignoring loglevel setting.
> > Memory policy: Data cache writealloc
> > On node 0 totalpages: 32768
> > free_area_init_node: node 0, pgdat c09286c0, node_mem_map c7efa000
> > Normal zone: 256 pages used for memmap
> > Normal zone: 0 pages reserved
> > Normal zone: 32768 pages, LIFO batch:7
> > percpu: Embedded 12 pages/cpu @c7ed9000 s19264 r8192 d21696 u49152
> > pcpu-alloc: s19264 r8192 d21696 u49152 alloc=12*4096
> > pcpu-alloc: [0] 0 [0] 1
> > Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
> > Kernel command line: console=ttyS1,115200n81 ignore_loglevel
> > root=/dev/nfs ip=dhcp
> > PID hash table entries: 512 (order: -1, 2048 bytes)
> > Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> > Memory: 121144K/131072K available (4243K kernel code, 165K rwdata,
> > 1344K rodata, 2048K init, 264K bss, 9928K reserved, 0K cma-reserved,
> > 0K highmem)
> > Virtual kernel memory layout:
> > vector : 0xffff0000 - 0xffff1000 ( 4 kB)
> > fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
> > vmalloc : 0xc8800000 - 0xff800000 ( 880 MB)
> > lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
> > pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
> > modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
> > .text : 0xc0008000 - 0xc0674eb8 (6580 kB)
> > .init : 0xc0700000 - 0xc0900000 (2048 kB)
> > .data : 0xc0900000 - 0xc0929420 ( 166 kB)
> > .bss : 0xc092b000 - 0xc096d1e8 ( 265 kB)
> > Hierarchical RCU implementation.
> > Build-time adjustment of leaf fanout to 32.
> > RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
> > RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
> > NR_IRQS:16 nr_irqs:16 16
> > clocksource_probe: no matching clocksources found
> > sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every
> > 21474836475000000ns
> > ------------[ cut here ]------------
> > WARNING: CPU: 0 PID: 0 at mm/slab.c:975 setup_kmem_cache_node+0x160/0x1c8
> > Modules linked in:
> > CPU: 0 PID: 0 Comm: swapper/0 Not tainted
> > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > [<c011fad0>] (warn_slowpath_null) from [<c01ced4c>]
> > (setup_kmem_cache_node+0x160/0x1c8)
> > [<c01ced4c>] (setup_kmem_cache_node) from [<c01cf02c>]
> > (__do_tune_cpucache+0xf4/0x114)
> > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > [<c01cf0b0>] (enable_cpucache) from [<c0710324>]
> > (kmem_cache_init_late+0x40/0x84)
> > [<c0710324>] (kmem_cache_init_late) from [<c0700af8>] (start_kernel+0x238/0x36c)
> > [<c0700af8>] (start_kernel) from [<4000807c>] (0x4000807c)
> > ---[ end trace cb88537fdc8fa200 ]---
> > Console: colour dummy device 80x30
> > Calibrating delay loop (skipped) preset value.. 1066.00 BogoMIPS (lpj=5330000)
> > pid_max: default: 32768 minimum: 301
> > Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > CPU: Testing write buffer coherency: ok
> > CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> > Setting up static identity map for 0x40100000 - 0x40100058
> > CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> > Brought up 2 CPUs
> > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > CPU: All CPU(s) started in SVC mode.
> > ------------[ cut here ]------------
> > WARNING: CPU: 0 PID: 1 at mm/slab.c:976 setup_kmem_cache_node+0x198/0x1c8
> > Modules linked in:
> > CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
> > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > [<c011fad0>] (warn_slowpath_null) from [<c01ced84>]
> > (setup_kmem_cache_node+0x198/0x1c8)
> > [<c01ced84>] (setup_kmem_cache_node) from [<c01cf02c>]
> > (__do_tune_cpucache+0xf4/0x114)
> > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > [<c01cf0b0>] (enable_cpucache) from [<c01cf4cc>]
> > (__kmem_cache_create+0x1a0/0x1c8)
> > [<c01cf4cc>] (__kmem_cache_create) from [<c01b2904>]
> > (kmem_cache_create+0xbc/0x190)
> > [<c01b2904>] (kmem_cache_create) from [<c070d724>] (shmem_init+0x34/0xb0)
> > [<c070d724>] (shmem_init) from [<c0700cc4>] (kernel_init_freeable+0x98/0x1ec)
> > [<c0700cc4>] (kernel_init_freeable) from [<c0497760>] (kernel_init+0x8/0x110)
> > [<c0497760>] (kernel_init) from [<c0106c78>] (ret_from_fork+0x14/0x3c)
> > ---[ end trace cb88537fdc8fa201 ]---
> > devtmpfs: initialized
> > VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
> > clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
> > max_idle_ns: 19112604462750000 ns
> > pinctrl core: initialized pinctrl subsystem
> > NET: Registered protocol family 16
> > DMA: preallocated 256 KiB pool for atomic coherent allocations
> > sh-pfc e0140200.pfc: emev2_pfc support registered
> > gpiochip_find_base: found new base at 992
> > gpio gpiochip0: (e0050000.gpio): created GPIO range 0->31 ==>
> > e0140200.pfc PIN 0->31
> > gpio gpiochip0: (e0050000.gpio): added GPIO chardev (254:0)
> > gpiochip_setup_dev: registered GPIOs 992 to 1023 on device: gpiochip0
> > (e0050000.gpio)
> > gpiochip_find_base: found new base at 960
> > gpio gpiochip1: (e0050080.gpio): created GPIO range 0->31 ==>
> > e0140200.pfc PIN 32->63
> > gpio gpiochip1: (e0050080.gpio): added GPIO chardev (254:1)
> > gpiochip_setup_dev: registered GPIOs 960 to 991 on device: gpiochip1
> > (e0050080.gpio)
> > gpiochip_find_base: found new base at 928
> > gpio gpiochip2: (e0050100.gpio): created GPIO range 0->31 ==>
> > e0140200.pfc PIN 64->95
> > gpio gpiochip2: (e0050100.gpio): added GPIO chardev (254:2)
> > gpiochip_setup_dev: registered GPIOs 928 to 959 on device: gpiochip2
> > (e0050100.gpio)
> > gpiochip_find_base: found new base at 896
> > gpio gpiochip3: (e0050180.gpio): created GPIO range 0->31 ==>
> > e0140200.pfc PIN 96->127
> > gpio gpiochip3: (e0050180.gpio): added GPIO chardev (254:3)
> > gpiochip_setup_dev: registered GPIOs 896 to 927 on device: gpiochip3
> > (e0050180.gpio)
> > gpiochip_find_base: found new base at 865
> > gpio gpiochip4: (e0050200.gpio): created GPIO range 0->30 ==>
> > e0140200.pfc PIN 128->158
> > gpio gpiochip4: (e0050200.gpio): added GPIO chardev (254:4)
> > gpiochip_setup_dev: registered GPIOs 865 to 895 on device: gpiochip4
> > (e0050200.gpio)
> > gio: map hw irq = 1, irq = 35
> > gio: sense irq = 1, mode = 8
> > No ATAGs?
> > hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> > hw-breakpoint: maximum watchpoint size is 4 bytes.
> > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@0[0]'
> > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@1[0]'
> > SCSI subsystem initialized
> > usbcore: registered new interface driver usbfs
> > usbcore: registered new interface driver hub
> > usbcore: registered new device driver usb
> > em_sti e0180000.timer: used for clock events
> > em_sti e0180000.timer: used for oneshot clock events
> > em_sti e0180000.timer: used as clock source
> > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > 0x1ef4687b1, max_idle_ns: 3697658158765000000 ns
> > Advanced Linux Sound Architecture Driver Initialized.
> > NET: Registered protocol family 23
> > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > 0x1ef4687b1, max_idle_ns: 112843571739654 ns
> > clocksource: Switched to clocksource e0180000.timer
> > NET: Registered protocol family 2
> > TCP established hash table entries: 1024 (order: 0, 4096 bytes)
> > TCP bind hash table entries: 1024 (order: 2, 20480 bytes)
> > TCP: Hash tables configured (established 1024 bind 1024)
> > UDP hash table entries: 256 (order: 1, 12288 bytes)
> > UDP-Lite hash table entries: 256 (order: 1, 12288 bytes)
> > NET: Registered protocol family 1
> > RPC: Registered named UNIX socket transport module.
> > RPC: Registered udp transport module.
> > RPC: Registered tcp transport module.
> > RPC: Registered tcp NFSv4.1 backchannel transport module.
> > Clockevents: could not switch to one-shot mode:
> > Clockevents: could not switch to one-shot mode: dummy_timer is not functional.
> > Could not switch to high resolution mode on CPU 0
> > dummy_timer is not functional.
> > Could not switch to high resolution mode on CPU 1
> > hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> > futex hash table entries: 512 (order: 3, 32768 bytes)
> > workingset: timestamp_bits=28 max_order=15 bucket_order=0
> > NFS: Registering the id_resolver key type
> > Key type id_resolver registered
> > Key type id_legacy registered
> > nfs4filelayout_init: NFSv4 File Layout Driver Registering...
> > io scheduler noop registered (default)
> > Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> > e1020000.serial: ttyS0 at MMIO 0xe1020000 (irq = 19, base_baud =
> > 796444) is a 16550A
> > e1030000.serial: ttyS1 at MMIO 0xe1030000 (irq = 20, base_baud =
> > 7168000) is a 16550A
> > console [ttyS1] enabled
> > e1040000.serial: ttyS2 at MMIO 0xe1040000 (irq = 21, base_baud =
> > 14336000) is a 16550A
> > e1050000.serial: ttyS3 at MMIO 0xe1050000 (irq = 22, base_baud =
> > 2389333) is a 16550A
> > gio: sense irq = 1, mode = 8
> > libphy: smsc911x-mdio: probed
> > Generic PHY 20000000.etherne:01: attached PHY driver [Generic PHY]
> > (mii_bus:phy_addr=20000000.etherne:01, irq=-1)
> > smsc911x 20000000.ethernet eth0: MAC Address: 00:01:9b:04:03:cf
> > usbcore: registered new interface driver usb-storage
> > i2c /dev entries driver
> > em-i2c e0070000.i2c: Added i2c controller 0, irq 33
> > em-i2c e10a0000.i2c: Added i2c controller 1, irq 34
> > cpu cpu0: failed to get clock: -2
> > cpufreq-dt: probe of cpufreq-dt failed with error -2
> > ledtrig-cpu: registered to indicate activity on CPUs
> > usbcore: registered new interface driver usbhid
> > usbhid: USB HID core driver
> > NET: Registered protocol family 17
> > Key type dns_resolver registered
> > Registering SWP/SWPB emulation handler
> > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > '/gpio_keys/button@1[0]' - status (0)
> > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > '/gpio_keys/button@2[0]' - status (0)
> > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > '/gpio_keys/button@3[0]' - status (0)
> > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > '/gpio_keys/button@4[0]' - status (0)
> > gpio-1006 (DSW2-1): gpiod_set_debounce: missing set() or
> > set_debounce() operations
> > gio: map hw irq = 14, irq = 36
> > gio: sense irq = 14, mode = 12
> > gpio-1007 (DSW2-2): gpiod_set_debounce: missing set() or
> > set_debounce() operations
> > gio: map hw irq = 15, irq = 37
> > gio: sense irq = 15, mode = 12
> > gpio-1008 (DSW2-3): gpiod_set_debounce: missing set() or
> > set_debounce() operations
> > gio: map hw irq = 16, irq = 38
> > gio: sense irq = 16, mode = 12
> > gpio-1009 (DSW2-4): gpiod_set_debounce: missing set() or
> > set_debounce() operations
> > gio: map hw irq = 17, irq = 39
> > gio: sense irq = 17, mode = 12
> > input: gpio_keys as /devices/platform/gpio_keys/input/input0
> > hctosys: unable to open rtc device (rtc0)
> > smsc911x 20000000.ethernet eth0: SMSC911x/921x identified at 0xc8880000, IRQ: 35
> > Sending DHCP requests .., OK
> > IP-Config: Got DHCP answer from 192.168.97.254, my address is 192.168.97.215
> > IP-Config: Complete:
> > device=eth0, hwaddr=00:01:9b:04:03:cf, ipaddr=192.168.97.215,
> > mask=255.255.255.0, gw=192.168.97.254
> > host=192.168.97.215, domain=of.borg, nis-domain=(none)
> > bootserver=192.168.97.254, rootserver=192.168.97.254, rootpath=
> > nameserver0=192.168.97.254
> > ALSA device list:
> > No soundcards found.
> > Freeing unused kernel memory: 2048K (c0700000 - c0900000)
> > sysctl: error: 'kernel.hotplug' is an unknown key
> >
> > Gr{oetje,eeting}s,
> >
> > Geert
> >
> > --
> > Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
> >
> > In personal conversations with technical people, I call myself a hacker. But
> > when I'm talking to journalists I just say "programmer" or something like that.
> > -- Linus Torvalds
> >
> > --
> > To unsubscribe, send a message with 'unsubscribe linux-mm' in
> > the body to majordomo@kvack.org. For more info on Linux MM,
> > see: http://www.linux-mm.org/ .
> > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
>
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-21 09:00 +0200 |
| Message-ID | <rMnPb-2gH-11@gated-at.bofh.it> |
| In reply to | #1426598 |
On Mon, Jun 20, 2016 at 06:12:54AM -0700, Paul E. McKenney wrote:
> On Mon, Jun 20, 2016 at 03:39:43PM +0900, Joonsoo Kim wrote:
> > CCing Paul to ask some question.
> >
> > On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> > > Hi Joonsoo,
> > >
> > > On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> > > >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> > > >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> > > >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > > >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> > > >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> > > >> >> >> > lock. But, accuracy isn't that important because race window would be
> > > >> >> >> > even small and if there is too much free object, cache reaper would reap
> > > >> >> >> > it. So, this patch makes the check for free object exisistence not to
> > > >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> > >
> > > >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> > > >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> > > >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> > >
> > > > It's curious that synchronize_sched() has some effect in this early
> > > > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > > > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> > > >
> > > > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> > > >
> > > > First, I'd like to confirm that num_online_cpus() is correct.
> > > > Could you try following patch and give me a dmesg?
> > > >
> > > > Thanks.
> > > >
> > > > ------->8----------
> > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > index 763096a..5b7300a 100644
> > > > --- a/mm/slab.c
> > > > +++ b/mm/slab.c
> > > > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > * freed after synchronize_sched().
> > > > */
> > > > - if (force_change)
> > > > - synchronize_sched();
> > > > + if (force_change) {
> > > > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > > > + WARN_ON_ONCE(num_online_cpus() > 1);
> > > > + }
> > >
> > > Full dmesg output below.
> > >
> > > I also tested whether it's the call to synchronize_sched() before or after
> > > secondary CPU bringup that hangs.
> > >
> > > if (force_change && num_online_cpus() <= 1)
> > > synchronize_sched();
> > >
> > > boots.
> > >
> > > if (force_change && num_online_cpus() > 1)
> > > synchronize_sched();
> > >
> > > hangs.
> >
> > Hello, Paul.
> >
> > I changed slab.c to use synchronize_sched() for full memory barrier. First
> > call happens on kmem_cache_init_late() and it would not be a problem
> > because, at this time, num_online_cpus() <= 1 and synchronize_sched()
> > would return immediately. Second call site would be shmem_init()
> > and it seems that system hangs on it. Since smp is already initialized
> > at that time, there would be some effect of synchronize_sched() but I
> > can't imagine what's wrong here. Is it invalid moment to call
> > synchronize_sched()?
> >
> > Note that my x86 virtual machine works fine even if
> > synchronize_sched() is called in shmem_init() but Geert's some ARM
> > machines (not all ARM machine) don't work well with it.
>
> Color me confused.
>
> Is Geert's ARM system somehow adding the second CPU before
> rcu_spawn_gp_kthread() is called, that is, before or during
> early_initcall() time?
Hang would happen on shmem_init() which is called in do_basic_setup().
do_basic_setup() is called after early_initcall().
Hmm... Is it okay to call synchronize_sched() by kernel thread?
Thanks.
>
> RCU does assume that its kthreads are created before the second
> CPU shows up.
>
> Thanx, Paul
>
> > Thanks.
> >
> > >
> > > Booting Linux on physical CPU 0x0
> > > Linux version 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty (geert@ramsan)
> > > (gcc version 4.9.0 (GCC) ) #84 SMP Wed Jun 15 10:20:12 CEST 2016
> > > CPU: ARMv7 Processor [411fc093] revision 3 (ARMv7), cr=10c5387d
> > > CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> > > Machine model: EMEV2 KZM9D Board
> > > debug: ignoring loglevel setting.
> > > Memory policy: Data cache writealloc
> > > On node 0 totalpages: 32768
> > > free_area_init_node: node 0, pgdat c09286c0, node_mem_map c7efa000
> > > Normal zone: 256 pages used for memmap
> > > Normal zone: 0 pages reserved
> > > Normal zone: 32768 pages, LIFO batch:7
> > > percpu: Embedded 12 pages/cpu @c7ed9000 s19264 r8192 d21696 u49152
> > > pcpu-alloc: s19264 r8192 d21696 u49152 alloc=12*4096
> > > pcpu-alloc: [0] 0 [0] 1
> > > Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
> > > Kernel command line: console=ttyS1,115200n81 ignore_loglevel
> > > root=/dev/nfs ip=dhcp
> > > PID hash table entries: 512 (order: -1, 2048 bytes)
> > > Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > > Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> > > Memory: 121144K/131072K available (4243K kernel code, 165K rwdata,
> > > 1344K rodata, 2048K init, 264K bss, 9928K reserved, 0K cma-reserved,
> > > 0K highmem)
> > > Virtual kernel memory layout:
> > > vector : 0xffff0000 - 0xffff1000 ( 4 kB)
> > > fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
> > > vmalloc : 0xc8800000 - 0xff800000 ( 880 MB)
> > > lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
> > > pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
> > > modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
> > > .text : 0xc0008000 - 0xc0674eb8 (6580 kB)
> > > .init : 0xc0700000 - 0xc0900000 (2048 kB)
> > > .data : 0xc0900000 - 0xc0929420 ( 166 kB)
> > > .bss : 0xc092b000 - 0xc096d1e8 ( 265 kB)
> > > Hierarchical RCU implementation.
> > > Build-time adjustment of leaf fanout to 32.
> > > RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
> > > RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
> > > NR_IRQS:16 nr_irqs:16 16
> > > clocksource_probe: no matching clocksources found
> > > sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every
> > > 21474836475000000ns
> > > ------------[ cut here ]------------
> > > WARNING: CPU: 0 PID: 0 at mm/slab.c:975 setup_kmem_cache_node+0x160/0x1c8
> > > Modules linked in:
> > > CPU: 0 PID: 0 Comm: swapper/0 Not tainted
> > > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > > [<c011fad0>] (warn_slowpath_null) from [<c01ced4c>]
> > > (setup_kmem_cache_node+0x160/0x1c8)
> > > [<c01ced4c>] (setup_kmem_cache_node) from [<c01cf02c>]
> > > (__do_tune_cpucache+0xf4/0x114)
> > > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > > [<c01cf0b0>] (enable_cpucache) from [<c0710324>]
> > > (kmem_cache_init_late+0x40/0x84)
> > > [<c0710324>] (kmem_cache_init_late) from [<c0700af8>] (start_kernel+0x238/0x36c)
> > > [<c0700af8>] (start_kernel) from [<4000807c>] (0x4000807c)
> > > ---[ end trace cb88537fdc8fa200 ]---
> > > Console: colour dummy device 80x30
> > > Calibrating delay loop (skipped) preset value.. 1066.00 BogoMIPS (lpj=5330000)
> > > pid_max: default: 32768 minimum: 301
> > > Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > > Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > > CPU: Testing write buffer coherency: ok
> > > CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> > > Setting up static identity map for 0x40100000 - 0x40100058
> > > CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> > > Brought up 2 CPUs
> > > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > > CPU: All CPU(s) started in SVC mode.
> > > ------------[ cut here ]------------
> > > WARNING: CPU: 0 PID: 1 at mm/slab.c:976 setup_kmem_cache_node+0x198/0x1c8
> > > Modules linked in:
> > > CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
> > > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > > [<c011fad0>] (warn_slowpath_null) from [<c01ced84>]
> > > (setup_kmem_cache_node+0x198/0x1c8)
> > > [<c01ced84>] (setup_kmem_cache_node) from [<c01cf02c>]
> > > (__do_tune_cpucache+0xf4/0x114)
> > > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > > [<c01cf0b0>] (enable_cpucache) from [<c01cf4cc>]
> > > (__kmem_cache_create+0x1a0/0x1c8)
> > > [<c01cf4cc>] (__kmem_cache_create) from [<c01b2904>]
> > > (kmem_cache_create+0xbc/0x190)
> > > [<c01b2904>] (kmem_cache_create) from [<c070d724>] (shmem_init+0x34/0xb0)
> > > [<c070d724>] (shmem_init) from [<c0700cc4>] (kernel_init_freeable+0x98/0x1ec)
> > > [<c0700cc4>] (kernel_init_freeable) from [<c0497760>] (kernel_init+0x8/0x110)
> > > [<c0497760>] (kernel_init) from [<c0106c78>] (ret_from_fork+0x14/0x3c)
> > > ---[ end trace cb88537fdc8fa201 ]---
> > > devtmpfs: initialized
> > > VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
> > > clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
> > > max_idle_ns: 19112604462750000 ns
> > > pinctrl core: initialized pinctrl subsystem
> > > NET: Registered protocol family 16
> > > DMA: preallocated 256 KiB pool for atomic coherent allocations
> > > sh-pfc e0140200.pfc: emev2_pfc support registered
> > > gpiochip_find_base: found new base at 992
> > > gpio gpiochip0: (e0050000.gpio): created GPIO range 0->31 ==>
> > > e0140200.pfc PIN 0->31
> > > gpio gpiochip0: (e0050000.gpio): added GPIO chardev (254:0)
> > > gpiochip_setup_dev: registered GPIOs 992 to 1023 on device: gpiochip0
> > > (e0050000.gpio)
> > > gpiochip_find_base: found new base at 960
> > > gpio gpiochip1: (e0050080.gpio): created GPIO range 0->31 ==>
> > > e0140200.pfc PIN 32->63
> > > gpio gpiochip1: (e0050080.gpio): added GPIO chardev (254:1)
> > > gpiochip_setup_dev: registered GPIOs 960 to 991 on device: gpiochip1
> > > (e0050080.gpio)
> > > gpiochip_find_base: found new base at 928
> > > gpio gpiochip2: (e0050100.gpio): created GPIO range 0->31 ==>
> > > e0140200.pfc PIN 64->95
> > > gpio gpiochip2: (e0050100.gpio): added GPIO chardev (254:2)
> > > gpiochip_setup_dev: registered GPIOs 928 to 959 on device: gpiochip2
> > > (e0050100.gpio)
> > > gpiochip_find_base: found new base at 896
> > > gpio gpiochip3: (e0050180.gpio): created GPIO range 0->31 ==>
> > > e0140200.pfc PIN 96->127
> > > gpio gpiochip3: (e0050180.gpio): added GPIO chardev (254:3)
> > > gpiochip_setup_dev: registered GPIOs 896 to 927 on device: gpiochip3
> > > (e0050180.gpio)
> > > gpiochip_find_base: found new base at 865
> > > gpio gpiochip4: (e0050200.gpio): created GPIO range 0->30 ==>
> > > e0140200.pfc PIN 128->158
> > > gpio gpiochip4: (e0050200.gpio): added GPIO chardev (254:4)
> > > gpiochip_setup_dev: registered GPIOs 865 to 895 on device: gpiochip4
> > > (e0050200.gpio)
> > > gio: map hw irq = 1, irq = 35
> > > gio: sense irq = 1, mode = 8
> > > No ATAGs?
> > > hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> > > hw-breakpoint: maximum watchpoint size is 4 bytes.
> > > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@0[0]'
> > > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@1[0]'
> > > SCSI subsystem initialized
> > > usbcore: registered new interface driver usbfs
> > > usbcore: registered new interface driver hub
> > > usbcore: registered new device driver usb
> > > em_sti e0180000.timer: used for clock events
> > > em_sti e0180000.timer: used for oneshot clock events
> > > em_sti e0180000.timer: used as clock source
> > > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > > 0x1ef4687b1, max_idle_ns: 3697658158765000000 ns
> > > Advanced Linux Sound Architecture Driver Initialized.
> > > NET: Registered protocol family 23
> > > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > > 0x1ef4687b1, max_idle_ns: 112843571739654 ns
> > > clocksource: Switched to clocksource e0180000.timer
> > > NET: Registered protocol family 2
> > > TCP established hash table entries: 1024 (order: 0, 4096 bytes)
> > > TCP bind hash table entries: 1024 (order: 2, 20480 bytes)
> > > TCP: Hash tables configured (established 1024 bind 1024)
> > > UDP hash table entries: 256 (order: 1, 12288 bytes)
> > > UDP-Lite hash table entries: 256 (order: 1, 12288 bytes)
> > > NET: Registered protocol family 1
> > > RPC: Registered named UNIX socket transport module.
> > > RPC: Registered udp transport module.
> > > RPC: Registered tcp transport module.
> > > RPC: Registered tcp NFSv4.1 backchannel transport module.
> > > Clockevents: could not switch to one-shot mode:
> > > Clockevents: could not switch to one-shot mode: dummy_timer is not functional.
> > > Could not switch to high resolution mode on CPU 0
> > > dummy_timer is not functional.
> > > Could not switch to high resolution mode on CPU 1
> > > hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> > > futex hash table entries: 512 (order: 3, 32768 bytes)
> > > workingset: timestamp_bits=28 max_order=15 bucket_order=0
> > > NFS: Registering the id_resolver key type
> > > Key type id_resolver registered
> > > Key type id_legacy registered
> > > nfs4filelayout_init: NFSv4 File Layout Driver Registering...
> > > io scheduler noop registered (default)
> > > Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> > > e1020000.serial: ttyS0 at MMIO 0xe1020000 (irq = 19, base_baud =
> > > 796444) is a 16550A
> > > e1030000.serial: ttyS1 at MMIO 0xe1030000 (irq = 20, base_baud =
> > > 7168000) is a 16550A
> > > console [ttyS1] enabled
> > > e1040000.serial: ttyS2 at MMIO 0xe1040000 (irq = 21, base_baud =
> > > 14336000) is a 16550A
> > > e1050000.serial: ttyS3 at MMIO 0xe1050000 (irq = 22, base_baud =
> > > 2389333) is a 16550A
> > > gio: sense irq = 1, mode = 8
> > > libphy: smsc911x-mdio: probed
> > > Generic PHY 20000000.etherne:01: attached PHY driver [Generic PHY]
> > > (mii_bus:phy_addr=20000000.etherne:01, irq=-1)
> > > smsc911x 20000000.ethernet eth0: MAC Address: 00:01:9b:04:03:cf
> > > usbcore: registered new interface driver usb-storage
> > > i2c /dev entries driver
> > > em-i2c e0070000.i2c: Added i2c controller 0, irq 33
> > > em-i2c e10a0000.i2c: Added i2c controller 1, irq 34
> > > cpu cpu0: failed to get clock: -2
> > > cpufreq-dt: probe of cpufreq-dt failed with error -2
> > > ledtrig-cpu: registered to indicate activity on CPUs
> > > usbcore: registered new interface driver usbhid
> > > usbhid: USB HID core driver
> > > NET: Registered protocol family 17
> > > Key type dns_resolver registered
> > > Registering SWP/SWPB emulation handler
> > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > '/gpio_keys/button@1[0]' - status (0)
> > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > '/gpio_keys/button@2[0]' - status (0)
> > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > '/gpio_keys/button@3[0]' - status (0)
> > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > '/gpio_keys/button@4[0]' - status (0)
> > > gpio-1006 (DSW2-1): gpiod_set_debounce: missing set() or
> > > set_debounce() operations
> > > gio: map hw irq = 14, irq = 36
> > > gio: sense irq = 14, mode = 12
> > > gpio-1007 (DSW2-2): gpiod_set_debounce: missing set() or
> > > set_debounce() operations
> > > gio: map hw irq = 15, irq = 37
> > > gio: sense irq = 15, mode = 12
> > > gpio-1008 (DSW2-3): gpiod_set_debounce: missing set() or
> > > set_debounce() operations
> > > gio: map hw irq = 16, irq = 38
> > > gio: sense irq = 16, mode = 12
> > > gpio-1009 (DSW2-4): gpiod_set_debounce: missing set() or
> > > set_debounce() operations
> > > gio: map hw irq = 17, irq = 39
> > > gio: sense irq = 17, mode = 12
> > > input: gpio_keys as /devices/platform/gpio_keys/input/input0
> > > hctosys: unable to open rtc device (rtc0)
> > > smsc911x 20000000.ethernet eth0: SMSC911x/921x identified at 0xc8880000, IRQ: 35
> > > Sending DHCP requests .., OK
> > > IP-Config: Got DHCP answer from 192.168.97.254, my address is 192.168.97.215
> > > IP-Config: Complete:
> > > device=eth0, hwaddr=00:01:9b:04:03:cf, ipaddr=192.168.97.215,
> > > mask=255.255.255.0, gw=192.168.97.254
> > > host=192.168.97.215, domain=of.borg, nis-domain=(none)
> > > bootserver=192.168.97.254, rootserver=192.168.97.254, rootpath=
> > > nameserver0=192.168.97.254
> > > ALSA device list:
> > > No soundcards found.
> > > Freeing unused kernel memory: 2048K (c0700000 - c0900000)
> > > sysctl: error: 'kernel.hotplug' is an unknown key
> > >
> > > Gr{oetje,eeting}s,
> > >
> > > Geert
> > >
> > > --
> > > Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
> > >
> > > In personal conversations with technical people, I call myself a hacker. But
> > > when I'm talking to journalists I just say "programmer" or something like that.
> > > -- Linus Torvalds
> > >
> > > --
> > > To unsubscribe, send a message with 'unsubscribe linux-mm' in
> > > the body to majordomo@kvack.org. For more info on Linux MM,
> > > see: http://www.linux-mm.org/ .
> > > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
> >
>
> --
> To unsubscribe, send a message with 'unsubscribe linux-mm' in
> the body to majordomo@kvack.org. For more info on Linux MM,
> see: http://www.linux-mm.org/ .
> Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-21 15:00 +0200 |
| Message-ID | <rMtrz-5YF-7@gated-at.bofh.it> |
| In reply to | #1427361 |
On Tue, Jun 21, 2016 at 03:43:02PM +0900, Joonsoo Kim wrote:
> On Mon, Jun 20, 2016 at 06:12:54AM -0700, Paul E. McKenney wrote:
> > On Mon, Jun 20, 2016 at 03:39:43PM +0900, Joonsoo Kim wrote:
> > > CCing Paul to ask some question.
> > >
> > > On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> > > > Hi Joonsoo,
> > > >
> > > > On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> > > > >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> > > > >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> > > > >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > > > >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> > > > >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> > > > >> >> >> > lock. But, accuracy isn't that important because race window would be
> > > > >> >> >> > even small and if there is too much free object, cache reaper would reap
> > > > >> >> >> > it. So, this patch makes the check for free object exisistence not to
> > > > >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> > > >
> > > > >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> > > > >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> > > > >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> > > >
> > > > > It's curious that synchronize_sched() has some effect in this early
> > > > > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > > > > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> > > > >
> > > > > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> > > > >
> > > > > First, I'd like to confirm that num_online_cpus() is correct.
> > > > > Could you try following patch and give me a dmesg?
> > > > >
> > > > > Thanks.
> > > > >
> > > > > ------->8----------
> > > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > > index 763096a..5b7300a 100644
> > > > > --- a/mm/slab.c
> > > > > +++ b/mm/slab.c
> > > > > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > > * freed after synchronize_sched().
> > > > > */
> > > > > - if (force_change)
> > > > > - synchronize_sched();
> > > > > + if (force_change) {
> > > > > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > > > > + WARN_ON_ONCE(num_online_cpus() > 1);
> > > > > + }
> > > >
> > > > Full dmesg output below.
> > > >
> > > > I also tested whether it's the call to synchronize_sched() before or after
> > > > secondary CPU bringup that hangs.
> > > >
> > > > if (force_change && num_online_cpus() <= 1)
> > > > synchronize_sched();
> > > >
> > > > boots.
> > > >
> > > > if (force_change && num_online_cpus() > 1)
> > > > synchronize_sched();
> > > >
> > > > hangs.
> > >
> > > Hello, Paul.
> > >
> > > I changed slab.c to use synchronize_sched() for full memory barrier. First
> > > call happens on kmem_cache_init_late() and it would not be a problem
> > > because, at this time, num_online_cpus() <= 1 and synchronize_sched()
> > > would return immediately. Second call site would be shmem_init()
> > > and it seems that system hangs on it. Since smp is already initialized
> > > at that time, there would be some effect of synchronize_sched() but I
> > > can't imagine what's wrong here. Is it invalid moment to call
> > > synchronize_sched()?
> > >
> > > Note that my x86 virtual machine works fine even if
> > > synchronize_sched() is called in shmem_init() but Geert's some ARM
> > > machines (not all ARM machine) don't work well with it.
> >
> > Color me confused.
> >
> > Is Geert's ARM system somehow adding the second CPU before
> > rcu_spawn_gp_kthread() is called, that is, before or during
> > early_initcall() time?
>
> Hang would happen on shmem_init() which is called in do_basic_setup().
> do_basic_setup() is called after early_initcall().
Thank you for the info!
That should be lat enough that the RCU kthreads are alive and well.
Can you get sysalt-t output?
> Hmm... Is it okay to call synchronize_sched() by kernel thread?
Yes, it can, in fact, rcutorture does this all the time. As do any
number of other kthreads.
Thanx, Paul
> Thanks.
>
> >
> > RCU does assume that its kthreads are created before the second
> > CPU shows up.
> >
> > Thanx, Paul
> >
> > > Thanks.
> > >
> > > >
> > > > Booting Linux on physical CPU 0x0
> > > > Linux version 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty (geert@ramsan)
> > > > (gcc version 4.9.0 (GCC) ) #84 SMP Wed Jun 15 10:20:12 CEST 2016
> > > > CPU: ARMv7 Processor [411fc093] revision 3 (ARMv7), cr=10c5387d
> > > > CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> > > > Machine model: EMEV2 KZM9D Board
> > > > debug: ignoring loglevel setting.
> > > > Memory policy: Data cache writealloc
> > > > On node 0 totalpages: 32768
> > > > free_area_init_node: node 0, pgdat c09286c0, node_mem_map c7efa000
> > > > Normal zone: 256 pages used for memmap
> > > > Normal zone: 0 pages reserved
> > > > Normal zone: 32768 pages, LIFO batch:7
> > > > percpu: Embedded 12 pages/cpu @c7ed9000 s19264 r8192 d21696 u49152
> > > > pcpu-alloc: s19264 r8192 d21696 u49152 alloc=12*4096
> > > > pcpu-alloc: [0] 0 [0] 1
> > > > Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
> > > > Kernel command line: console=ttyS1,115200n81 ignore_loglevel
> > > > root=/dev/nfs ip=dhcp
> > > > PID hash table entries: 512 (order: -1, 2048 bytes)
> > > > Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > > > Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> > > > Memory: 121144K/131072K available (4243K kernel code, 165K rwdata,
> > > > 1344K rodata, 2048K init, 264K bss, 9928K reserved, 0K cma-reserved,
> > > > 0K highmem)
> > > > Virtual kernel memory layout:
> > > > vector : 0xffff0000 - 0xffff1000 ( 4 kB)
> > > > fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
> > > > vmalloc : 0xc8800000 - 0xff800000 ( 880 MB)
> > > > lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
> > > > pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
> > > > modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
> > > > .text : 0xc0008000 - 0xc0674eb8 (6580 kB)
> > > > .init : 0xc0700000 - 0xc0900000 (2048 kB)
> > > > .data : 0xc0900000 - 0xc0929420 ( 166 kB)
> > > > .bss : 0xc092b000 - 0xc096d1e8 ( 265 kB)
> > > > Hierarchical RCU implementation.
> > > > Build-time adjustment of leaf fanout to 32.
> > > > RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
> > > > RCU: Adjusting geometry for rcu_fanout_leaf=32, nr_cpu_ids=2
> > > > NR_IRQS:16 nr_irqs:16 16
> > > > clocksource_probe: no matching clocksources found
> > > > sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every
> > > > 21474836475000000ns
> > > > ------------[ cut here ]------------
> > > > WARNING: CPU: 0 PID: 0 at mm/slab.c:975 setup_kmem_cache_node+0x160/0x1c8
> > > > Modules linked in:
> > > > CPU: 0 PID: 0 Comm: swapper/0 Not tainted
> > > > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > > > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > > > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > > > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > > > [<c011fad0>] (warn_slowpath_null) from [<c01ced4c>]
> > > > (setup_kmem_cache_node+0x160/0x1c8)
> > > > [<c01ced4c>] (setup_kmem_cache_node) from [<c01cf02c>]
> > > > (__do_tune_cpucache+0xf4/0x114)
> > > > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > > > [<c01cf0b0>] (enable_cpucache) from [<c0710324>]
> > > > (kmem_cache_init_late+0x40/0x84)
> > > > [<c0710324>] (kmem_cache_init_late) from [<c0700af8>] (start_kernel+0x238/0x36c)
> > > > [<c0700af8>] (start_kernel) from [<4000807c>] (0x4000807c)
> > > > ---[ end trace cb88537fdc8fa200 ]---
> > > > Console: colour dummy device 80x30
> > > > Calibrating delay loop (skipped) preset value.. 1066.00 BogoMIPS (lpj=5330000)
> > > > pid_max: default: 32768 minimum: 301
> > > > Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > > > Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
> > > > CPU: Testing write buffer coherency: ok
> > > > CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> > > > Setting up static identity map for 0x40100000 - 0x40100058
> > > > CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> > > > Brought up 2 CPUs
> > > > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > > > CPU: All CPU(s) started in SVC mode.
> > > > ------------[ cut here ]------------
> > > > WARNING: CPU: 0 PID: 1 at mm/slab.c:976 setup_kmem_cache_node+0x198/0x1c8
> > > > Modules linked in:
> > > > CPU: 0 PID: 1 Comm: swapper/0 Tainted: G W
> > > > 4.6.0-kzm9d-05060-g801faf0db8947e01-dirty #84
> > > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > > [<c010de08>] (unwind_backtrace) from [<c010a620>] (show_stack+0x10/0x14)
> > > > [<c010a620>] (show_stack) from [<c02b3178>] (dump_stack+0x7c/0x9c)
> > > > [<c02b3178>] (dump_stack) from [<c011f9fc>] (__warn+0xcc/0xfc)
> > > > [<c011f9fc>] (__warn) from [<c011fad0>] (warn_slowpath_null+0x1c/0x24)
> > > > [<c011fad0>] (warn_slowpath_null) from [<c01ced84>]
> > > > (setup_kmem_cache_node+0x198/0x1c8)
> > > > [<c01ced84>] (setup_kmem_cache_node) from [<c01cf02c>]
> > > > (__do_tune_cpucache+0xf4/0x114)
> > > > [<c01cf02c>] (__do_tune_cpucache) from [<c01cf0b0>] (enable_cpucache+0x64/0xb4)
> > > > [<c01cf0b0>] (enable_cpucache) from [<c01cf4cc>]
> > > > (__kmem_cache_create+0x1a0/0x1c8)
> > > > [<c01cf4cc>] (__kmem_cache_create) from [<c01b2904>]
> > > > (kmem_cache_create+0xbc/0x190)
> > > > [<c01b2904>] (kmem_cache_create) from [<c070d724>] (shmem_init+0x34/0xb0)
> > > > [<c070d724>] (shmem_init) from [<c0700cc4>] (kernel_init_freeable+0x98/0x1ec)
> > > > [<c0700cc4>] (kernel_init_freeable) from [<c0497760>] (kernel_init+0x8/0x110)
> > > > [<c0497760>] (kernel_init) from [<c0106c78>] (ret_from_fork+0x14/0x3c)
> > > > ---[ end trace cb88537fdc8fa201 ]---
> > > > devtmpfs: initialized
> > > > VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1
> > > > clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
> > > > max_idle_ns: 19112604462750000 ns
> > > > pinctrl core: initialized pinctrl subsystem
> > > > NET: Registered protocol family 16
> > > > DMA: preallocated 256 KiB pool for atomic coherent allocations
> > > > sh-pfc e0140200.pfc: emev2_pfc support registered
> > > > gpiochip_find_base: found new base at 992
> > > > gpio gpiochip0: (e0050000.gpio): created GPIO range 0->31 ==>
> > > > e0140200.pfc PIN 0->31
> > > > gpio gpiochip0: (e0050000.gpio): added GPIO chardev (254:0)
> > > > gpiochip_setup_dev: registered GPIOs 992 to 1023 on device: gpiochip0
> > > > (e0050000.gpio)
> > > > gpiochip_find_base: found new base at 960
> > > > gpio gpiochip1: (e0050080.gpio): created GPIO range 0->31 ==>
> > > > e0140200.pfc PIN 32->63
> > > > gpio gpiochip1: (e0050080.gpio): added GPIO chardev (254:1)
> > > > gpiochip_setup_dev: registered GPIOs 960 to 991 on device: gpiochip1
> > > > (e0050080.gpio)
> > > > gpiochip_find_base: found new base at 928
> > > > gpio gpiochip2: (e0050100.gpio): created GPIO range 0->31 ==>
> > > > e0140200.pfc PIN 64->95
> > > > gpio gpiochip2: (e0050100.gpio): added GPIO chardev (254:2)
> > > > gpiochip_setup_dev: registered GPIOs 928 to 959 on device: gpiochip2
> > > > (e0050100.gpio)
> > > > gpiochip_find_base: found new base at 896
> > > > gpio gpiochip3: (e0050180.gpio): created GPIO range 0->31 ==>
> > > > e0140200.pfc PIN 96->127
> > > > gpio gpiochip3: (e0050180.gpio): added GPIO chardev (254:3)
> > > > gpiochip_setup_dev: registered GPIOs 896 to 927 on device: gpiochip3
> > > > (e0050180.gpio)
> > > > gpiochip_find_base: found new base at 865
> > > > gpio gpiochip4: (e0050200.gpio): created GPIO range 0->30 ==>
> > > > e0140200.pfc PIN 128->158
> > > > gpio gpiochip4: (e0050200.gpio): added GPIO chardev (254:4)
> > > > gpiochip_setup_dev: registered GPIOs 865 to 895 on device: gpiochip4
> > > > (e0050200.gpio)
> > > > gio: map hw irq = 1, irq = 35
> > > > gio: sense irq = 1, mode = 8
> > > > No ATAGs?
> > > > hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> > > > hw-breakpoint: maximum watchpoint size is 4 bytes.
> > > > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@0[0]'
> > > > of_get_named_gpiod_flags: can't parse 'gpio' property of node '/regulator@1[0]'
> > > > SCSI subsystem initialized
> > > > usbcore: registered new interface driver usbfs
> > > > usbcore: registered new interface driver hub
> > > > usbcore: registered new device driver usb
> > > > em_sti e0180000.timer: used for clock events
> > > > em_sti e0180000.timer: used for oneshot clock events
> > > > em_sti e0180000.timer: used as clock source
> > > > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > > > 0x1ef4687b1, max_idle_ns: 3697658158765000000 ns
> > > > Advanced Linux Sound Architecture Driver Initialized.
> > > > NET: Registered protocol family 23
> > > > clocksource: e0180000.timer: mask: 0xffffffffffff max_cycles:
> > > > 0x1ef4687b1, max_idle_ns: 112843571739654 ns
> > > > clocksource: Switched to clocksource e0180000.timer
> > > > NET: Registered protocol family 2
> > > > TCP established hash table entries: 1024 (order: 0, 4096 bytes)
> > > > TCP bind hash table entries: 1024 (order: 2, 20480 bytes)
> > > > TCP: Hash tables configured (established 1024 bind 1024)
> > > > UDP hash table entries: 256 (order: 1, 12288 bytes)
> > > > UDP-Lite hash table entries: 256 (order: 1, 12288 bytes)
> > > > NET: Registered protocol family 1
> > > > RPC: Registered named UNIX socket transport module.
> > > > RPC: Registered udp transport module.
> > > > RPC: Registered tcp transport module.
> > > > RPC: Registered tcp NFSv4.1 backchannel transport module.
> > > > Clockevents: could not switch to one-shot mode:
> > > > Clockevents: could not switch to one-shot mode: dummy_timer is not functional.
> > > > Could not switch to high resolution mode on CPU 0
> > > > dummy_timer is not functional.
> > > > Could not switch to high resolution mode on CPU 1
> > > > hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> > > > futex hash table entries: 512 (order: 3, 32768 bytes)
> > > > workingset: timestamp_bits=28 max_order=15 bucket_order=0
> > > > NFS: Registering the id_resolver key type
> > > > Key type id_resolver registered
> > > > Key type id_legacy registered
> > > > nfs4filelayout_init: NFSv4 File Layout Driver Registering...
> > > > io scheduler noop registered (default)
> > > > Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
> > > > e1020000.serial: ttyS0 at MMIO 0xe1020000 (irq = 19, base_baud =
> > > > 796444) is a 16550A
> > > > e1030000.serial: ttyS1 at MMIO 0xe1030000 (irq = 20, base_baud =
> > > > 7168000) is a 16550A
> > > > console [ttyS1] enabled
> > > > e1040000.serial: ttyS2 at MMIO 0xe1040000 (irq = 21, base_baud =
> > > > 14336000) is a 16550A
> > > > e1050000.serial: ttyS3 at MMIO 0xe1050000 (irq = 22, base_baud =
> > > > 2389333) is a 16550A
> > > > gio: sense irq = 1, mode = 8
> > > > libphy: smsc911x-mdio: probed
> > > > Generic PHY 20000000.etherne:01: attached PHY driver [Generic PHY]
> > > > (mii_bus:phy_addr=20000000.etherne:01, irq=-1)
> > > > smsc911x 20000000.ethernet eth0: MAC Address: 00:01:9b:04:03:cf
> > > > usbcore: registered new interface driver usb-storage
> > > > i2c /dev entries driver
> > > > em-i2c e0070000.i2c: Added i2c controller 0, irq 33
> > > > em-i2c e10a0000.i2c: Added i2c controller 1, irq 34
> > > > cpu cpu0: failed to get clock: -2
> > > > cpufreq-dt: probe of cpufreq-dt failed with error -2
> > > > ledtrig-cpu: registered to indicate activity on CPUs
> > > > usbcore: registered new interface driver usbhid
> > > > usbhid: USB HID core driver
> > > > NET: Registered protocol family 17
> > > > Key type dns_resolver registered
> > > > Registering SWP/SWPB emulation handler
> > > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > > '/gpio_keys/button@1[0]' - status (0)
> > > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > > '/gpio_keys/button@2[0]' - status (0)
> > > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > > '/gpio_keys/button@3[0]' - status (0)
> > > > of_get_named_gpiod_flags: parsed 'gpios' property of node
> > > > '/gpio_keys/button@4[0]' - status (0)
> > > > gpio-1006 (DSW2-1): gpiod_set_debounce: missing set() or
> > > > set_debounce() operations
> > > > gio: map hw irq = 14, irq = 36
> > > > gio: sense irq = 14, mode = 12
> > > > gpio-1007 (DSW2-2): gpiod_set_debounce: missing set() or
> > > > set_debounce() operations
> > > > gio: map hw irq = 15, irq = 37
> > > > gio: sense irq = 15, mode = 12
> > > > gpio-1008 (DSW2-3): gpiod_set_debounce: missing set() or
> > > > set_debounce() operations
> > > > gio: map hw irq = 16, irq = 38
> > > > gio: sense irq = 16, mode = 12
> > > > gpio-1009 (DSW2-4): gpiod_set_debounce: missing set() or
> > > > set_debounce() operations
> > > > gio: map hw irq = 17, irq = 39
> > > > gio: sense irq = 17, mode = 12
> > > > input: gpio_keys as /devices/platform/gpio_keys/input/input0
> > > > hctosys: unable to open rtc device (rtc0)
> > > > smsc911x 20000000.ethernet eth0: SMSC911x/921x identified at 0xc8880000, IRQ: 35
> > > > Sending DHCP requests .., OK
> > > > IP-Config: Got DHCP answer from 192.168.97.254, my address is 192.168.97.215
> > > > IP-Config: Complete:
> > > > device=eth0, hwaddr=00:01:9b:04:03:cf, ipaddr=192.168.97.215,
> > > > mask=255.255.255.0, gw=192.168.97.254
> > > > host=192.168.97.215, domain=of.borg, nis-domain=(none)
> > > > bootserver=192.168.97.254, rootserver=192.168.97.254, rootpath=
> > > > nameserver0=192.168.97.254
> > > > ALSA device list:
> > > > No soundcards found.
> > > > Freeing unused kernel memory: 2048K (c0700000 - c0900000)
> > > > sysctl: error: 'kernel.hotplug' is an unknown key
> > > >
> > > > Gr{oetje,eeting}s,
> > > >
> > > > Geert
> > > >
> > > > --
> > > > Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
> > > >
> > > > In personal conversations with technical people, I call myself a hacker. But
> > > > when I'm talking to journalists I just say "programmer" or something like that.
> > > > -- Linus Torvalds
> > > >
> > > > --
> > > > To unsubscribe, send a message with 'unsubscribe linux-mm' in
> > > > the body to majordomo@kvack.org. For more info on Linux MM,
> > > > see: http://www.linux-mm.org/ .
> > > > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
> > >
> >
> > --
> > To unsubscribe, send a message with 'unsubscribe linux-mm' in
> > the body to majordomo@kvack.org. For more info on Linux MM,
> > see: http://www.linux-mm.org/ .
> > Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>
>
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-22 02:50 +0200 |
| Message-ID | <rMEwF-4Et-5@gated-at.bofh.it> |
| In reply to | #1427724 |
On Tue, Jun 21, 2016 at 05:54:06AM -0700, Paul E. McKenney wrote:
> On Tue, Jun 21, 2016 at 03:43:02PM +0900, Joonsoo Kim wrote:
> > On Mon, Jun 20, 2016 at 06:12:54AM -0700, Paul E. McKenney wrote:
> > > On Mon, Jun 20, 2016 at 03:39:43PM +0900, Joonsoo Kim wrote:
> > > > CCing Paul to ask some question.
> > > >
> > > > On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> > > > > Hi Joonsoo,
> > > > >
> > > > > On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> > > > > >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> > > > > >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> > > > > >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > > > > >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> > > > > >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> > > > > >> >> >> > lock. But, accuracy isn't that important because race window would be
> > > > > >> >> >> > even small and if there is too much free object, cache reaper would reap
> > > > > >> >> >> > it. So, this patch makes the check for free object exisistence not to
> > > > > >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> > > > >
> > > > > >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> > > > > >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> > > > > >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> > > > >
> > > > > > It's curious that synchronize_sched() has some effect in this early
> > > > > > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > > > > > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> > > > > >
> > > > > > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> > > > > >
> > > > > > First, I'd like to confirm that num_online_cpus() is correct.
> > > > > > Could you try following patch and give me a dmesg?
> > > > > >
> > > > > > Thanks.
> > > > > >
> > > > > > ------->8----------
> > > > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > > > index 763096a..5b7300a 100644
> > > > > > --- a/mm/slab.c
> > > > > > +++ b/mm/slab.c
> > > > > > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > > > * freed after synchronize_sched().
> > > > > > */
> > > > > > - if (force_change)
> > > > > > - synchronize_sched();
> > > > > > + if (force_change) {
> > > > > > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > > > > > + WARN_ON_ONCE(num_online_cpus() > 1);
> > > > > > + }
> > > > >
> > > > > Full dmesg output below.
> > > > >
> > > > > I also tested whether it's the call to synchronize_sched() before or after
> > > > > secondary CPU bringup that hangs.
> > > > >
> > > > > if (force_change && num_online_cpus() <= 1)
> > > > > synchronize_sched();
> > > > >
> > > > > boots.
> > > > >
> > > > > if (force_change && num_online_cpus() > 1)
> > > > > synchronize_sched();
> > > > >
> > > > > hangs.
> > > >
> > > > Hello, Paul.
> > > >
> > > > I changed slab.c to use synchronize_sched() for full memory barrier. First
> > > > call happens on kmem_cache_init_late() and it would not be a problem
> > > > because, at this time, num_online_cpus() <= 1 and synchronize_sched()
> > > > would return immediately. Second call site would be shmem_init()
> > > > and it seems that system hangs on it. Since smp is already initialized
> > > > at that time, there would be some effect of synchronize_sched() but I
> > > > can't imagine what's wrong here. Is it invalid moment to call
> > > > synchronize_sched()?
> > > >
> > > > Note that my x86 virtual machine works fine even if
> > > > synchronize_sched() is called in shmem_init() but Geert's some ARM
> > > > machines (not all ARM machine) don't work well with it.
> > >
> > > Color me confused.
> > >
> > > Is Geert's ARM system somehow adding the second CPU before
> > > rcu_spawn_gp_kthread() is called, that is, before or during
> > > early_initcall() time?
> >
> > Hang would happen on shmem_init() which is called in do_basic_setup().
> > do_basic_setup() is called after early_initcall().
>
> Thank you for the info!
>
> That should be lat enough that the RCU kthreads are alive and well.
>
> Can you get sysalt-t output?
>
> > Hmm... Is it okay to call synchronize_sched() by kernel thread?
>
> Yes, it can, in fact, rcutorture does this all the time. As do any
> number of other kthreads.
Paul, thanks for confirmation.
Geert, we need to try more debugging.
Could you try below patch to check who causes the hang?
And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
used it before but Paul could find some culprit on it. :)
Thanks.
----->8-----
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..9652d38 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
* guaranteed to be valid until irq is re-enabled, because it will be
* freed after synchronize_sched().
*/
- if (force_change)
+ if (force_change) {
+ if (num_online_cpus() > 1)
+ dump_stack();
synchronize_sched();
+ if (num_online_cpus() > 1)
+ dump_stack();
+ }
fail:
kfree(old_shared);
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-22 05:30 +0200 |
| Message-ID | <rMH1v-6pK-1@gated-at.bofh.it> |
| In reply to | #1428287 |
On Wed, Jun 22, 2016 at 09:52:08AM +0900, Joonsoo Kim wrote:
> On Tue, Jun 21, 2016 at 05:54:06AM -0700, Paul E. McKenney wrote:
> > On Tue, Jun 21, 2016 at 03:43:02PM +0900, Joonsoo Kim wrote:
> > > On Mon, Jun 20, 2016 at 06:12:54AM -0700, Paul E. McKenney wrote:
> > > > On Mon, Jun 20, 2016 at 03:39:43PM +0900, Joonsoo Kim wrote:
> > > > > CCing Paul to ask some question.
> > > > >
> > > > > On Wed, Jun 15, 2016 at 10:39:47AM +0200, Geert Uytterhoeven wrote:
> > > > > > Hi Joonsoo,
> > > > > >
> > > > > > On Wed, Jun 15, 2016 at 4:23 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > > > On Tue, Jun 14, 2016 at 12:45:14PM +0200, Geert Uytterhoeven wrote:
> > > > > > >> On Tue, Jun 14, 2016 at 10:11 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > > >> > On Tue, Jun 14, 2016 at 09:31:23AM +0200, Geert Uytterhoeven wrote:
> > > > > > >> >> On Tue, Jun 14, 2016 at 8:24 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > > >> >> > On Mon, Jun 13, 2016 at 09:43:13PM +0200, Geert Uytterhoeven wrote:
> > > > > > >> >> >> On Tue, Apr 12, 2016 at 6:51 AM, <js1304@gmail.com> wrote:
> > > > > > >> >> >> > From: Joonsoo Kim <iamjoonsoo.kim@lge.com>
> > > > > > >> >> >> > To check whther free objects exist or not precisely, we need to grab a
> > > > > > >> >> >> > lock. But, accuracy isn't that important because race window would be
> > > > > > >> >> >> > even small and if there is too much free object, cache reaper would reap
> > > > > > >> >> >> > it. So, this patch makes the check for free object exisistence not to
> > > > > > >> >> >> > hold a lock. This will reduce lock contention in heavily allocation case.
> > > > > >
> > > > > > >> >> >> I've bisected a boot failure (no output at all) in v4.7-rc2 on emev2/kzm9d
> > > > > > >> >> >> (Renesas dual Cortex A9) to this patch, which is upstream commit
> > > > > > >> >> >> 801faf0db8947e01877920e848a4d338dd7a99e7.
> > > > > >
> > > > > > > It's curious that synchronize_sched() has some effect in this early
> > > > > > > phase. In synchronize_sched(), rcu_blocking_is_gp() is called and
> > > > > > > it checks num_online_cpus <= 1. If so, synchronize_sched() does nothing.
> > > > > > >
> > > > > > > It would be related to might_sleep() in rcu_blocking_is_gp() but I'm not sure now.
> > > > > > >
> > > > > > > First, I'd like to confirm that num_online_cpus() is correct.
> > > > > > > Could you try following patch and give me a dmesg?
> > > > > > >
> > > > > > > Thanks.
> > > > > > >
> > > > > > > ------->8----------
> > > > > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > > > > index 763096a..5b7300a 100644
> > > > > > > --- a/mm/slab.c
> > > > > > > +++ b/mm/slab.c
> > > > > > > @@ -964,8 +964,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > > > > * freed after synchronize_sched().
> > > > > > > */
> > > > > > > - if (force_change)
> > > > > > > - synchronize_sched();
> > > > > > > + if (force_change) {
> > > > > > > + WARN_ON_ONCE(num_online_cpus() <= 1);
> > > > > > > + WARN_ON_ONCE(num_online_cpus() > 1);
> > > > > > > + }
> > > > > >
> > > > > > Full dmesg output below.
> > > > > >
> > > > > > I also tested whether it's the call to synchronize_sched() before or after
> > > > > > secondary CPU bringup that hangs.
> > > > > >
> > > > > > if (force_change && num_online_cpus() <= 1)
> > > > > > synchronize_sched();
> > > > > >
> > > > > > boots.
> > > > > >
> > > > > > if (force_change && num_online_cpus() > 1)
> > > > > > synchronize_sched();
> > > > > >
> > > > > > hangs.
> > > > >
> > > > > Hello, Paul.
> > > > >
> > > > > I changed slab.c to use synchronize_sched() for full memory barrier. First
> > > > > call happens on kmem_cache_init_late() and it would not be a problem
> > > > > because, at this time, num_online_cpus() <= 1 and synchronize_sched()
> > > > > would return immediately. Second call site would be shmem_init()
> > > > > and it seems that system hangs on it. Since smp is already initialized
> > > > > at that time, there would be some effect of synchronize_sched() but I
> > > > > can't imagine what's wrong here. Is it invalid moment to call
> > > > > synchronize_sched()?
> > > > >
> > > > > Note that my x86 virtual machine works fine even if
> > > > > synchronize_sched() is called in shmem_init() but Geert's some ARM
> > > > > machines (not all ARM machine) don't work well with it.
> > > >
> > > > Color me confused.
> > > >
> > > > Is Geert's ARM system somehow adding the second CPU before
> > > > rcu_spawn_gp_kthread() is called, that is, before or during
> > > > early_initcall() time?
> > >
> > > Hang would happen on shmem_init() which is called in do_basic_setup().
> > > do_basic_setup() is called after early_initcall().
> >
> > Thank you for the info!
> >
> > That should be lat enough that the RCU kthreads are alive and well.
> >
> > Can you get sysalt-t output?
> >
> > > Hmm... Is it okay to call synchronize_sched() by kernel thread?
> >
> > Yes, it can, in fact, rcutorture does this all the time. As do any
> > number of other kthreads.
>
> Paul, thanks for confirmation.
>
> Geert, we need to try more debugging.
>
> Could you try below patch to check who causes the hang?
Nice! That might be quite valuable!
> And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> used it before but Paul could find some culprit on it. :)
And the other thing to do is to read the last portion of
Documentation/RCU/stallwarn.txt, the part starting with
"What Causes RCU CPU Stall Warnings?". I would expect any
of these things to also result in an RCU CPU stall warning,
but perhaps something is preventing them from being printed.
Short summary: If a CPU gets stuck badly enough, RCU grace
periods won't end and therefore synchronize_sched() won't
ever return.
Thanx, Paul
> Thanks.
>
>
> ----->8-----
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..9652d38 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * guaranteed to be valid until irq is re-enabled, because it will be
> * freed after synchronize_sched().
> */
> - if (force_change)
> + if (force_change) {
> + if (num_online_cpus() > 1)
> + dump_stack();
> synchronize_sched();
> + if (num_online_cpus() > 1)
> + dump_stack();
> + }
>
> fail:
> kfree(old_shared);
>
[toc] | [prev] | [next] | [standalone]
| From | Geert Uytterhoeven <geert@linux-m68k.org> |
|---|---|
| Date | 2016-06-22 17:10 +0200 |
| Message-ID | <rMRWV-53e-9@gated-at.bofh.it> |
| In reply to | #1428287 |
On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> Could you try below patch to check who causes the hang?
>
> And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> used it before but Paul could find some culprit on it. :)
>
> Thanks.
>
>
> ----->8-----
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..9652d38 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * guaranteed to be valid until irq is re-enabled, because it will be
> * freed after synchronize_sched().
> */
> - if (force_change)
> + if (force_change) {
> + if (num_online_cpus() > 1)
> + dump_stack();
> synchronize_sched();
> + if (num_online_cpus() > 1)
> + dump_stack();
> + }
I've only added the first one, as I would never see the second one. All of
this happens before the serial console is activated, earlycon is not supported,
and I only have remote access.
Brought up 2 CPUs
SMP: Total of 2 processors activated (2132.00 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
CPU: 0 PID: 1 Comm: swapper/0 Not tainted
4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
[<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
[<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
[<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
[<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
(__do_tune_cpucache+0xf4/0x114)
[<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
[<c01cff54>] (enable_cpucache) from [<c01d0190>]
(__kmem_cache_create+0x1a8/0x1d0)
[<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
(kmem_cache_create+0xbc/0x190)
[<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
[<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
[<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
[<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
devtmpfs: initialized
Gr{oetje,eeting}s,
Geert
--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org
In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-22 21:10 +0200 |
| Message-ID | <rMVHc-7u5-5@gated-at.bofh.it> |
| In reply to | #1428880 |
On Wed, Jun 22, 2016 at 05:01:35PM +0200, Geert Uytterhoeven wrote:
> On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > Could you try below patch to check who causes the hang?
> >
> > And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> > used it before but Paul could find some culprit on it. :)
> >
> > Thanks.
> >
> >
> > ----->8-----
> > diff --git a/mm/slab.c b/mm/slab.c
> > index 763096a..9652d38 100644
> > --- a/mm/slab.c
> > +++ b/mm/slab.c
> > @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > * guaranteed to be valid until irq is re-enabled, because it will be
> > * freed after synchronize_sched().
> > */
> > - if (force_change)
> > + if (force_change) {
> > + if (num_online_cpus() > 1)
> > + dump_stack();
> > synchronize_sched();
> > + if (num_online_cpus() > 1)
> > + dump_stack();
> > + }
>
> I've only added the first one, as I would never see the second one. All of
> this happens before the serial console is activated, earlycon is not supported,
> and I only have remote access.
>
> Brought up 2 CPUs
> SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> CPU: All CPU(s) started in SVC mode.
> CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> 4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
> Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> [<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
> [<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
> [<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
> [<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
> (__do_tune_cpucache+0xf4/0x114)
> [<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
> [<c01cff54>] (enable_cpucache) from [<c01d0190>]
> (__kmem_cache_create+0x1a8/0x1d0)
> [<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
> (kmem_cache_create+0xbc/0x190)
> [<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
> [<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
> [<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
> [<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
> devtmpfs: initialized
I don't see anything here that would prevent grace periods from completing.
The CPUs are using the normal hotplug sequence to come online, correct?
Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-23 02:50 +0200 |
| Message-ID | <rN10d-2mo-5@gated-at.bofh.it> |
| In reply to | #1429058 |
On Wed, Jun 22, 2016 at 12:08:59PM -0700, Paul E. McKenney wrote:
> On Wed, Jun 22, 2016 at 05:01:35PM +0200, Geert Uytterhoeven wrote:
> > On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > Could you try below patch to check who causes the hang?
> > >
> > > And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> > > used it before but Paul could find some culprit on it. :)
> > >
> > > Thanks.
> > >
> > >
> > > ----->8-----
> > > diff --git a/mm/slab.c b/mm/slab.c
> > > index 763096a..9652d38 100644
> > > --- a/mm/slab.c
> > > +++ b/mm/slab.c
> > > @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > * freed after synchronize_sched().
> > > */
> > > - if (force_change)
> > > + if (force_change) {
> > > + if (num_online_cpus() > 1)
> > > + dump_stack();
> > > synchronize_sched();
> > > + if (num_online_cpus() > 1)
> > > + dump_stack();
> > > + }
> >
> > I've only added the first one, as I would never see the second one. All of
> > this happens before the serial console is activated, earlycon is not supported,
> > and I only have remote access.
> >
> > Brought up 2 CPUs
> > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > CPU: All CPU(s) started in SVC mode.
> > CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > 4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
> > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > [<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
> > [<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
> > [<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
> > [<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
> > (__do_tune_cpucache+0xf4/0x114)
> > [<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
> > [<c01cff54>] (enable_cpucache) from [<c01d0190>]
> > (__kmem_cache_create+0x1a8/0x1d0)
> > [<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
> > (kmem_cache_create+0xbc/0x190)
> > [<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
> > [<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
> > [<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
> > [<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
> > devtmpfs: initialized
>
> I don't see anything here that would prevent grace periods from completing.
>
> The CPUs are using the normal hotplug sequence to come online, correct?
And either way, could you please apply the patch below and then
invoke rcu_dump_rcu_sched_tree() just before the offending call to
synchronize_sched()? That will tell me what CPUs RCU believes exist,
and perhaps also which CPU is holding it up.
Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | Joonsoo Kim <iamjoonsoo.kim@lge.com> |
|---|---|
| Date | 2016-06-23 04:40 +0200 |
| Message-ID | <rN2IF-3BK-3@gated-at.bofh.it> |
| In reply to | #1429372 |
On Wed, Jun 22, 2016 at 05:49:35PM -0700, Paul E. McKenney wrote:
> On Wed, Jun 22, 2016 at 12:08:59PM -0700, Paul E. McKenney wrote:
> > On Wed, Jun 22, 2016 at 05:01:35PM +0200, Geert Uytterhoeven wrote:
> > > On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > Could you try below patch to check who causes the hang?
> > > >
> > > > And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> > > > used it before but Paul could find some culprit on it. :)
> > > >
> > > > Thanks.
> > > >
> > > >
> > > > ----->8-----
> > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > index 763096a..9652d38 100644
> > > > --- a/mm/slab.c
> > > > +++ b/mm/slab.c
> > > > @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > * freed after synchronize_sched().
> > > > */
> > > > - if (force_change)
> > > > + if (force_change) {
> > > > + if (num_online_cpus() > 1)
> > > > + dump_stack();
> > > > synchronize_sched();
> > > > + if (num_online_cpus() > 1)
> > > > + dump_stack();
> > > > + }
> > >
> > > I've only added the first one, as I would never see the second one. All of
> > > this happens before the serial console is activated, earlycon is not supported,
> > > and I only have remote access.
> > >
> > > Brought up 2 CPUs
> > > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > > CPU: All CPU(s) started in SVC mode.
> > > CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > > 4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
> > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > [<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
> > > [<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
> > > [<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
> > > [<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
> > > (__do_tune_cpucache+0xf4/0x114)
> > > [<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
> > > [<c01cff54>] (enable_cpucache) from [<c01d0190>]
> > > (__kmem_cache_create+0x1a8/0x1d0)
> > > [<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
> > > (kmem_cache_create+0xbc/0x190)
> > > [<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
> > > [<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
> > > [<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
> > > [<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
> > > devtmpfs: initialized
> >
> > I don't see anything here that would prevent grace periods from completing.
> >
> > The CPUs are using the normal hotplug sequence to come online, correct?
>
> And either way, could you please apply the patch below and then
> invoke rcu_dump_rcu_sched_tree() just before the offending call to
> synchronize_sched()? That will tell me what CPUs RCU believes exist,
> and perhaps also which CPU is holding it up.
I can't find rcu_dump_rcu_sched_tree(). Do you mean
rcu_dump_rcu_node_tree()? Anyway, there is no patch below so I attach
one which does what Paul want, maybe.
Thanks.
------->8---------
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index 88d3f95..6b650f0 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -4171,7 +4171,7 @@ static void __init rcu_init_geometry(void)
* Dump out the structure of the rcu_node combining tree associated
* with the rcu_state structure referenced by rsp.
*/
-static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
+static void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
{
int level = 0;
struct rcu_node *rnp;
@@ -4189,6 +4189,11 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
pr_cont("\n");
}
+void rcu_dump_rcu_sched_tree(void)
+{
+ rcu_dump_rcu_node_tree(&rcu_sched_state);
+}
+
void __init rcu_init(void)
{
int cpu;
diff --git a/mm/slab.c b/mm/slab.c
index 763096a..d88976c 100644
--- a/mm/slab.c
+++ b/mm/slab.c
@@ -909,6 +909,8 @@ static int init_cache_node_node(int node)
return 0;
}
+extern void rcu_dump_rcu_sched_tree(void);
+
static int setup_kmem_cache_node(struct kmem_cache *cachep,
int node, gfp_t gfp, bool force_change)
{
@@ -964,8 +966,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
* guaranteed to be valid until irq is re-enabled, because it will be
* freed after synchronize_sched().
*/
- if (force_change)
+ if (force_change) {
+ rcu_dump_rcu_sched_tree();
synchronize_sched();
+ }
fail:
kfree(old_shared);
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-23 04:50 +0200 |
| Message-ID | <rN2Sl-3Fp-5@gated-at.bofh.it> |
| In reply to | #1429411 |
On Thu, Jun 23, 2016 at 11:37:56AM +0900, Joonsoo Kim wrote:
> On Wed, Jun 22, 2016 at 05:49:35PM -0700, Paul E. McKenney wrote:
> > On Wed, Jun 22, 2016 at 12:08:59PM -0700, Paul E. McKenney wrote:
> > > On Wed, Jun 22, 2016 at 05:01:35PM +0200, Geert Uytterhoeven wrote:
> > > > On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > Could you try below patch to check who causes the hang?
> > > > >
> > > > > And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> > > > > used it before but Paul could find some culprit on it. :)
> > > > >
> > > > > Thanks.
> > > > >
> > > > >
> > > > > ----->8-----
> > > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > > index 763096a..9652d38 100644
> > > > > --- a/mm/slab.c
> > > > > +++ b/mm/slab.c
> > > > > @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > > * freed after synchronize_sched().
> > > > > */
> > > > > - if (force_change)
> > > > > + if (force_change) {
> > > > > + if (num_online_cpus() > 1)
> > > > > + dump_stack();
> > > > > synchronize_sched();
> > > > > + if (num_online_cpus() > 1)
> > > > > + dump_stack();
> > > > > + }
> > > >
> > > > I've only added the first one, as I would never see the second one. All of
> > > > this happens before the serial console is activated, earlycon is not supported,
> > > > and I only have remote access.
> > > >
> > > > Brought up 2 CPUs
> > > > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > > > CPU: All CPU(s) started in SVC mode.
> > > > CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > > > 4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
> > > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > > [<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
> > > > [<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
> > > > [<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
> > > > [<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
> > > > (__do_tune_cpucache+0xf4/0x114)
> > > > [<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
> > > > [<c01cff54>] (enable_cpucache) from [<c01d0190>]
> > > > (__kmem_cache_create+0x1a8/0x1d0)
> > > > [<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
> > > > (kmem_cache_create+0xbc/0x190)
> > > > [<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
> > > > [<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
> > > > [<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
> > > > [<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
> > > > devtmpfs: initialized
> > >
> > > I don't see anything here that would prevent grace periods from completing.
> > >
> > > The CPUs are using the normal hotplug sequence to come online, correct?
> >
> > And either way, could you please apply the patch below and then
> > invoke rcu_dump_rcu_sched_tree() just before the offending call to
> > synchronize_sched()? That will tell me what CPUs RCU believes exist,
> > and perhaps also which CPU is holding it up.
>
> I can't find rcu_dump_rcu_sched_tree(). Do you mean
> rcu_dump_rcu_node_tree()? Anyway, there is no patch below so I attach
> one which does what Paul want, maybe.
One of those days, I guess! :-/
Your patch is exactly what I intended to send, thank you!
Thanx, Paul
> Thanks.
>
> ------->8---------
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index 88d3f95..6b650f0 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -4171,7 +4171,7 @@ static void __init rcu_init_geometry(void)
> * Dump out the structure of the rcu_node combining tree associated
> * with the rcu_state structure referenced by rsp.
> */
> -static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> +static void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> {
> int level = 0;
> struct rcu_node *rnp;
> @@ -4189,6 +4189,11 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> pr_cont("\n");
> }
>
> +void rcu_dump_rcu_sched_tree(void)
> +{
> + rcu_dump_rcu_node_tree(&rcu_sched_state);
> +}
> +
> void __init rcu_init(void)
> {
> int cpu;
> diff --git a/mm/slab.c b/mm/slab.c
> index 763096a..d88976c 100644
> --- a/mm/slab.c
> +++ b/mm/slab.c
> @@ -909,6 +909,8 @@ static int init_cache_node_node(int node)
> return 0;
> }
>
> +extern void rcu_dump_rcu_sched_tree(void);
> +
> static int setup_kmem_cache_node(struct kmem_cache *cachep,
> int node, gfp_t gfp, bool force_change)
> {
> @@ -964,8 +966,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> * guaranteed to be valid until irq is re-enabled, because it will be
> * freed after synchronize_sched().
> */
> - if (force_change)
> + if (force_change) {
> + rcu_dump_rcu_sched_tree();
> synchronize_sched();
> + }
>
> fail:
> kfree(old_shared);
>
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-06-23 05:00 +0200 |
| Message-ID | <rN321-3Jc-1@gated-at.bofh.it> |
| In reply to | #1429417 |
On Wed, Jun 22, 2016 at 07:47:42PM -0700, Paul E. McKenney wrote:
> On Thu, Jun 23, 2016 at 11:37:56AM +0900, Joonsoo Kim wrote:
> > On Wed, Jun 22, 2016 at 05:49:35PM -0700, Paul E. McKenney wrote:
> > > On Wed, Jun 22, 2016 at 12:08:59PM -0700, Paul E. McKenney wrote:
> > > > On Wed, Jun 22, 2016 at 05:01:35PM +0200, Geert Uytterhoeven wrote:
> > > > > On Wed, Jun 22, 2016 at 2:52 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote:
> > > > > > Could you try below patch to check who causes the hang?
> > > > > >
> > > > > > And, if sysalt-t works when hang, could you get sysalt-t output? I haven't
> > > > > > used it before but Paul could find some culprit on it. :)
> > > > > >
> > > > > > Thanks.
> > > > > >
> > > > > >
> > > > > > ----->8-----
> > > > > > diff --git a/mm/slab.c b/mm/slab.c
> > > > > > index 763096a..9652d38 100644
> > > > > > --- a/mm/slab.c
> > > > > > +++ b/mm/slab.c
> > > > > > @@ -964,8 +964,13 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > > > > > * guaranteed to be valid until irq is re-enabled, because it will be
> > > > > > * freed after synchronize_sched().
> > > > > > */
> > > > > > - if (force_change)
> > > > > > + if (force_change) {
> > > > > > + if (num_online_cpus() > 1)
> > > > > > + dump_stack();
> > > > > > synchronize_sched();
> > > > > > + if (num_online_cpus() > 1)
> > > > > > + dump_stack();
> > > > > > + }
> > > > >
> > > > > I've only added the first one, as I would never see the second one. All of
> > > > > this happens before the serial console is activated, earlycon is not supported,
> > > > > and I only have remote access.
> > > > >
> > > > > Brought up 2 CPUs
> > > > > SMP: Total of 2 processors activated (2132.00 BogoMIPS).
> > > > > CPU: All CPU(s) started in SVC mode.
> > > > > CPU: 0 PID: 1 Comm: swapper/0 Not tainted
> > > > > 4.7.0-rc4-kzm9d-00404-g4a235e6dde4404dd-dirty #89
> > > > > Hardware name: Generic Emma Mobile EV2 (Flattened Device Tree)
> > > > > [<c010de68>] (unwind_backtrace) from [<c010a658>] (show_stack+0x10/0x14)
> > > > > [<c010a658>] (show_stack) from [<c02b5cf8>] (dump_stack+0x7c/0x9c)
> > > > > [<c02b5cf8>] (dump_stack) from [<c01cfa4c>] (setup_kmem_cache_node+0x140/0x170)
> > > > > [<c01cfa4c>] (setup_kmem_cache_node) from [<c01cfe3c>]
> > > > > (__do_tune_cpucache+0xf4/0x114)
> > > > > [<c01cfe3c>] (__do_tune_cpucache) from [<c01cff54>] (enable_cpucache+0xf8/0x148)
> > > > > [<c01cff54>] (enable_cpucache) from [<c01d0190>]
> > > > > (__kmem_cache_create+0x1a8/0x1d0)
> > > > > [<c01d0190>] (__kmem_cache_create) from [<c01b32d0>]
> > > > > (kmem_cache_create+0xbc/0x190)
> > > > > [<c01b32d0>] (kmem_cache_create) from [<c070d968>] (shmem_init+0x34/0xb0)
> > > > > [<c070d968>] (shmem_init) from [<c0700cc8>] (kernel_init_freeable+0x98/0x1ec)
> > > > > [<c0700cc8>] (kernel_init_freeable) from [<c049fdbc>] (kernel_init+0x8/0x110)
> > > > > [<c049fdbc>] (kernel_init) from [<c0106cb8>] (ret_from_fork+0x14/0x3c)
> > > > > devtmpfs: initialized
> > > >
> > > > I don't see anything here that would prevent grace periods from completing.
> > > >
> > > > The CPUs are using the normal hotplug sequence to come online, correct?
> > >
> > > And either way, could you please apply the patch below and then
> > > invoke rcu_dump_rcu_sched_tree() just before the offending call to
> > > synchronize_sched()? That will tell me what CPUs RCU believes exist,
> > > and perhaps also which CPU is holding it up.
> >
> > I can't find rcu_dump_rcu_sched_tree(). Do you mean
> > rcu_dump_rcu_node_tree()? Anyway, there is no patch below so I attach
> > one which does what Paul want, maybe.
>
> One of those days, I guess! :-/
>
> Your patch is exactly what I intended to send, thank you!
Ah, but your telepathy was not sufficient to intuit the additional
information I need. Please see the patch at the end. Your hunk
in mm/slab.c is needed on top of my patch.
So I am clearly having difficulties reading as well as including patches
today...
Thanx, Paul
> > Thanks.
> >
> > ------->8---------
> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > index 88d3f95..6b650f0 100644
> > --- a/kernel/rcu/tree.c
> > +++ b/kernel/rcu/tree.c
> > @@ -4171,7 +4171,7 @@ static void __init rcu_init_geometry(void)
> > * Dump out the structure of the rcu_node combining tree associated
> > * with the rcu_state structure referenced by rsp.
> > */
> > -static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> > +static void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> > {
> > int level = 0;
> > struct rcu_node *rnp;
> > @@ -4189,6 +4189,11 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
> > pr_cont("\n");
> > }
> >
> > +void rcu_dump_rcu_sched_tree(void)
> > +{
> > + rcu_dump_rcu_node_tree(&rcu_sched_state);
> > +}
> > +
> > void __init rcu_init(void)
> > {
> > int cpu;
> > diff --git a/mm/slab.c b/mm/slab.c
> > index 763096a..d88976c 100644
> > --- a/mm/slab.c
> > +++ b/mm/slab.c
> > @@ -909,6 +909,8 @@ static int init_cache_node_node(int node)
> > return 0;
> > }
> >
> > +extern void rcu_dump_rcu_sched_tree(void);
> > +
> > static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > int node, gfp_t gfp, bool force_change)
> > {
> > @@ -964,8 +966,10 @@ static int setup_kmem_cache_node(struct kmem_cache *cachep,
> > * guaranteed to be valid until irq is re-enabled, because it will be
> > * freed after synchronize_sched().
> > */
> > - if (force_change)
> > + if (force_change) {
> > + rcu_dump_rcu_sched_tree();
> > synchronize_sched();
> > + }
> >
> > fail:
> > kfree(old_shared);
> >
------------------------------------------------------------------------
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index c7f1bc4f817c..2eda7bece401 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -4707,7 +4707,7 @@ static void __init rcu_init_geometry(void)
* Dump out the structure of the rcu_node combining tree associated
* with the rcu_state structure referenced by rsp.
*/
-static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
+static void rcu_dump_rcu_node_tree(struct rcu_state *rsp)
{
int level = 0;
struct rcu_node *rnp;
@@ -4720,11 +4720,18 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp)
pr_info(" ");
level = rnp->level;
}
- pr_cont("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum);
+ pr_cont("%d:%d/%#lx/%#lx ^%d ", rnp->grplo, rnp->grphi,
+ rnp->qsmask,
+ rnp->qsmaskinit | rnp->qsmaskinitnext, rnp->grpnum);
}
pr_cont("\n");
}
+void rcu_dump_rcu_sched_tree(void)
+{
+ rcu_dump_rcu_node_tree(&rcu_sched_state);
+}
+
void __init rcu_init(void)
{
int cpu;
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web