2022-01-24 23:50:29

by Vijay Balakrishna

[permalink] [raw]
Subject: [arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update

We noticed 150ms kernel boot slowdown back in June, 2021, when moving
from v5.10.19 to v5.10.42. This on a 8GB SoC. Only recently we
investigated this issue and found the regression is introduced by a
change in map_mem() (paging_init() -> map_mem() -> __map_memblock(), in
particular "map all the memory banks" for loop) by patch

2687275a5843d1089687f08fc64eb3f3b026a169
arm64: Force NO_BLOCK_MAPPINGS if crashkernel reservation is required

above is a follow up to

0a30c53573b07d5561457e41fb0ab046cd857da5
arm64: mm: Move reserve_crashkernel() into mem_init())

which deferred crashkernel reservation into mem_init().

The ~150ms slowdown disappears on booting without "crashkernel=.." on
kernel command-line.

Please let us know if it known/understood or addressed already or being
looked into. Any insight is appreciated.

Thanks,
Vijay

console output collected with debug prints --

[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[ 0.000000] Linux version
5.10.42.6-xxx-standard-2008.3.0-local-snapshot-01210432
(oe-user@oe-host) (clang version 10.[ 0.000001] sched_clock: 64 bits
at 125MHz, resolution 8ns, wraps every 4398046511100ns
[ 0.000003] 2.560781952 MSFT: kernel boot start
[ 0.000484] Machine model: xxx
[ 0.009379] earlycon: uart8250 at MMIO32 0x0000000068a10000 (options '')
[ 0.009383] printk: bootconsole [uart8250] enabled
[ 0.009828] before paging_init()
[ 0.009977] before map_mem()
[ 0.009978] after memblock_mark_nomap()
[ 0.152388] after __map_memblock() for loop
[ 0.152391] after __map_memblock() kernel_start, kernel_end
[ 0.152393] after memblock_clear_nomap
[ 0.152394] after map_mem()
[ 0.152401] after paging_init()
[ 0.153273] NUMA: No NUMA configuration found
[ 0.153278] NUMA: Faking a node at [mem
0x0000000080000000-0x000000097fffffff]
[ 0.153282] NUMA: NODE_DATA [mem 0x97efec5c0-0x97efedfff]
[ 0.153316] Zone ranges:
[ 0.153319] Normal [mem 0x0000000080000000-0x000000097fffffff]
[ 0.153323] Device empty
[ 0.153325] Movable zone start for each node
[ 0.153326] Early memory node ranges
[ 0.153328] node 0: [mem 0x0000000080000000-0x000000008adfffff]
[ 0.153330] node 0: [mem 0x000000008ae00000-0x000000008f223fff]
[ 0.153331] node 0: [mem 0x000000008f224000-0x00000000ffffffff]
[ 0.153333] node 0: [mem 0x0000000880000000-0x00000008800fffff]
[ 0.153334] node 0: [mem 0x0000000880100000-0x000000097fffffff]
[ 0.153337] Initmem setup node 0 [mem
0x0000000080000000-0x000000097fffffff]
[ 0.153340] On node 0 totalpages: 1572864
[ 0.153342] Normal zone: 24576 pages used for memmap
[ 0.153343] Normal zone: 0 pages reserved
[ 0.153345] Normal zone: 1572864 pages, LIFO batch:63
[ 0.154507] crashkernel reserved: 0x0000000968e00000 -
0x0000000978e00000 (256 MB)

Console output from PXE boot without "crashkernel=256M" boot parameter --
[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[ 0.000000] Linux version
5.10.42.6-xxx-standard-2008.3.0-local-snapshot-01210432
(oe-user@oe-host) (clang version 10.[ 0.000001] sched_clock: 64 bits
at 125MHz, resolution 8ns, wraps every 4398046511100ns
[ 0.000003] 14.765446920 MSFT: kernel boot start
[ 0.000484] Machine model: xxx
[ 0.009400] earlycon: uart8250 at MMIO32 0x0000000068a10000 (options '')
[ 0.009404] printk: bootconsole [uart8250] enabled
[ 0.009835] before paging_init()
[ 0.009986] before map_mem()
[ 0.009987] after memblock_mark_nomap()
[ 0.010154] after __map_memblock() for loop
[ 0.010156] after __map_memblock() kernel_start, kernel_end
[ 0.010158] after memblock_clear_nomap
[ 0.010159] after map_mem()
[ 0.010163] after paging_init()
[ 0.011002] NUMA: No NUMA configuration found
[ 0.011005] NUMA: Faking a node at [mem
0x0000000080000000-0x000000097fffffff]
[ 0.011009] NUMA: NODE_DATA [mem 0x97fbc65c0-0x97fbc7fff]
[ 0.011037] Zone ranges:
[ 0.011038] Normal [mem 0x0000000080000000-0x000000097fffffff]
[ 0.011041] Device empty
[ 0.011043] Movable zone start for each node
[ 0.011044] Early memory node ranges
[ 0.011046] node 0: [mem 0x0000000080000000-0x000000008adfffff]
[ 0.011048] node 0: [mem 0x000000008ae00000-0x000000008f223fff]
[ 0.011049] node 0: [mem 0x000000008f224000-0x00000000ffffffff]
[ 0.011050] node 0: [mem 0x0000000880000000-0x00000008800fffff]
[ 0.011052] node 0: [mem 0x0000000880100000-0x000000097fffffff]
[ 0.011054] Initmem setup node 0 [mem
0x0000000080000000-0x000000097fffffff]
[ 0.011056] On node 0 totalpages: 1572864
[ 0.011058] Normal zone: 24576 pages used for memmap
[ 0.011060] Normal zone: 0 pages reserved
[ 0.011061] Normal zone: 1572864 pages, LIFO batch:63


2022-01-31 10:01:20

by Catalin Marinas

[permalink] [raw]
Subject: Re: [arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update

On Mon, Jan 24, 2022 at 03:03:48PM -0800, Vijay Balakrishna wrote:
> We noticed 150ms kernel boot slowdown back in June, 2021, when moving from
> v5.10.19 to v5.10.42. This on a 8GB SoC. Only recently we investigated
> this issue and found the regression is introduced by a change in map_mem()
> (paging_init() -> map_mem() -> __map_memblock(), in particular "map all the
> memory banks" for loop) by patch
>
> 2687275a5843d1089687f08fc64eb3f3b026a169
> arm64: Force NO_BLOCK_MAPPINGS if crashkernel reservation is required
>
> above is a follow up to
>
> 0a30c53573b07d5561457e41fb0ab046cd857da5
> arm64: mm: Move reserve_crashkernel() into mem_init())
>
> which deferred crashkernel reservation into mem_init().
>
> The ~150ms slowdown disappears on booting without "crashkernel=.." on kernel
> command-line.

Is CONFIG_RODATA_FULL_DEFAULT_ENABLED set in your config file? It may
cause the same slowdown. I suspect it's because we end up mapping the
RAM at the page granularity so more loops and slightly higher TLB
pressure. Not sure we can do much about.

--
Catalin

2022-01-31 11:31:04

by Vijay Balakrishna

[permalink] [raw]
Subject: Re: [arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update



On 1/28/2022 4:06 AM, Catalin Marinas wrote:
> On Mon, Jan 24, 2022 at 03:03:48PM -0800, Vijay Balakrishna wrote:
>> We noticed 150ms kernel boot slowdown back in June, 2021, when moving from
>> v5.10.19 to v5.10.42. This on a 8GB SoC. Only recently we investigated
>> this issue and found the regression is introduced by a change in map_mem()
>> (paging_init() -> map_mem() -> __map_memblock(), in particular "map all the
>> memory banks" for loop) by patch
>>
>> 2687275a5843d1089687f08fc64eb3f3b026a169
>> arm64: Force NO_BLOCK_MAPPINGS if crashkernel reservation is required
>>
>> above is a follow up to
>>
>> 0a30c53573b07d5561457e41fb0ab046cd857da5
>> arm64: mm: Move reserve_crashkernel() into mem_init())
>>
>> which deferred crashkernel reservation into mem_init().
>>
>> The ~150ms slowdown disappears on booting without "crashkernel=.." on kernel
>> command-line.
>
> Is CONFIG_RODATA_FULL_DEFAULT_ENABLED set in your config file? It may
> cause the same slowdown. I suspect it's because we end up mapping the
> RAM at the page granularity so more loops and slightly higher TLB
> pressure. Not sure we can do much about >

Catalin,

Thanks for your reply.

CONFIG_RODATA_FULL_DEFAULT_ENABLED is not set in our config for boot
time performance reasons.

2022-02-09 23:51:44

by Vijay Balakrishna

[permalink] [raw]
Subject: Re: [arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update



On 1/28/2022 10:03 AM, Vijay Balakrishna wrote:
>
>
> On 1/28/2022 4:06 AM, Catalin Marinas wrote:
>> On Mon, Jan 24, 2022 at 03:03:48PM -0800, Vijay Balakrishna wrote:
>>> We noticed 150ms kernel boot slowdown back in June, 2021, when moving
>>> from
>>> v5.10.19 to v5.10.42.  This on a 8GB SoC.  Only recently we investigated
>>> this issue and found the regression is introduced by a change in
>>> map_mem()
>>> (paging_init() -> map_mem() -> __map_memblock(), in particular "map
>>> all the
>>> memory banks" for loop) by patch
>>>
>>> 2687275a5843d1089687f08fc64eb3f3b026a169
>>> arm64: Force NO_BLOCK_MAPPINGS if crashkernel reservation is required
>>>
>>> above is a follow up to
>>>
>>> 0a30c53573b07d5561457e41fb0ab046cd857da5
>>> arm64: mm: Move reserve_crashkernel() into mem_init())
>>>
>>> which deferred crashkernel reservation into mem_init().
>>>
>>> The ~150ms slowdown disappears on booting without "crashkernel=.." on
>>> kernel
>>> command-line.
>>
>> Is CONFIG_RODATA_FULL_DEFAULT_ENABLED set in your config file? It may
>> cause the same slowdown. I suspect it's because we end up mapping the
>> RAM at the page granularity so more loops and slightly higher TLB
>> pressure. Not sure we can do much about >
>
> Catalin,
>
> Thanks for your reply.
>
> CONFIG_RODATA_FULL_DEFAULT_ENABLED is not set in our config for boot
> time performance reasons.

From following patches, the main source of deferring crash kernel
reservation is for Raspberry Pi 4, which has no IOMMU.

1a8e1cef7603e218339ac63cb3178b25554524e5
arm64: use both ZONE_DMA and ZONE_DMA32

8424ecdde7df99d5426e1a1fd9f0fb36f4183032
arm64: mm: Set ZONE_DMA size based on devicetree's dma-ranges

0a30c53573b07d5561457e41fb0ab046cd857da5
arm64: mm: Move reserve_crashkernel() into mem_init())

2687275a5843d1089687f08fc64eb3f3b026a169
arm64: Force NO_BLOCK_MAPPINGS if crashkernel reservation is required

However above changes introduced slow boot (regression) for platforms
with IOMMU, for example as I mentioned earlier ~150ms for us. We don't
have following configs set for our SoC --

# CONFIG_ZONE_DMA is not set
# CONFIG_ZONE_DMA32 is not set

Can we restore crash kernel reservation (no deferring to mem_init()) for
platforms with no DMA memory zones?

I can submit a patch.

Thanks,
Vijay