Re: mm: mkfs.ext4 invoked oom-killer on i386 - pagecache_get_page

[Naresh Kamboju]

Thanks for looking into this problem.

On Sat, 2 May 2020 at 02:28, Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx> wrote:
>
> On Fri, 1 May 2020 18:08:28 +0530 Naresh Kamboju <naresh.kamboju@xxxxxxxxxx> wrote:
>
> > mkfs -t ext4 invoked oom-killer on i386 kernel running on x86_64 device
> > and started happening on linux -next master branch kernel tag next-20200430
> > and next-20200501. We did not bisect this problem.
>
> It would be wonderful if you could do so, please.  I can't immediately see
> any MM change in this area which might cause this.

We are planning a bisection soon on this problem.

>
> > metadata
> >   git branch: master
> >   git repo: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
> >   git commit: e4a08b64261ab411b15580c369a3b8fbed28bbc1
> >   git describe: next-20200430
> >   make_kernelversion: 5.7.0-rc3
> >   kernel-config:
> > https://builds.tuxbuild.com/1YrE_XUQ6odA52tSBM919w/kernel.config
> >
> > Steps to reproduce: (always reproducible)
>
> Reproducibility helps!
>
> > oom-killer: gfp_mask=0x101cc0(GFP_USER|__GFP_WRITE), order=0,
>
> > [   34.793430]  pagecache_get_page+0xae/0x260
>
> > [   34.897923] active_anon:5366 inactive_anon:2172 isolated_anon:0
> > [   34.897923]  active_file:4151 inactive_file:212494 isolated_file:0
> > [   34.897923]  unevictable:0 dirty:16505 writeback:6520 unstable:0
>
> > [ 34.987678] Normal free:3948kB min:7732kB low:8640kB high:9548kB
> > reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB
> > active_file:1096kB inactive_file:786400kB unevictable:0kB
> > writepending:65432kB present:884728kB managed:845576kB mlocked:0kB
> > kernel_stack:1112kB pagetables:0kB bounce:0kB free_pcp:2908kB
> > local_pcp:500kB free_cma:0kB
>
> ZONE_NORMAL has a huge amount of clean pagecache stuck on the
> inactive list, not being reclaimed.

FYI,
This issue is already reported here.
Now this problem is happening and easily reproducible on i386
and arm beagleboard x15 devices.

mkfs -t ext4 /dev/disk/by-id/ata-SanDisk_SSD_PLUS_120GB_190703A01414
mke2fs 1.43.8 (1-Jan-2018)
Discarding device blocks:     4096/29306880
2625536/29306880
9441280/29306880                 16257024/29306880
23072768/29306880
                                 done
