[arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update

[arm64] kernel boot slowdown in v5.10.19 -> v5.10.42 update

[Vijay Balakrishna]

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

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

[Catalin Marinas]

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

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

[Vijay Balakrishna]

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.

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

[Vijay Balakrishna]

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