linux-kernel - Re: mm: LTP/memcg testcase regression induced by 8cd7c588decf..66ce520bb7c2 series

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <904392102aee146723ebd442c6289db10f85f421.camel@gmx.de>
Date:   Tue, 23 Nov 2021 14:12:59 +0100
From:   Mike Galbraith <efault@....de>
To:     Mel Gorman <mgorman@...hsingularity.net>
Cc:     lkml <linux-kernel@...r.kernel.org>
Subject: Re: mm: LTP/memcg testcase regression induced by
 8cd7c588decf..66ce520bb7c2 series

On Tue, 2021-11-23 at 12:18 +0100, Mike Galbraith wrote:
> On Tue, 2021-11-23 at 09:13 +0000, Mel Gorman wrote:
> >
> > I'll see can I reproduce this...
>
> You likely already know this, but just in case, just plunk the below
> into $LTPROOT/runtest/foo, and $LTPROOT/runltp -f foo.
>
> #DESCRIPTION:Resource Management testing
> memcg_regression        memcg_regression_test.sh

Editing memcg_regression_test.sh to only run test_4() works fine, and
an earlier kernel does oom-kill swapoff as it expects.

  319.265016] swapoff invoked oom-killer: gfp_mask=0x1100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0

New kernel says it oom-killed, but it's in the penalty box.

[  272.325727] swapoff invoked oom-killer: gfp_mask=0x1100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0

crash> ps | grep memcg
   4105   4104   4  ffff953bd1a88000  IN   0.0   15176   3596  memcg_regressio
   4115   4105   0  ffff953beffe2880  IN   0.0   15172   3580  memcg_test_4.sh
   4117   4115   7  ffff953c0b818000  IN   0.2  110020  38404  memcg_test_4
crash> ps | grep swapoff
   4138   4115   1  ffff953bf2f70000  UN   0.0   19032      0  swapoff
crash> bt -sx 4138
PID: 4138   TASK: ffff953bf2f70000  CPU: 5   COMMAND: "swapoff"
 #0 [ffffad1a02957770] __schedule+0x2c3 at ffffffff932636e3
 #1 [ffffad1a02957830] schedule+0x3a at ffffffff932644ba
 #2 [ffffad1a02957840] schedule_timeout+0x1f3 at ffffffff93268d03
 #3 [ffffad1a029578b8] reclaim_throttle+0xd0 at ffffffff92a69ab0
 #4 [ffffad1a02957920] do_try_to_free_pages+0x160 at ffffffff92a6bab0
 #5 [ffffad1a02957978] try_to_free_mem_cgroup_pages+0xf4 at ffffffff92a6d264
 #6 [ffffad1a02957a10] try_charge_memcg+0x19f at ffffffff92b03b6f
 #7 [ffffad1a02957ab0] charge_memcg+0x33 at ffffffff92b04313
 #8 [ffffad1a02957ad0] mem_cgroup_swapin_charge_page+0x58 at ffffffff92b06a08
 #9 [ffffad1a02957b00] __read_swap_cache_async+0x206 at ffffffff92ac2006
#10 [ffffad1a02957b68] swap_cluster_readahead+0x165 at ffffffff92ac2295
#11 [ffffad1a02957bf0] swapin_readahead+0x84 at ffffffff92ac24d4
#12 [ffffad1a02957c78] unuse_pte_range+0x53c at ffffffff92ac5cfc
#13 [ffffad1a02957d68] try_to_unuse+0x50e at ffffffff92ac664e
#14 [ffffad1a02957e38] __do_sys_swapoff+0x1e4 at ffffffff92ac6ba4
#15 [ffffad1a02957e90] do_syscall_64+0x58 at ffffffff93256138
#16 [ffffad1a02957ea8] exit_to_user_mode_prepare+0xf8 at ffffffff9293f138
#17 [ffffad1a02957ec0] syscall_exit_to_user_mode+0x18 at ffffffff9325a358
#18 [ffffad1a02957ed0] do_syscall_64+0x67 at ffffffff93256147
#19 [ffffad1a02957ef0] syscall_exit_to_user_mode+0x18 at ffffffff9325a358
#20 [ffffad1a02957f28] exc_page_fault+0x67 at ffffffff93259c97
#21 [ffffad1a02957f50] entry_SYSCALL_64_after_hwframe+0x44 at ffffffff9340007c
    RIP: 00007f6da7cd9997  RSP: 00007fffbca10388  RFLAGS: 00000202
    RAX: ffffffffffffffda  RBX: 0000000000000001  RCX: 00007f6da7cd9997
    RDX: 0000000000000001  RSI: 0000000000000001  RDI: 000055bc98cb6d10
    RBP: 000055bc98cb6d10   R8: 00007fffbca103f0   R9: 0000000000000003
    R10: 000055bc98cb15af  R11: 0000000000000202  R12: 0000000000000001
    R13: 0000000000000000  R14: 00007fffbca103f0  R15: 0000000000000000
    ORIG_RAX: 00000000000000a8  CS: 0033  SS: 002b
