Hi Alexander,
FYI this happens in mainline kernel 4.17.0-rc1.
It dates back to at least v4.15.
It occurs in 4 out of 4 boots. Here KVM has 1G memory.
This high order allocation caused lots of noises in our boot testing.
We could disable this device in our tests, but it would be great if
there are better ways out.
[ 75.039408] Product name: fake-design-for-testing
[ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
[ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
[ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
[ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
[ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
[ 75.063053] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.17.0-rc1 #262
[ 75.063338] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 75.063338] Call Trace:
[ 75.063338] dump_stack+0x71/0xab:
dump_stack at lib/dump_stack.c:115
[ 75.063338] warn_alloc+0x180/0x280:
warn_alloc_show_mem at mm/page_alloc.c:3398
(inlined by) warn_alloc at mm/page_alloc.c:3437
[ 75.063338] ? zone_watermark_ok_safe+0x260/0x260:
warn_alloc at mm/page_alloc.c:3417
[ 75.063338] ? __zone_watermark_ok+0x260/0x260:
get_page_from_freelist at mm/page_alloc.c:3262
[ 75.063338] ? _cond_resched+0x14/0x30:
_cond_resched at kernel/sched/core.c:4982
[ 75.063338] __alloc_pages_nodemask+0x1068/0x19a0:
__alloc_pages_slowpath at mm/page_alloc.c:4293
(inlined by) __alloc_pages_nodemask at mm/page_alloc.c:4384
[ 75.063338] ? gfp_pfmemalloc_allowed+0x150/0x150:
__alloc_pages_nodemask at mm/page_alloc.c:4350
[ 75.063338] ? sched_clock_cpu+0x14f/0x180:
sched_clock_cpu at kernel/sched/clock.c:362
[ 75.063338] cache_alloc_refill+0x27e/0x770:
kmem_getpages at mm/slab.c:1412
(inlined by) cache_grow_begin at mm/slab.c:2678
(inlined by) cache_alloc_refill at mm/slab.c:3045
[ 75.063338] ? lock_acquire+0xd0/0x190:
get_current at arch/x86/include/asm/current.h:15
(inlined by) lock_acquire at kernel/locking/lockdep.c:3922
[ 75.063338] __kmalloc+0x14b/0x180:
____cache_alloc at mm/slab.c:3127
(inlined by) __do_cache_alloc at mm/slab.c:3366
(inlined by) slab_alloc at mm/slab.c:3384
(inlined by) __do_kmalloc at mm/slab.c:3716
(inlined by) __kmalloc at mm/slab.c:3727
[ 75.063338] stm_register_device+0xf3/0x5c0:
stm_register_device at drivers/hwtracing/stm/core.c:695
[ 75.063338] ? stp_policy_node_put+0x10/0x10:
dummy_stm_packet at drivers/hwtracing/stm/dummy_stm.c:33
[ 75.063338] dummy_stm_init+0x175/0x2b0:
dummy_stm_init at drivers/hwtracing/stm/dummy_stm.c:93
[ 75.063338] ? intel_th_pti_lpp_init+0x37/0x37:
stm_core_init at drivers/hwtracing/stm/core.c:1149
[ 75.063338] ? dummy_stm_exit+0x80/0x80:
dummy_stm_init at drivers/hwtracing/stm/dummy_stm.c:70
[ 75.063338] do_one_initcall+0xd8/0x1e0:
do_trace_initcall_finish at init/main.c:867
(inlined by) do_one_initcall at init/main.c:884
[ 75.063338] ? start_kernel+0x9c2/0x9c2:
do_one_initcall at init/main.c:874
[ 75.063338] ? __wake_up_common+0x580/0x580:
__wake_up_common_lock at kernel/sched/wait.c:109
[ 75.063338] ? lock_downgrade+0x5e0/0x5e0:
lock_release at kernel/locking/lockdep.c:3929
[ 75.063338] kernel_init_freeable+0x2b6/0x348:
do_initcall_level at init/main.c:951
(inlined by) do_initcalls at init/main.c:959
(inlined by) do_basic_setup at init/main.c:977
(inlined by) kernel_init_freeable at init/main.c:1127
[ 75.063338] ? rest_init+0x170/0x170:
kernel_init at init/main.c:1050
[ 75.063338] kernel_init+0xa/0x110:
kernel_init at init/main.c:1055
[ 75.063338] ? rest_init+0x170/0x170:
kernel_init at init/main.c:1050
[ 75.063338] ret_from_fork+0x1f/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:418
[ 75.089849] Mem-Info:
[ 75.090370] active_anon:0 inactive_anon:0 isolated_anon:0
[ 75.090370] active_file:0 inactive_file:0 isolated_file:0
[ 75.090370] unevictable:123532 dirty:0 writeback:0 unstable:0
[ 75.090370] slab_reclaimable:6653 slab_unreclaimable:10019
[ 75.090370] mapped:0 shmem:0 pagetables:0 bounce:0
[ 75.090370] free:10580 free_pcp:0 free_cma:0
[ 75.094750] Node 0 active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:494128kB isolated(anon):0kB isolated(file):0kB mapped:0kB dirty:0kB writeback:0kB shmem:0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[ 75.097690] DMA free:12232kB min:80kB low:100kB high:120kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:1180kB writepending:0kB present:15992kB managed:15904kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 75.101009] lowmem_reserve[]: 0 588 588 588
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> Hi Alexander,
>
> FYI this happens in mainline kernel 4.17.0-rc1.
> It dates back to at least v4.15.
>
> It occurs in 4 out of 4 boots. Here KVM has 1G memory.
>
> This high order allocation caused lots of noises in our boot testing.
> We could disable this device in our tests, but it would be great if
> there are better ways out.
>
> [ 75.039408] Product name: fake-design-for-testing
> [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
Is there any reason why
> [ 75.063338] stm_register_device+0xf3/0x5c0:
> stm_register_device at drivers/hwtracing/stm/core.c:695
cannot use kvzalloc?
--
Michal Hocko
SUSE Labs
On Thu, Apr 19, 2018 at 08:51:11AM +0200, Michal Hocko wrote:
> On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> > Hi Alexander,
> >
> > FYI this happens in mainline kernel 4.17.0-rc1.
> > It dates back to at least v4.15.
> >
> > It occurs in 4 out of 4 boots. Here KVM has 1G memory.
> >
> > This high order allocation caused lots of noises in our boot testing.
> > We could disable this device in our tests, but it would be great if
> > there are better ways out.
> >
> > [ 75.039408] Product name: fake-design-for-testing
> > [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> > [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> > [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
>
> Is there any reason why
> > [ 75.063338] stm_register_device+0xf3/0x5c0:
> > stm_register_device at drivers/hwtracing/stm/core.c:695
>
> cannot use kvzalloc?
You're right, of course, I'll fix that.
I can't see, though, how it ends up asking order==9 from the buddy
allocator. The kmalloc() in question should be asking for ~512kB,
theres should be smaller slabs for that.
Regards,
--
Alex
On Thu, Apr 19, 2018 at 08:51:11AM +0200, Michal Hocko wrote:
> On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> > Hi Alexander,
> >
> > FYI this happens in mainline kernel 4.17.0-rc1.
> > It dates back to at least v4.15.
> >
> > It occurs in 4 out of 4 boots. Here KVM has 1G memory.
> >
> > This high order allocation caused lots of noises in our boot testing.
> > We could disable this device in our tests, but it would be great if
> > there are better ways out.
> >
> > [ 75.039408] Product name: fake-design-for-testing
> > [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> > [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> > [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
>
> Is there any reason why
> > [ 75.063338] stm_register_device+0xf3/0x5c0:
> > stm_register_device at drivers/hwtracing/stm/core.c:695
>
> cannot use kvzalloc?
Michal, do you understand how allocating ~512kB leads to order-9 failure?
Shouldn't it be order-8 at most? That's not clear to me.
--
Kirill A. Shutemov
On Thu 19-04-18 13:21:14, Kirill A. Shutemov wrote:
> On Thu, Apr 19, 2018 at 08:51:11AM +0200, Michal Hocko wrote:
> > On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> > > Hi Alexander,
> > >
> > > FYI this happens in mainline kernel 4.17.0-rc1.
> > > It dates back to at least v4.15.
> > >
> > > It occurs in 4 out of 4 boots. Here KVM has 1G memory.
> > >
> > > This high order allocation caused lots of noises in our boot testing.
> > > We could disable this device in our tests, but it would be great if
> > > there are better ways out.
> > >
> > > [ 75.039408] Product name: fake-design-for-testing
> > > [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> > > [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> > > [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
> >
> > Is there any reason why
> > > [ 75.063338] stm_register_device+0xf3/0x5c0:
> > > stm_register_device at drivers/hwtracing/stm/core.c:695
> >
> > cannot use kvzalloc?
>
> Michal, do you understand how allocating ~512kB leads to order-9 failure?
> Shouldn't it be order-8 at most? That's not clear to me.
How do you tell it is 512kB? The page allocator consumes order so maybe
something miscalculated the order when calling the allocator?
--
Michal Hocko
SUSE Labs
On Sun, Apr 22, 2018 at 07:44:39AM -0600, Michal Hocko wrote:
> On Thu 19-04-18 13:21:14, Kirill A. Shutemov wrote:
> > On Thu, Apr 19, 2018 at 08:51:11AM +0200, Michal Hocko wrote:
> > > On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> > > > Hi Alexander,
> > > >
> > > > FYI this happens in mainline kernel 4.17.0-rc1.
> > > > It dates back to at least v4.15.
> > > >
> > > > It occurs in 4 out of 4 boots. Here KVM has 1G memory.
> > > >
> > > > This high order allocation caused lots of noises in our boot testing.
> > > > We could disable this device in our tests, but it would be great if
> > > > there are better ways out.
> > > >
> > > > [ 75.039408] Product name: fake-design-for-testing
> > > > [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > > [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> > > > [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > > [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> > > > [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
> > >
> > > Is there any reason why
> > > > [ 75.063338] stm_register_device+0xf3/0x5c0:
> > > > stm_register_device at drivers/hwtracing/stm/core.c:695
> > >
> > > cannot use kvzalloc?
> >
> > Michal, do you understand how allocating ~512kB leads to order-9 failure?
> > Shouldn't it be order-8 at most? That's not clear to me.
>
> How do you tell it is 512kB? The page allocator consumes order so maybe
> something miscalculated the order when calling the allocator?
Alexander, was it 513kB, right?
I just want to make sure that we don't have any bugs in calculation on
allocator side.
--
Kirill A. Shutemov
On Tue, Apr 24, 2018 at 02:27:35PM +0300, Kirill A. Shutemov wrote:
> On Sun, Apr 22, 2018 at 07:44:39AM -0600, Michal Hocko wrote:
> > On Thu 19-04-18 13:21:14, Kirill A. Shutemov wrote:
> > > On Thu, Apr 19, 2018 at 08:51:11AM +0200, Michal Hocko wrote:
> > > > On Thu 19-04-18 10:36:39, Wu Fengguang wrote:
> > > > > Hi Alexander,
> > > > >
> > > > > FYI this happens in mainline kernel 4.17.0-rc1.
> > > > > It dates back to at least v4.15.
> > > > >
> > > > > It occurs in 4 out of 4 boots. Here KVM has 1G memory.
> > > > >
> > > > > This high order allocation caused lots of noises in our boot testing.
> > > > > We could disable this device in our tests, but it would be great if
> > > > > there are better ways out.
> > > > >
> > > > > [ 75.039408] Product name: fake-design-for-testing
> > > > > [ 75.040995] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > > > [ 75.042509] fmc_trivial: probe of fake-design-for-testing-f001 failed with error -95
> > > > > [ 75.044323] fmc fake-design-for-testing-f001: Driver has no ID: matches all
> > > > > [ 75.045644] fmc_chardev fake-design-for-testing-f001: Created misc device "fake-design-for-testing-f001"
> > > > > [ 75.061570] swapper/0: page allocation failure: order:9, mode:0x14040c0(GFP_KERNEL|__GFP_COMP), nodemask=(null)
> > > >
> > > > Is there any reason why
> > > > > [ 75.063338] stm_register_device+0xf3/0x5c0:
> > > > > stm_register_device at drivers/hwtracing/stm/core.c:695
> > > >
> > > > cannot use kvzalloc?
> > >
> > > Michal, do you understand how allocating ~512kB leads to order-9 failure?
> > > Shouldn't it be order-8 at most? That's not clear to me.
> >
> > How do you tell it is 512kB? The page allocator consumes order so maybe
> > something miscalculated the order when calling the allocator?
>
> Alexander, was it 513kB, right?
Yes, 526024 bytes.
Regards,
--
Alex