Very slow page fault caused by migrate_pages
From: Hu Weiwen
Date: Sat May 15 2021 - 13:22:30 EST
Hi all,
We observed our program sometimes running over 1000x slower than normal and
cannot find the root cause. I would be grateful if someone can give me a hint. I
also searched on this mailing list but failed to find anything related.
The affected process spend almost 100% CPU time in kernel. First I ran `perf' to
identify where times are spent. It turns out 99.93% of the time is spent on
do_page_fault, and 98.16% on migrate_pages. And `perf record -e faults -t <tid>`
show 3 seconds per fault, which seems to much to me.
Then I do `perf record -e compaction:*`, and see 12k
compaction:mm_compaction_migratepages events per second. almost all of them has
nr_migrated=0 and nr_failed greater than 0. So it seems a lot of migration
failure is happening. But I cannot understand what causes it. The more
complete perf output is attached below.
This system is used to run machine-learning training programs, with 2 Intel Xeon
CPU, 512GB RAM and 8 NVIDIA GPU attached, running Ubuntu 20.04, with kernel
version 5.4.0-72-generic. Load average is 13, and 367GB of RAM is available when
we observe the problem this time. We have observed the very same problem on
multiple nodes, running different programs, with different models of CPU, GPU.
Currently, only reboot the system can resolve this. When this happens, all
process on the system is affected, and it does not resolve if I restart the
affected process.
Thanks,
Hu Weiwen
SCUT student
`perf report` output, collected with `sudo perf record -F 99 --pid 2413158 -g -- sleep 10`:
Samples: 993 of event 'cycles', Event count (approx.): 36810932529
Children Self Command Shared Object Symbol
- 99.93% 0.00% python libc-2.31.so [.] 0x00007ff5fcc78984 ▒
0x7ff5fcc78984 ▒
page_fault ▒
do_page_fault ▒
__do_page_fault ▒
do_user_addr_fault ▒
handle_mm_fault ▒
__handle_mm_fault ▒
do_huge_pmd_anonymous_page ◆
alloc_pages_vma ▒
__alloc_pages_nodemask ▒
__alloc_pages_slowpath ▒
__alloc_pages_direct_compact ▒
try_to_compact_pages ▒
compact_zone_order ▒
- compact_zone ▒
- 98.16% migrate_pages ▒
- 93.30% try_to_unmap ▒
- rmap_walk ▒
- 92.12% rmap_walk_file ▒
- 90.45% try_to_unmap_one ▒
- 83.48% ptep_clear_flush ▒
- 76.33% flush_tlb_mm_range ▒
- 74.35% native_flush_tlb_others ▒
- 73.75% on_each_cpu_cond_mask ▒
- 70.85% on_each_cpu_mask ▒
- 69.57% smp_call_function_many ▒
- 67.20% smp_call_function_single ▒
4.93% llist_add_batch ▒
+ 1.09% generic_exec_single ▒
1.19% smp_call_function_single ▒
+ 2.01% zalloc_cpumask_var ▒
1.45% page_vma_mapped_walk ▒
0.78% down_read ▒
0.79% up_read ▒
+ 3.29% remove_migration_ptes ▒
0.59% move_to_new_page
`perf report` output, collected with `sudo perf record -e compaction:* -a -- sleep 10`:
Samples: 133K of event 'compaction:mm_compaction_migratepages', Event count (approx.): 133394
Overhead Trace output
26.25% nr_migrated=0 nr_failed=32
5.00% nr_migrated=0 nr_failed=2
4.64% nr_migrated=0 nr_failed=4
4.24% nr_migrated=0 nr_failed=3
4.20% nr_migrated=0 nr_failed=6
3.83% nr_migrated=0 nr_failed=1
3.79% nr_migrated=0 nr_failed=5
3.62% nr_migrated=0 nr_failed=7
3.45% nr_migrated=0 nr_failed=8
3.06% nr_migrated=0 nr_failed=9
2.68% nr_migrated=0 nr_failed=10
2.68% nr_migrated=0 nr_failed=11
2.42% nr_migrated=0 nr_failed=12
2.35% nr_migrated=0 nr_failed=13
2.11% nr_migrated=0 nr_failed=14
1.93% nr_migrated=0 nr_failed=16
1.90% nr_migrated=0 nr_failed=15
1.64% nr_migrated=0 nr_failed=17
1.50% nr_migrated=0 nr_failed=18
1.25% nr_migrated=0 nr_failed=19
1.25% nr_migrated=0 nr_failed=20
1.22% nr_migrated=0 nr_failed=21
...
0.00% nr_migrated=0 nr_failed=207 ▒
0.00% nr_migrated=0 nr_failed=258 ▒
0.00% nr_migrated=0 nr_failed=273 ▒
0.00% nr_migrated=0 nr_failed=277 ▒
0.00% nr_migrated=10 nr_failed=22 ▒
0.00% nr_migrated=13 nr_failed=19 ▒
0.00% nr_migrated=2 nr_failed=2 ▒
0.00% nr_migrated=3 nr_failed=13 ▒
0.00% nr_migrated=3 nr_failed=17 ▒
0.00% nr_migrated=3 nr_failed=25 ▒
0.00% nr_migrated=3 nr_failed=27 ▒
0.00% nr_migrated=3 nr_failed=28 ▒
0.00% nr_migrated=4 nr_failed=10 ▒
0.00% nr_migrated=4 nr_failed=15 ▒
0.00% nr_migrated=4 nr_failed=24 ▒
0.00% nr_migrated=5 nr_failed=10 ▒
0.00% nr_migrated=5 nr_failed=15 ▒
0.00% nr_migrated=6 nr_failed=20 ▒
0.00% nr_migrated=6 nr_failed=21 ▒
0.00% nr_migrated=6 nr_failed=23 ▒
0.00% nr_migrated=8 nr_failed=19