illumos gate

Root cause

The problem is happening because i40e_m_stop() needs to call ddi_dma_mem_free() many times - approximately 0x100*(0x400+0x400+0x600) = ca 1M times. Every ddi_dma_mem_free() usually turns to one vmem_free() call via contig_free() and then to one vmem_hash_delete() call. The vmem_hash_delete() function is the actual bottleneck as could be seen here:

[0]> ::bp i40e`i40e_m_stop
[0]> :c

...

kmdb: stop at i40e`i40e_m_stop
kmdb: target stopped at:
i40e`i40e_m_stop:       pushq  %rbp
[0]> heap_arena::print|::print vmem_t vm_kstat.vk_lookup.value.ui64
vm_kstat.vk_lookup.value.ui64 = 0x3
[0]> dls_link_rele::bp
[0]> :c

... after ca 30 minutes ...

kmdb: stop at dls`dls_link_rele
kmdb: target stopped at:
dls`dls_link_rele:      pushq  %rbp
[0]> heap_arena::print|::print vmem_t vm_kstat.vk_lookup.value.ui64
vm_kstat.vk_lookup.value.ui64 = 0x66d76ba0c
[0]>

Yes, in our example the vmem_hash_delete() function had to iterate in the while loop 27606301196 (2.76e10) times! Honestly, I'm a bit surprised it took 30 minutes only :-).

Why is the heap_arena so slow? Because during boot the vmem_hash_rescale() optimizer does not run yet:

380void
381main(void)
382{

...

516    /*
517     * Initialize Solaris Audit Subsystem
518     */
519    audit_init();
520
521    /*
522     * Plumb the protocol modules and drivers only if we are not
523     * networked booted, in this case we already did it in rootconf().
524     */
525    if (netboot == 0 && iscsiboot_prop == NULL)
526        (void) strplumb();

...

601    /*
602     * After mp_init(), number of cpus are known (this is
603     * true for the time being, when there are actually
604     * hot pluggable cpus then this scheme  would not do).
605     * Any per cpu initialization is done here.
606     */
607    kmem_mp_init();
608    vmem_update(NULL);

...

The i40e driver is loaded at line 526 via strplumb(). Then, once all drivers are loaded, the hash optimizer is started at line 608 - via the vmem_update() call, but i40e_m_stop() is called while still in strplumb().

Proposed solution

With the root cause known the obvious question arises: Why we do not call vmem_update(NULL) before strplumb() to make sure all vmem arenas are properly optimized as soon as possible?

The short answer is: I do not know.

The longer answer is: I was unable to find any reason why we need to defer the vmem_update(NULL) call until so late in the boot process. So the easiest fix should be just to move the vmem_update(NULL) call before the strplumb() call.

To confirm how such modification changes our case (and to see whether it possibly causes any regression) I patched the live code as follows:

[0]> main+0x170::dis -n 2
main+0x161:                     call   -0x2253a6        <post_startup>
main+0x166:                     movl   $0x1,+0x2910c0(%rip)     <swaploaded>
main+0x170:                     call   -0xa8eb5 <audit_init>
main+0x175:                     movl   +0x28846d(%rip),%edx     <netboot>
main+0x17b:                     testl  %edx,%edx
[0]> main+0x171/W 000CBB7B
main+0x171:     0xfff5714b      =       0xcbb7b
[0]> main+0x170::dis -n 2
main+0x161:                     call   -0x2253a6        <post_startup>
main+0x166:                     movl   $0x1,+0x2910c0(%rip)     <swaploaded>
main+0x170:                     call   +0xcbb7b <vmem_update>
main+0x175:                     movl   +0x28846d(%rip),%edx     <netboot>
main+0x17b:                     testl  %edx,%edx
[0]>
[0]>
[0]>
[0]>
[0]>
[0]> main+0x2ba::dis -n 2
main+0x2b3:                     call   -0x15508 <kmem_mp_init>
main+0x2b8:                     xorl   %edi,%edi
main+0x2ba:                     call   +0xcba31 <vmem_update>
main+0x2bf:                     call   -0x1c6254        <clock_tick_init_post>
main+0x2c4:                     movq   +0x19d165(%rip),%rdx     <mp_init_tbl>
[0]> main+0x2ba/W 90909090
main+0x2ba:     0xcba31e8       =       0x90909090
[0]> main+0x2be/v 90
main+0x2be:     0       =       0x90
[0]> main+0x2ba::dis -n 6
main+0x2a2:                     xorl   %edi,%edi
main+0x2a4:                     call   -0x22de89        <start_other_cpus>
main+0x2a9:                     movl   $0x4,%edi
main+0x2ae:                     call   -0x1f2ec3        <lgrp_init>
main+0x2b3:                     call   -0x15508 <kmem_mp_init>
main+0x2b8:                     xorl   %edi,%edi
main+0x2ba:                     nop    
main+0x2bb:                     nop    
main+0x2bc:                     nop    
main+0x2bd:                     nop    
main+0x2be:                     nop    
main+0x2bf:                     call   -0x1c6254        <clock_tick_init_post>
main+0x2c4:                     movq   +0x19d165(%rip),%rdx     <mp_init_tbl>
[0]>

So I simply replaced the audit_init() call at line 519 by the vmem_update() call and removed the vmem_update() call from line 608. Then I measured how it behaves:

[0]> ::bp i40e`i40e_m_stop
[0]> :c

...

kmdb: stop at i40e`i40e_m_stop
kmdb: target stopped at:
i40e`i40e_m_stop:       pushq  %rbp
[0]> heap_arena::print|::print vmem_t vm_kstat.vk_lookup.value.ui64
vm_kstat.vk_lookup.value.ui64 = 0
[0]> dls_link_rele::bp
[0]> :c

... after few seconds ...

kmdb: stop at dls`dls_link_rele
kmdb: target stopped at:
dls`dls_link_rele:      pushq  %rbp
[0]> heap_arena::print|::print vmem_t vm_kstat.vk_lookup.value.ui64
vm_kstat.vk_lookup.value.ui64 = 0x37bff
[0]> ::delete 1
[0]> ::delete 2
[0]> :c

...

openindiana console login:

Far better results.

Review: https://www.illumos.org/rb/r/2504/

Testing Done

Without this change the boot process on affected machines was stuck for about 30 minutes in the i40e driver. With the fix the delay is hardly noticeable.

I also confirmed that this change does not introduce any regression on tested machines.