2020-05-01 12:39:31

by Naresh Kamboju

[permalink] [raw]
Subject: mm: mkfs.ext4 invoked oom-killer on i386 - pagecache_get_page

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.

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)
---------------------------
mkfs -t ext4 <external-STORAGE_DEV>

Test log:
------------
+ mkfs -t ext4 /dev/disk/by-id/ata-TOSHIBA_MG04ACA100N_Y8RQK14KF6XF
mke2fs 1.43.8 (1-Jan-2018)
Creating filesystem with 244190646 4k blocks and 61054976 inodes
Filesystem UUID: 05e8451c-1dd6-4d94-b030-0f806653e4b4
Superblock backups stored on blocks:
32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208,
4096000, 7962624, 11239424, 20480000, 23887872, 71663616, 78675968,
102400000, 214990848
Allocating group tables: 0/7453 done
Writing inode tables: 0/7453 done
Creating journal (262144 blocks): [ 34.739137] mkfs.ext4 invoked
oom-killer: gfp_mask=0x101cc0(GFP_USER|__GFP_WRITE), order=0,
oom_score_adj=0
[ 34.748889] CPU: 0 PID: 393 Comm: mkfs.ext4 Not tainted
5.7.0-rc3-next-20200430 #1
[ 34.756450] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 34.763844] Call Trace:
[ 34.766305] dump_stack+0x54/0x6e
[ 34.769629] dump_header+0x3d/0x1c6
[ 34.773126] ? oom_badness.part.0+0x10/0x120
[ 34.777397] ? ___ratelimit+0x8f/0xdc
[ 34.781056] oom_kill_process.cold+0x9/0xe
[ 34.785152] out_of_memory+0x1ab/0x260
[ 34.788898] __alloc_pages_nodemask+0xe0e/0xec0
[ 34.793430] pagecache_get_page+0xae/0x260
[ 34.797521] grab_cache_page_write_begin+0x1c/0x30
[ 34.802303] block_write_begin+0x1e/0x90
[ 34.806222] blkdev_write_begin+0x1e/0x20
[ 34.810225] ? bdev_evict_inode+0xd0/0xd0
[ 34.814230] generic_perform_write+0x97/0x180
[ 34.818579] __generic_file_write_iter+0x140/0x1f0
[ 34.823365] blkdev_write_iter+0xc0/0x190
[ 34.827376] __vfs_write+0x132/0x1e0
[ 34.830947] ? __audit_syscall_entry+0xa8/0xe0
[ 34.835385] vfs_write+0xa1/0x1a0
[ 34.838696] ksys_pwrite64+0x50/0x80
[ 34.842267] __ia32_sys_ia32_pwrite64+0x16/0x20
[ 34.846798] do_fast_syscall_32+0x6b/0x270
[ 34.850890] entry_SYSENTER_32+0xa5/0xf8
[ 34.854805] EIP: 0xb7f0d549
[ 34.857596] Code: 03 74 c0 01 10 05 03 74 b8 01 10 06 03 74 b4 01
10 07 03 74 b0 01 10 08 03 74 d8 01 00 00 00 00 00 51 52 55 89 e5 0f
34 cd 80 <5d> 5a 59 c3 90 90 90 90 8d 76 00 58 b8 77 00 00 00 cd 80 90
8d 76
[ 34.876334] EAX: ffffffda EBX: 00000003 ECX: b7801010 EDX: 00400000
[ 34.882591] ESI: 38400000 EDI: 00000074 EBP: 07438400 ESP: bfd266f0
[ 34.888847] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00000246
[ 34.895630] Mem-Info:
[ 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.897923] slab_reclaimable:5855 slab_unreclaimable:3531
[ 34.897923] mapped:6321 shmem:2236 pagetables:178 bounce:0
[ 34.897923] free:264202 free_pcp:1082 free_cma:0
[ 34.931663] Node 0 active_anon:21464kB inactive_anon:8688kB
active_file:16604kB inactive_file:849976kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB mapped:25284kB dirty:58952kB
writeback:27772kB shmem:8944kB writeback_tmp:0kB unstable:0kB
all_unreclaimable? yes
[ 34.955523] DMA free:3356kB min:68kB low:84kB high:100kB
reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB
active_file:0kB inactive_file:11964kB unevictable:0kB
writepending:11980kB present:15964kB managed:15876kB mlocked:0kB
kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB
free_cma:0kB
[ 34.983385] lowmem_reserve[]: 0 825 1947 825
[ 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
[ 35.017427] lowmem_reserve[]: 0 0 8980 0
[ 35.021362] HighMem free:1049496kB min:512kB low:1748kB high:2984kB
reserved_highatomic:0KB active_anon:21464kB inactive_anon:8688kB
active_file:15508kB inactive_file:51612kB unevictable:0kB
writepending:0kB present:1149540kB managed:1149540kB mlocked:0kB
kernel_stack:0kB pagetables:712kB bounce:0kB free_pcp:1524kB
local_pcp:292kB free_cma:0kB
[ 35.051717] lowmem_reserve[]: 0 0 0 0
[ 35.055374] DMA: 8*4kB (UE) 1*8kB (E) 1*16kB (E) 0*32kB 0*64kB
0*128kB 1*256kB (E) 0*512kB 1*1024kB (E) 1*2048kB (E) 0*4096kB =
3384kB
[ 35.067446] Normal: 27*4kB (U) 23*8kB (U) 12*16kB (UE) 12*32kB (U)
4*64kB (UE) 2*128kB (U) 2*256kB (UE) 1*512kB (E) 0*1024kB 1*2048kB (U)
0*4096kB = 4452kB
[ 35.081347] HighMem: 2*4kB (UM) 0*8kB 1*16kB (M) 2*32kB (UM) 1*64kB
(U) 0*128kB 1*256kB (M) 1*512kB (M) 0*1024kB 0*2048kB 256*4096kB (M) =
1049496kB
[ 35.094634] Node 0 hugepages_total=0 hugepages_free=0
hugepages_surp=0 hugepages_size=4096kB
[ 35.103059] 218892 total pagecache pages
[ 35.106985] 0 pages in swap cache
[ 35.110303] Swap cache stats: add 0, delete 0, find 0/0
[ 35.115519] Free swap = 0kB
[ 35.118396] Total swap = 0kB
[ 35.121274] 512558 pages RAM
[ 35.124151] 287385 pages HighMem/MovableOnly
[ 35.128418] 9810 pages reserved
[ 35.131563] Tasks state (memory values in pages):
[ 35.136260] [ pid ] uid tgid total_vm rss pgtables_bytes
swapents oom_score_adj name
[ 35.144866] [ 224] 0 224 3425 1273 28672
0 0 systemd-journal
[ 35.153932] [ 241] 0 241 3260 828 20480
0 -1000 systemd-udevd
[ 35.162797] [ 244] 994 244 3929 456 24576
0 0 systemd-timesyn
[ 35.171837] [ 277] 993 277 1569 786 20480
0 0 systemd-network
[ 35.180891] [ 279] 992 279 1729 825 20480
0 0 systemd-resolve
[ 35.189948] [ 283] 0 283 2032 1087 24576
0 0 haveged
[ 35.198312] [ 284] 0 284 810 457 16384
0 0 crond
[ 35.206485] [ 285] 996 285 1175 812 20480
0 -900 dbus-daemon
[ 35.215177] [ 286] 0 286 11786 2558 49152
0 0 NetworkManager
[ 35.224121] [ 287] 0 287 922 174 12288
0 0 klogd
[ 35.232293] [ 288] 0 288 1468 1001 20480
0 0 systemd-logind
[ 35.241247] [ 289] 995 289 1213 791 20480
0 0 avahi-daemon
[ 35.250026] [ 290] 0 290 677 435 16384
0 0 atd
[ 35.258040] [ 302] 0 302 921 420 16384
0 0 syslogd
[ 35.266380] [ 303] 0 303 5638 1558 32768
0 0 thermald
[ 35.274828] [ 305] 995 305 1182 58 20480
0 0 avahi-daemon
[ 35.283659] [ 306] 0 306 594 16 16384
0 0 acpid
[ 35.291848] [ 320] 0 320 1347 334 20480
0 0 systemd-hostnam
[ 35.300906] [ 336] 65534 336 729 32 16384
0 0 dnsmasq
[ 35.309253] [ 337] 0 337 666 443 16384
0 0 agetty
[ 35.317528] [ 338] 0 338 947 710 16384
0 0 login
[ 35.325693] [ 339] 0 339 666 458 16384
0 0 agetty
[ 35.333994] [ 350] 998 350 19521 2816 73728
0 0 polkitd
[ 35.342330] [ 358] 0 358 1892 1149 20480
0 0 systemd
[ 35.350668] [ 359] 0 359 2341 329 20480
0 0 (sd-pam)
[ 35.359093] [ 363] 0 363 971 711 16384
0 0 sh
[ 35.367023] [ 367] 0 367 920 627 20480
0 0 su
[ 35.374937] [ 368] 0 368 971 668 16384
0 0 sh
[ 35.382864] [ 373] 0 373 903 613 16384
0 0 lava-test-runne
[ 35.391897] [ 383] 0 383 903 518 16384
0 0 lava-test-shell
[ 35.400935] [ 384] 0 384 903 612 16384
0 0 sh
[ 35.408847] [ 393] 0 393 1976 1713 20480
0 0 mkfs.ext4
[ 35.417384] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=polkitd,pid=350,uid=998
[ 35.429982] Out of memory: Killed process 350 (polkitd)
total-vm:78084kB, anon-rss:2976kB, file-rss:8288kB, shmem-rss:0kB,
UID:998 pgtables:72kB oom_score_adj:0
[ 35.444646] oom_reaper: reaped process 350 (polkitd), now
anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
[ 35.444648] mkfs.ext4 invoked oom-killer:
gfp_mask=0x101cc0(GFP_USER|__GFP_WRITE), order=0, oom_score_adj=0
[ 35.463429] CPU: 0 PID: 393 Comm: mkfs.ext4 Not tainted
5.7.0-rc3-next-20200430 #1
[ 35.470991] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018
[ 35.478377] Call Trace:
[ 35.480822] dump_stack+0x54/0x6e
[ 35.484139] dump_header+0x3d/0x1c6
[ 35.487634] ? oom_badness.part.0+0x10/0x120
[ 35.491922] ? ___ratelimit+0x8f/0xdc
[ 35.495578] oom_kill_process.cold+0x9/0xe
[ 35.499669] out_of_memory+0x1ab/0x260
[ 35.503414] __alloc_pages_nodemask+0xe0e/0xec0
[ 35.507939] pagecache_get_page+0xae/0x260

Git log from recent changes on fs and mm.

# fs$ git log --oneline ext4 | head
5868dada23f7 ext4: pass the inode to ext4_mpage_readpages
0c855f1fc999 ext4: convert from readpages to readahead
ebc0198b60e9 mm: add page_cache_readahead_unbounded
907ea529fc4c ext4: convert BUG_ON's to WARN_ON's in mballoc.c
a17a9d935dc4 ext4: increase wait time needed before reuse of deleted
inode numbers
648814111af2 ext4: remove set but not used variable 'es' in ext4_jbd2.c
05ca87c149ae ext4: remove set but not used variable 'es'
801674f34ecf ext4: do not zeroout extents beyond i_disksize
9033783c8cfd ext4: fix return-value types in several function comments
d87f639258a6 ext4: use non-movable memory for superblock readahead

# fs/f2fs$ git log --oneline . | head
a4928e314c45 Merge branch 'akpm-current/current'
f1c6758147a8 f2fs: pass the inode to f2fs_mpage_readpages
272e45338126 f2fs: convert from readpages to readahead
ebc0198b60e9 mm: add page_cache_readahead_unbounded
435cbab95e39 f2fs: fix quota_sync failure due to f2fs_lock_op
8b83ac81f428 f2fs: support read iostat
df4233997575 f2fs: Fix the accounting of dcc->undiscard_blks
ce4c638cdd52 f2fs: fix to handle error path of f2fs_ra_meta_pages()
3fa6a8c5b55d f2fs: report the discard cmd errors properly
141af6ba5216 f2fs: fix long latency due to discard during umount

# fs$ git log --oneline ext4 | head
5868dada23f7 ext4: pass the inode to ext4_mpage_readpages
0c855f1fc999 ext4: convert from readpages to readahead
ebc0198b60e9 mm: add page_cache_readahead_unbounded
907ea529fc4c ext4: convert BUG_ON's to WARN_ON's in mballoc.c
a17a9d935dc4 ext4: increase wait time needed before reuse of deleted
inode numbers
648814111af2 ext4: remove set but not used variable 'es' in ext4_jbd2.c
05ca87c149ae ext4: remove set but not used variable 'es'
801674f34ecf ext4: do not zeroout extents beyond i_disksize
9033783c8cfd ext4: fix return-value types in several function comments
d87f639258a6 ext4: use non-movable memory for superblock readahead

Test full log link,
https://lkft.validation.linaro.org/scheduler/job/1406110#L1223
https://lkft.validation.linaro.org/scheduler/job/1408508#L1250

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


2020-05-01 20:59:55

by Andrew Morton

[permalink] [raw]
Subject: Re: mm: mkfs.ext4 invoked oom-killer on i386 - pagecache_get_page

On Fri, 1 May 2020 18:08:28 +0530 Naresh Kamboju <[email protected]> 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.

> 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.