On 12/2/2022 4:29 AM, Rik van Riel wrote:
> On Thu, 2022-12-01 at 19:33 +0100, Thorsten Leemhuis wrote:
>> Hi, this is your Linux kernel regression tracker.
>>
>> On 28.11.22 07:40, Nathan Chancellor wrote:
>>> Hi Rik,
>>
>> I wonder what we should do about below performance regression. Is
>> reverting the culprit now and reapplying it later together with a fix
>> a
>> viable option? Or was anything done/is anybody doing something
>> already
>> to address the problem and I just missed it?
>
> The changeset in question speeds up kernel compiles with
> GCC, as well as the runtime speed of other programs, due
> to being able to use THPs more. However, it slows down kernel
> compiles with clang, due to ... something clang does.
>
> I have not figured out what that something is yet.
>
> I don't know if I have the wrong version of clang here,
> but I have not seen any smoking gun at all when tracing
> clang system calls. I see predominantly small mmap and
> unmap calls, and nothing that even triggers 2MB alignment.
There are some findings in my side. I not very sure that it's root
case and like to share here to call more eyes on it.
1. The regression is not related to clang. It's related with
ld.lld.
In my env, command
make LD=ld.lld -skj96 allmodconfig all
could reproduce the regression. But command
make CC=clang -skj96 allmodconfig all
can't reproduce the regression.
2. It looks like ld.lld calls madvise(MADV_DONTNEED) many times to
free memory. But the parameters "len" is not friendly to THP.
trace-bpfcc with do_madvise gave:
531607 531732 ld.lld do_madvise.part.0 start: 0x7feca9000000, len: 0x7fb000, behavior: 0x4
531607 531793 ld.lld do_madvise.part.0 start: 0x7fec86a00000, len: 0x7fb000, behavior: 0x4
531607 531767 ld.lld do_madvise.part.0 start: 0x7fec95000000, len: 0x7fb000, behavior: 0x4
531607 531703 ld.lld do_madvise.part.0 start: 0x7fecb3000000, len: 0x7fb000, behavior: 0x4
531607 531757 ld.lld do_madvise.part.0 start: 0x7fec9b400000, len: 0x7fb000, behavior: 0x4
531607 531701 ld.lld do_madvise.part.0 start: 0x7fecb4400000, len: 0x7fb000, behavior: 0x4
531607 531795 ld.lld do_madvise.part.0 start: 0x7fec85600000, len: 0x7fb000, behavior: 0x4
531607 531792 ld.lld do_madvise.part.0 start: 0x7fec87400000, len: 0x7fb000, behavior: 0x4
531607 531695 ld.lld do_madvise.part.0 start: 0x7fecbca00000, len: 0x7fb000, behavior: 0x4
531607 531760 ld.lld do_madvise.part.0 start: 0x7fec99600000, len: 0x7fb000, behavior: 0x4
531607 531706 ld.lld do_madvise.part.0 start: 0x7fecb1200000, len: 0x7fb000, behavior: 0x4
531607 531769 ld.lld do_madvise.part.0 start: 0x7fec94600000, len: 0x7fb000, behavior: 0x4
531607 531699 ld.lld do_madvise.part.0 start: 0x7fecb5800000, len: 0x7fb000, behavior: 0x4
531607 531738 ld.lld do_madvise.part.0 start: 0x7feca5e00000, len: 0x7fb000, behavior: 0x4
3. I captured the perf data for 50s when kernel build with ld.lld
was ongoing and got:
24.20% 0.27% cc1 [kernel.kallsyms] [k] asm_exc_page_fault
9.52%
asm_exc_page_fault
exc_page_fault
do_user_addr_fault
handle_mm_fault
__handle_mm_fault
do_huge_pmd_anonymous_page
vma_alloc_folio
__folio_alloc
__alloc_pages
get_page_from_freelist
clear_page_erms
14.85% 0.00% ld.lld [kernel.kallsyms] [k] entry_SYSCALL_64_after_hwframe
11.52%
entry_SYSCALL_64_after_hwframe
do_syscall_64
__x64_sys_madvise
do_madvise.part.0
zap_page_range
unmap_single_vma
unmap_page_range
page_remove_rmap
deferred_split_huge_page
__lock_text_start
native_queued_spin_lock_slowpath
My understanding is that the deferred_split_huge_page() here is kind of
matching len: 0x7fb000 in do_madvise() call. The end is not PMD size
aligned and trigger lock contention on deferred_split_queue.
With GNU ld, there is no any madvise(MADV_DONTNEED) called.
Regards
Yin, Fengwei
>
>>
>> Yang Shi, Andrew, what's your option on this? I ask you directly,
>> because it looks like Rik hasn't posted anything to lists archived on
>> lore during the last few weeks. :-/
>>
>> Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker'
>> hat)
>>
>> P.S.: As the Linux kernel's regression tracker I deal with a lot of
>> reports and sometimes miss something important when writing mails
>> like
>> this. If that's the case here, don't hesitate to tell me in a public
>> reply, it's in everyone's interest to set the public record straight.
>>
>>> On Thu, Oct 20, 2022 at 10:16:20AM -0700, Nathan Chancellor wrote:
>>>> On Thu, Oct 20, 2022 at 11:28:16AM -0400, Rik van Riel wrote:
>>>>> On Thu, 2022-10-20 at 13:07 +0800, Huang, Ying wrote:
>>>>>> Nathan Chancellor <nathan@xxxxxxxxxx> writes:
>>>>>>>
>>>>>>> For what it's worth, I just bisected a massive and visible
>>>>>>> performance
>>>>>>> regression on my Threadripper 3990X workstation to commit
>>>>>>> f35b5d7d676e
>>>>>>> ("mm: align larger anonymous mappings on THP boundaries"),
>>>>>>> which
>>>>>>> seems
>>>>>>> directly related to this report/analysis. I initially
>>>>>>> noticed this
>>>>>>> because my full set of kernel builds against mainline went
>>>>>>> from 2
>>>>>>> hours
>>>>>>> and 20 minutes or so to over 3 hours. Zeroing in on x86_64
>>>>>>> allmodconfig,
>>>>>>> which I used for the bisect:
>>>>>>>
>>>>>>> @ 7b5a0b664ebe ("mm/page_ext: remove unused variable in
>>>>>>> offline_page_ext"):
>>>>>>>
>>>>>>> Benchmark 1: make -skj128 LLVM=1 allmodconfig all
>>>>>>> Time (mean ± σ): 318.172 s ± 0.730 s [User:
>>>>>>> 31750.902 s,
>>>>>>> System: 4564.246 s]
>>>>>>> Range (min … max): 317.332 s … 318.662 s 3 runs
>>>>>>>
>>>>>>> @ f35b5d7d676e ("mm: align larger anonymous mappings on THP
>>>>>>> boundaries"):
>>>>>>>
>>>>>>> Benchmark 1: make -skj128 LLVM=1 allmodconfig all
>>>>>>> Time (mean ± σ): 406.688 s ± 0.676 s [User:
>>>>>>> 31819.526 s,
>>>>> System: 16327.022 s]
>>>>>>> Range (min … max): 405.954 s … 407.284 s 3 run
>>>>>>
>>>>>> Have you tried to build with gcc? Want to check whether is
>>>>>> this
>>>>>> clang
>>>>>> specific issue or not.
>>>>>
>>>>> This may indeed be something LLVM specific. In previous tests,
>>>>> GCC has generally seen a benefit from increased THP usage.
>>>>> Many other applications also benefit from getting more THPs.
>>>>
>>>> Indeed, GCC builds actually appear to be slightly faster on my
>>>> system now,
>>>> apologies for not trying that before reporting :/
>>>>
>>>> 7b5a0b664ebe:
>>>>
>>>> Benchmark 1: make -skj128 allmodconfig all
>>>> Time (mean ± σ): 355.294 s ± 0.931 s [User: 33620.469
>>>> s, System: 6390.064 s]
>>>> Range (min … max): 354.571 s … 356.344 s 3 runs
>>>>
>>>> f35b5d7d676e:
>>>>
>>>> Benchmark 1: make -skj128 allmodconfig all
>>>> Time (mean ± σ): 347.400 s ± 2.029 s [User: 34389.724
>>>> s, System: 4603.175 s]
>>>> Range (min … max): 345.815 s … 349.686 s 3 runs
>>>>
>>>>> LLVM showing 10% system time before this change, and a whopping
>>>>> 30% system time after that change, suggests that LLVM is
>>>>> behaving
>>>>> quite differently from GCC in some ways.
>>>>
>>>> The above tests were done with GCC 12.2.0 from Arch Linux. The
>>>> previous LLVM
>>>> tests were done with a self-compiled version of LLVM from the
>>>> main branch
>>>> (16.0.0), optimized with BOLT [1]. To eliminate that as a source
>>>> of issues, I
>>>> used my distribution's version of clang (14.0.6) and saw similar
>>>> results as
>>>> before:
>>>>
>>>> 7b5a0b664ebe:
>>>>
>>>> Benchmark 1: make -skj128 LLVM=/usr/bin/ allmodconfig all
>>>> Time (mean ± σ): 462.517 s ± 1.214 s [User: 48544.240
>>>> s, System: 5586.212 s]
>>>> Range (min … max): 461.115 s … 463.245 s 3 runs
>>>>
>>>> f35b5d7d676e:
>>>>
>>>> Benchmark 1: make -skj128 LLVM=/usr/bin/ allmodconfig all
>>>> Time (mean ± σ): 547.927 s ± 0.862 s [User: 47913.709
>>>> s, System: 17682.514 s]
>>>> Range (min … max): 547.429 s … 548.922 s 3 runs
>>>>
>>>>> If we can figure out what these differences are, maybe we can
>>>>> just fine tune the code to avoid this issue.
>>>>>
>>>>> I'll try to play around with LLVM compilation a little bit next
>>>>> week, to see if I can figure out what might be going on. I
>>>>> wonder
>>>>> if LLVM is doing lots of mremap calls or something...
>>>>
>>>> If there is any further information I can provide or patches I
>>>> can test,
>>>> I am more than happy to do so.
>>>>
>>>> [1]:
>>>> https://github.com/llvm/llvm-project/tree/96552e73900176d65ee6650facae8d669d6f9498/bolt
>>>
>>> Was there ever a follow up to this report that I missed? I just
>>> noticed that I am still reverting f35b5d7d676e in my mainline
>>> kernel.
>>>
>>> Cheers,
>>> Nathan
>>>
>>
>> #regzbot ignore-activity
>>
>