crash>

Enabling sched events for it...

homer:..debug/tracing # tail -25 trace
         swapoff-4138    [001] d....  1641.929650: sched_switch: prev_comm=swapoff prev_pid=4138 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120
          <idle>-0       [001] d.s..  1642.441625: sched_waking: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] dNs..  1642.441631: sched_wakeup: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] d....  1642.441638: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapoff next_pid=4138 next_prio=120
         swapoff-4138    [001] d....  1642.441642: sched_waking: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1642.441643: sched_stat_runtime: comm=swapoff pid=4138 runtime=11453 [ns] vruntime=45946584931 [ns]
         swapoff-4138    [001] d....  1642.441645: sched_wakeup: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1642.441652: sched_stat_runtime: comm=swapoff pid=4138 runtime=8758 [ns] vruntime=45946593689 [ns]
         swapoff-4138    [001] d....  1642.441653: sched_switch: prev_comm=swapoff prev_pid=4138 prev_prio=120 prev_state=D ==> next_comm=kworker/1:0 next_pid=5005 next_prio=120
          <idle>-0       [001] d.s..  1642.953622: sched_waking: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] dNs..  1642.953627: sched_wakeup: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] d....  1642.953634: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapoff next_pid=4138 next_prio=120
         swapoff-4138    [001] d....  1642.953638: sched_waking: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1642.953639: sched_stat_runtime: comm=swapoff pid=4138 runtime=10995 [ns] vruntime=45946604684 [ns]
         swapoff-4138    [001] d....  1642.953641: sched_wakeup: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1642.953648: sched_stat_runtime: comm=swapoff pid=4138 runtime=8633 [ns] vruntime=45946613317 [ns]
         swapoff-4138    [001] d....  1642.953649: sched_switch: prev_comm=swapoff prev_pid=4138 prev_prio=120 prev_state=D ==> next_comm=kworker/1:0 next_pid=5005 next_prio=120
          <idle>-0       [001] d.s..  1643.465642: sched_waking: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] dNs..  1643.465654: sched_wakeup: comm=swapoff pid=4138 prio=120 target_cpu=001
          <idle>-0       [001] d....  1643.465674: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapoff next_pid=4138 next_prio=120
         swapoff-4138    [001] d....  1643.465683: sched_waking: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1643.465686: sched_stat_runtime: comm=swapoff pid=4138 runtime=28731 [ns] vruntime=45946642048 [ns]
         swapoff-4138    [001] d....  1643.465690: sched_wakeup: comm=kworker/1:0 pid=5005 prio=120 target_cpu=001
         swapoff-4138    [001] d....  1643.465708: sched_stat_runtime: comm=swapoff pid=4138 runtime=21966 [ns] vruntime=45946664014 [ns]
         swapoff-4138    [001] d....  1643.465711: sched_switch: prev_comm=swapoff prev_pid=4138 prev_prio=120 prev_state=D ==> next_comm=kworker/1:0 next_pid=5005 next_prio=120
homer:..debug/tracing #

...I bet if I were reeeeeally patient, I might see the test pass.

LOL, and as I write this, it just did :)

	-Mike