lkml.org 
[lkml]   [2021]   [Nov]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: mm: LTP/memcg testcase regression induced by 8cd7c588decf..66ce520bb7c2 series
    From
    Date
    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

    \
     
     \ /
      Last update: 2021-11-23 14:14    [W:4.222 / U:0.012 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site