Creating filesystem with 29306880 4k blocks and 7331840 inodes
Filesystem UUID: a838d994-0a1e-403a-88d5-444d75aecc5a
Superblock backups stored on blocks:
32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208,
4096000, 7962624, 11239424, 20480000, 23887872
Allocating group tables:   0/895                     done
Writing inode tables:   0/895                     done
Creating journal (131072 blocks): [   31.251333] mkfs.ext4 invoked
oom-killer: gfp_mask=0x101cc0(GFP_USER|__GFP_WRITE), order=0,
oom_score_adj=0
[   31.261172] CPU: 0 PID: 397 Comm: mkfs.ext4 Not tainted
5.7.0-rc6-next-20200518 #1
[   31.268771] Hardware name: Generic DRA74X (Flattened Device Tree)
[   31.274904] [<c0411500>] (unwind_backtrace) from [<c040b66c>]
(show_stack+0x10/0x14)
[   31.282685] [<c040b66c>] (show_stack) from [<c08b1b14>]
(dump_stack+0xc4/0xd8)
[   31.289940] [<c08b1b14>] (dump_stack) from [<c0547bf8>]
(dump_header+0x54/0x1ec)
[   31.297367] [<c0547bf8>] (dump_header) from [<c0547008>]
(oom_kill_process+0x18c/0x198)
[   31.305405] [<c0547008>] (oom_kill_process) from [<c0547a0c>]
(out_of_memory+0x250/0x368)
[   31.313619] [<c0547a0c>] (out_of_memory) from [<c0599d80>]
(__alloc_pages_nodemask+0xce8/0x10bc)
[   31.322445] [<c0599d80>] (__alloc_pages_nodemask) from [<c0541bb4>]
(pagecache_get_page+0x128/0x358)
[   31.331619] [<c0541bb4>] (pagecache_get_page) from [<c0543a8c>]
(grab_cache_page_write_begin+0x18/0x2c)
[   31.341054] [<c0543a8c>] (grab_cache_page_write_begin) from
[<c0619fb0>] (block_write_begin+0x20/0xc4)
[   31.350401] [<c0619fb0>] (block_write_begin) from [<c053e718>]
(generic_perform_write+0xb8/0x1d8)
[   31.359312] [<c053e718>] (generic_perform_write) from [<c054496c>]
(__generic_file_write_iter+0x164/0x1ec)
[   31.369007] [<c054496c>] (__generic_file_write_iter) from
[<c061c8a4>] (blkdev_write_iter+0xc8/0x1a4)
[   31.378269] [<c061c8a4>] (blkdev_write_iter) from [<c05d50d0>]
(__vfs_write+0x13c/0x1cc)
[   31.386397] [<c05d50d0>] (__vfs_write) from [<c05d81d4>]
(vfs_write+0xb0/0x1bc)
[   31.393738] [<c05d81d4>] (vfs_write) from [<c05d85e4>]
(ksys_pwrite64+0x60/0x8c)
[   31.401167] [<c05d85e4>] (ksys_pwrite64) from [<c04001a0>]
(ret_fast_syscall+0x0/0x4c)
[   31.409115] Exception stack(0xe810dfa8 to 0xe810dff0)
[   31.414185] dfa0:                   a2000000 0000000d 00000003
b6952008 00400000 00000000
[   31.422395] dfc0: a2000000 0000000d a2000000 000000b5 00400000
0003b768 b6952008 00da2000
[   31.430604] dfe0: 00000064 beb891b8 b6f85108 b6e38f2c
[   31.435809] Mem-Info:
[   31.438098] active_anon:5813 inactive_anon:4129 isolated_anon:0
[   31.438098]  active_file:6080 inactive_file:118548 isolated_file:0
[   31.438098]  unevictable:0 dirty:13674 writeback:7440 unstable:0
[   31.438098]  slab_reclaimable:5651 slab_unreclaimable:4566
[   31.438098]  mapped:5585 shmem:4468 pagetables:182 bounce:0
[   31.438098]  free:347556 free_pcp:608 free_cma:57235
[   31.472362] Node 0 active_anon:23252kB inactive_anon:16516kB
active_file:24320kB inactive_file:474192kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB mapped:22340kB dirty:54696kB
writeback:11196kB shmem:17872kB shmem_thp: 0kB shmem_pmdmapped: 0kB
anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[   31.500943] DMA free:187396kB min:22528kB low:28160kB high:33792kB
reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB
active_file:4736kB inactive_file:431688kB unevictable:0kB
writepending:62020kB present:783360kB managed:668264kB mlocked:0kB
kernel_stack:888kB pagetables:0kB bounce:0kB free_pcp:880kB
local_pcp:216kB free_cma:163840kB
[   31.531339] lowmem_reserve[]: 0 0 1216 0
[   31.535289] HighMem free:1203904kB min:512kB low:11592kB
high:22672kB reserved_highatomic:0KB active_anon:23252kB
inactive_anon:16516kB active_file:19584kB inactive_file:42420kB
unevictable:0kB writepending:0kB present:1310720kB managed:1310720kB
mlocked:0kB kernel_stack:0kB pagetables:728kB bounce:0kB
free_pcp:1584kB local_pcp:1232kB free_cma:65100kB
[   31.566540] lowmem_reserve[]: 0 0 0 0
[   31.570244] DMA: 87*4kB (UME) 53*8kB (UME) 26*16kB (UE) 6*32kB (UM)
1*64kB (E) 1*128kB (U) 5*256kB (ME) 5*512kB (ME) 4*1024kB (ME)
5*2048kB (M) 1*4096kB (M) 20*8192kB (C) = 187684kB
[   31.586520] HighMem: 2*4kB (MC) 1*8kB (C) 1*16kB (M) 5*32kB (UM)
4*64kB (UMC) 2*128kB (UM) 2*256kB (UM) 1*512kB (C) 2*1024kB (MC)
2*2048kB (MC) 2*4096kB (UC) 145*8192kB (MC) = 1203904kB
[   31.603150] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=2048kB
[   31.611637] 129102 total pagecache pages
[   31.615577] 0 pages in swap cache
[   31.618902] Swap cache stats: add 0, delete 0, find 0/0
[   31.624162] Free swap  = 0kB
[   31.627053] Total swap = 0kB
[   31.629955] 523520 pages RAM
[   31.632846] 327680 pages HighMem/MovableOnly
[   31.637128] 28774 pages reserved
[   31.640381] 57344 pages cma reserved
[   31.643971] Tasks state (memory values in pages):
[   31.648691] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes
swapents oom_score_adj name
[   31.657367] [    183]     0   183     7370     1082    36864
0             0 systemd-journal
[   31.666466] [    209]   994   209     3742      326    40960
0             0 systemd-timesyn
[   31.675570] [    217]     0   217     3398      817    32768
0         -1000 systemd-udevd
[   31.684498] [    230]   993   230     1411      737    32768
0             0 systemd-network
[   31.693598] [    231]   992   231     1496      712    32768
0             0 systemd-resolve
[   31.702702] [    236]   996   236     1112      742    24576
0          -900 dbus-daemon
[   31.711454] [    241]     0   241     1895     1045    36864
0             0 haveged
[   31.719857] [    242]     0   242     1362      906    28672
0             0 systemd-logind
[   31.728855] [    243]     0   243    13412     2571    69632
0             0 NetworkManager
[   31.737867] [    244]   995   244     1197      608    28672
0             0 avahi-daemon
[   31.746707] [    245]   995   245     1164       59    28672
0             0 avahi-daemon
[   31.755545] [    246]     0   246      594      332    28672
0             0 atd
[   31.763601] [    248]     0   248      699       99    24576
0             0 syslogd
[   31.772001] [    251]     0   251      699      102    24576
0             0 klogd
[   31.780231] [    252]     0   252      676      365    24576
0             0 crond
[   31.788443] [    254]     0   254     1172      240    32768
0             0 systemd-hostnam
[   31.797547] [    264] 65534   264      605       32    24576
0             0 dnsmasq
[   31.805948] [    265]     0   265      556      357    28672
0             0 agetty
[   31.814262] [    266]     0   266     1131      613    32768
0             0 login
[   31.822492] [    268]   998   268    18201     2629    81920
0             0 polkitd
[   31.830895] [    350]     0   350     1840     1161    32768
0             0 systemd
[   31.839286] [    351]     0   351     2403      473    36864
0             0 (sd-pam)
[   31.847774] [    355]     0   355      827      611    24576
0             0 sh
[   31.855742] [    364]     0   364     7341     1145    53248
0             0 nm-dispatcher
[   31.864667] [    377]     0   377      711      510    28672
0             0 lava-test-runne
[   31.873770] [    387]     0   387      711      138    20480
0             0 lava-test-shell
[   31.882869] [    388]     0   388      711      523    20480
0             0 sh
[   31.890837] [    397]     0   397     1785     1518    36864
0             0 mkfs.ext4
[   31.899397] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),global_oom,task_memcg=/,task=polkitd,pid=268,uid=998
[   31.910012] Out of memory: Killed process 268 (polkitd)
total-vm:72804kB, anon-rss:2948kB, file-rss:7568kB, shmem-rss:0kB,
UID:998 pgtables:80kB oom_score_adj:0
[   31.927948] oom_reaper: reaped process 268 (polkitd), now
anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
[   31.937461] mkfs.ext4 invoked oom-killer:
gfp_mask=0x101cc0(GFP_USER|__GFP_WRITE), order=0, oom_score_adj=0
[   31.947273] CPU: 1 PID: 397 Comm: mkfs.ext4 Not tainted
5.7.0-rc6-next-20200518 #1
[   31.954871] Hardware name: Generic DRA74X (Flattened Device Tree)
[   31.961000] [<c0411500>] (unwind_backtrace) from [<c040b66c>]
(show_stack+0x10/0x14)
[   31.968778] [<c040b66c>] (show_stack) from [<c08b1b14>]
(dump_stack+0xc4/0xd8)
[   31.976032] [<c08b1b14>] (dump_stack) from [<c0547bf8>]
(dump_header+0x54/0x1ec)
[   31.983458] [<c0547bf8>] (dump_header) from [<c0547008>]
(oom_kill_process+0x18c/0x198)
[   31.991495] [<c0547008>] (oom_kill_process) from [<c0547a0c>]
(out_of_memory+0x250/0x368)
[   31.999706] [<c0547a0c>] (out_of_memory) from [<c0599d80>]
(__alloc_pages_nodemask+0xce8/0x10bc)
[   32.008532] [<c0599d80>] (__alloc_pages_nodemask) from [<c0541bb4>]
(pagecache_get_page+0x128/0x358)
[   32.017704] [<c0541bb4>] (pagecache_get_page) from [<c0543a8c>]
(grab_cache_page_write_begin+0x18/0x2c)
[   32.027138] [<c0543a8c>] (grab_cache_page_write_begin) from
[<c0619fb0>] (block_write_begin+0x20/0xc4)
[   32.036484] [<c0619fb0>] (block_write_begin) from [<c053e718>]
(generic_perform_write+0xb8/0x1d8)
[   32.045395] [<c053e718>] (generic_perform_write) from [<c054496c>]
(__generic_file_write_iter+0x164/0x1ec)
[   32.055090] [<c054496c>] (__generic_file_write_iter) from
[<c061c8a4>] (blkdev_write_iter+0xc8/0x1a4)
[   32.064350] [<c061c8a4>] (blkdev_write_iter) from [<c05d50d0>]
(__vfs_write+0x13c/0x1cc)
[   32.072476] [<c05d50d0>] (__vfs_write) from [<c05d81d4>]
(vfs_write+0xb0/0x1bc)
[   32.079814] [<c05d81d4>] (vfs_write) from [<c05d85e4>]
(ksys_pwrite64+0x60/0x8c)
[   32.087241] [<c05d85e4>] (ksys_pwrite64) from [<c04001a0>]
(ret_fast_syscall+0x0/0x4c)
[   32.095187] Exception stack(0xe810dfa8 to 0xe810dff0)
[   32.100256] dfa0:                   a2000000 0000000d 00000003
b6952008 00400000 00000000
[   32.108466] dfc0: a2000000 0000000d a2000000 000000b5 00400000
0003b768 b6952008 00da2000
[   32.116673] dfe0: 00000064 beb891b8 b6f85108 b6e38f2c
[   32.121786] Mem-Info:
[   32.124070] active_anon:5056 inactive_anon:4129 isolated_anon:0
[   32.124070]  active_file:6289 inactive_file:118790 isolated_file:0
[   32.124070]  unevictable:0 dirty:14118 writeback:6 unstable:0
[   32.124070]  slab_reclaimable:5653 slab_unreclaimable:4209
[   32.124070]  mapped:4839 shmem:4468 pagetables:165 bounce:0
[   32.124070]  free:348249 free_pcp:562 free_cma:57235
[   32.158031] Node 0 active_anon:20224kB inactive_anon:16516kB
active_file:25156kB inactive_file:475160kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB mapped:19356kB dirty:56472kB
writeback:24kB shmem:17872kB shmem_thp: 0kB shmem_pmdmapped: 0kB
anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[   32.186324] DMA free:186320kB min:22528kB low:28160kB high:33792kB
reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB
active_file:4736kB inactive_file:433580kB unevictable:0kB
writepending:56468kB present:783360kB managed:668264kB mlocked:0kB
kernel_stack:888kB pagetables:0kB bounce:0kB free_pcp:420kB
local_pcp:220kB free_cma:163840kB
[   32.216693] lowmem_reserve[]: 0 0 1216 0
[   32.220652] HighMem free:1206676kB min:512kB low:11592kB
high:22672kB reserved_highatomic:0KB active_anon:20224kB
inactive_anon:16516kB active_file:20420kB inactive_file:41584kB
unevictable:0kB writepending:0kB present:1310720kB managed:1310720kB
mlocked:0kB kernel_stack:0kB pagetables:660kB bounce:0kB
free_pcp:1816kB local_pcp:340kB free_cma:65100kB
[   32.251805] lowmem_reserve[]: 0 0 0 0
[   32.255482] DMA: 2*4kB (UM) 3*8kB (UME) 1*16kB (U) 1*32kB (M)
0*64kB 1*128kB (U) 5*256kB (ME) 5*512kB (ME) 4*1024kB (ME) 5*2048kB
(M) 1*4096kB (M) 20*8192kB (C) = 186320kB
[   32.270871] HighMem: 183*4kB (UMC) 65*8kB (UMC) 21*16kB (M) 11*32kB
(UM) 6*64kB (UMC) 3*128kB (UM) 3*256kB (UM) 2*512kB (MC) 2*1024kB (MC)
2*2048kB (MC) 2*4096kB (UC) 145*8192kB (MC) = 1206676kB
[   32.288273] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=2048kB
[   32.296751] 129546 total pagecache pages
[   32.300695] 0 pages in swap cache
[   32.304019] Swap cache stats: add 0, delete 0, find 0/0
[   32.309260] Free swap  = 0kB
[   32.312155] Total swap = 0kB
[   32.315045] 523520 pages RAM
[   32.317932] 327680 pages HighMem/MovableOnly
[   32.322221] 28774 pages reserved
[   32.325457] 57344 pages cma reserved
[   32.329043] Tasks state (memory values in pages):
[   32.333771] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes
swapents oom_score_adj name
[   32.342436] [    183]     0   183     7370     1082    36864
0             0 systemd-journal
[   32.351529] [    209]   994   209     3742      326    40960
0             0 systemd-timesyn
[   32.360620] [    217]     0   217     3398      817    32768
0         -1000 systemd-udevd
[   32.369528] [    230]   993   230     1411      737    32768
0             0 systemd-network
[   32.378620] [    231]   992   231     1496      712    32768
0             0 systemd-resolve
[   32.387713] [    236]   996   236     1112      742    24576
0          -900 dbus-daemon
[   32.396456] [    241]     0   241     1895     1045    36864
0             0 haveged
[   32.404850] [    242]     0   242     1362      906    28672
0             0 systemd-logind
[   32.413852] [    243]     0   243    13412     2571    69632
0             0 NetworkManager
[   32.422858] [    244]   995   244     1197      608    28672
0             0 avahi-daemon
[   32.431687] [    245]   995   245     1164       59    28672
0             0 avahi-daemon
[   32.440518] [    246]     0   246      594      332    28672
0             0 atd
[   32.448553] [    248]     0   248      699       99    24576
0             0 syslogd
[   32.456945] [    251]     0   251      699      102    24576
0             0 klogd
[   32.465171] [    252]     0   252      676      365    24576
0             0 crond
[   32.473390] [    254]     0   254     1172      240    32768
0             0 systemd-hostnam
[   32.482481] [    264] 65534   264      605       32    24576
0             0 dnsmasq
[   32.490876] [    265]     0   265      556      357    28672
0             0 agetty
[   32.499175] [    266]     0   266     1131      613    32768
0             0 login
[   32.507394] [    350]     0   350     1840     1161    32768
0             0 systemd
[   32.515788] [    351]     0   351     2403      473    36864
0             0 (sd-pam)
[   32.524268] [    355]     0   355      827      611    24576
0             0 sh
[   32.532227] [    364]     0   364     7341     1145    53248
0             0 nm-dispatcher
[   32.541142] [    377]     0   377      711      510    28672
0             0 lava-test-runne
[   32.550234] [    387]     0   387      711      138    20480
0             0 lava-test-shell
[   32.559316] [    388]     0   388      711      523    20480
0             0 sh
[   32.567273] [    397]     0   397     1785     1518    36864
0             0 mkfs.ext4

ref:
https://lkft.validation.linaro.org/scheduler/job/1436647#L4261
https://lkft.validation.linaro.org/scheduler/job/1436562#L1247

--
Linaro LKFT
https://lkft.linaro.org