Re: Hugepage program taking forever to exit

[Yu Zhao <yuzhao@google.com>]

On Tue, Sep 10, 2024 at 12:21 PM Jens Axboe <axboe@kernel.dk> wrote:
>
> Hi,
>
> Investigating another issue, I wrote the following simple program that allocates
> and faults in 500 1GB huge pages, and then registers them with io_uring. Each
> step is timed:
>
> Got 500 huge pages (each 1024MB) in 0 msec
> Faulted in 500 huge pages in 38632 msec
> Registered 500 pages in 867 msec
>
> and as expected, faulting in the pages takes (by far) the longest. From
> the above, you'd also expect the total runtime to be around ~39 seconds.
> But it is not... In fact it takes 82 seconds in total for this program
> to have exited. Looking at why, I see:
>
> [<0>] __wait_rcu_gp+0x12b/0x160
> [<0>] synchronize_rcu_normal.part.0+0x2a/0x30
> [<0>] hugetlb_vmemmap_restore_folios+0x22/0xe0
> [<0>] update_and_free_pages_bulk+0x4c/0x220
> [<0>] return_unused_surplus_pages+0x80/0xa0
> [<0>] hugetlb_acct_memory.part.0+0x2dd/0x3b0
> [<0>] hugetlb_vm_op_close+0x160/0x180
> [<0>] remove_vma+0x20/0x60
> [<0>] exit_mmap+0x199/0x340
> [<0>] mmput+0x49/0x110
> [<0>] do_exit+0x261/0x9b0
> [<0>] do_group_exit+0x2c/0x80
> [<0>] __x64_sys_exit_group+0x14/0x20
> [<0>] x64_sys_call+0x714/0x720
> [<0>] do_syscall_64+0x5b/0x160
> [<0>] entry_SYSCALL_64_after_hwframe+0x4b/0x53
>
> and yes, it does look like the program is mostly idle for most of the
> time while returning these huge pages. It's also telling us exactly why
> we're just sitting idle - RCU grace period.
>
> The below quick change means the runtime of the program is pretty much
> just the time it takes to execute the parts of it, as you can see from
> the full output after the change:
>
> axboe@r7525 ~> time sudo ./reg-huge
> Got 500 huge pages (each 1024MB) in 0 msec
> Faulted in 500 huge pages in 38632 msec
> Registered 500 pages in 867 msec
>
> ________________________________________________________
> Executed in   39.53 secs      fish           external
>    usr time    4.88 millis  238.00 micros    4.64 millis
>    sys time    0.00 millis    0.00 micros    0.00 millis
>
> where 38632+876 == 39.51s.
>
> Looks like this was introduced by:
>
> commit bd225530a4c717714722c3731442b78954c765b3
> Author: Yu Zhao <yuzhao@google.com>
> Date:   Thu Jun 27 16:27:05 2024 -0600

Fixes are in git://git.kernel.org/pub/scm/linux/kernel/git/akpm/mm.git mm-stable

c2a967f6ab0e mm/hugetlb_vmemmap: don't synchronize_rcu() without HVO
c0f398c3b2cf mm/hugetlb_vmemmap: batch HVO work when demoting

Additional improvements from mm-stable that may or may not help your test case:

e98337d11bbd mm/contig_alloc: support __GFP_COMP
463586e9ff39 mm/cma: add cma_{alloc,free}_folio()
cf54f310d0d3 mm/hugetlb: use __GFP_COMP for gigantic folios