On Sun, 16 May 2021 15:39:56 +0800 Hu Weiwen wrote:

On Sun, May 16, 2021 at 10:50:35AM +0800, Hillf Danton wrote:

quoted

On Sun, 16 May 2021 01:01:04 +0800 Hu Weiwen wrote:

quoted

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.

Given the do_huge_pmd_anonymous_page in your perf report below, what you
need is likely commit facdaa917c4d ("mm: proactive compaction").

You need to port it back to the linux-5.4 powering your box if there is
anying that prevents you from using the mainline kernel. Feel free to
report again if it does not work for you.

Thank you for your reply. Will try it. But it is hard to say whether it is
working. We can only reproduce this about once per month on 10+ similar boxes.

But I think things still not adding up.

The last time I see this, I left it running in this state for 6 hours. But it
still does not get better. If it is just fragmented memory that caused too much
compaction on huge page allocation, I'd expect it to solve itself in minutes.

Sounds good given "367GB of RAM is available when we observe the problem."
(free -g illustrates the available RAM.)

Commit message of facdaa917c4d reported 700GB memory being allocated in 27
minutes without that patch, but we hardly have any progress in 6 hours.

Also, Commit message of facdaa917c4d reported at most 33ms latency on allocation
without that patch, but we see 3 seconds per page fault.

Over 99% of pages passed to `migrate_pages' are failed to migrate. This is
concerning. It might relate to our issue. I plan to investigate more on this
when I see the issue next time. Any tips on how to find out why migrate failed
are appreciated.

No idea of such tips if they exist instead of migrate.c.
If d479960e44f2 ("mm: disable LRU pagevec during the migration temporarily")
is not a cure then try to see which commit works with GPU module unloaded.

quoted

quoted

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