View Issue Details

IDProjectCategoryView StatusLast Update
0016905CentOS-7kernelpublic2020-01-13 13:49
Reporterdmt6823 
PrioritynormalSeveritymajorReproducibilityN/A
Status newResolutionopen 
PlatformLinuxOSCentOSOS Version7.7
Product Version7.7-1908 
Target VersionFixed in Version 
Summary0016905: Processes end up in infinite loop in xfs driver (xfs_iomap_write_allocate)
DescriptionKernel: 3.10.0-1062.9.1.el7.x86_64

We are seeing multiple processes stuck consuming 100% CPU being uninterruptable, looking at the stack they all seem to be in the xfs_iomap_write_allocate function:

# top
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 9466 root 16 -4 55528 1076 632 S 100,3 0,0 961:54.44 auditd
31420 1001 20 0 383324 171028 1056 R 100,0 0,1 992:25.62 git
36110 root 39 19 123164 4588 1856 R 100,0 0,0 5124101h mandb
25368 root 20 0 0 0 0 R 99,7 0,0 1015:42 kworker/u97:0
35145 root 20 0 572508 240248 5780 R 99,7 0,1 963:46.56 puppet

# for p in 9466 31420 36110 25368 35145; do echo -----------------; ps -o pid,lstart,cmd -p $p; cat /proc/$p/stack; done
-----------------
  PID STARTED CMD
 9466 Mon Dec 9 16:54:51 2019 /sbin/auditd
[<ffffffffb6a98e7e>] ep_poll+0x23e/0x360
[<ffffffffb6a9a34d>] SyS_epoll_wait+0xed/0x120
[<ffffffffb6f8dede>] system_call_fastpath+0x25/0x2a
[<ffffffffffffffff>] 0xffffffffffffffff
-----------------
  PID STARTED CMD
31420 Tue Jan 7 16:18:08 2020 git index-pack --stdin --fix-thin --keep=fetch-pack 3715 on runner-E2XVjs-E-project-6131-concurrent-0
[<ffffffffc08af8b2>] xfs_iomap_write_allocate+0x182/0x380 [xfs]
[<ffffffffc0899166>] xfs_map_blocks+0x1a6/0x220 [xfs]
[<ffffffffc089a1a4>] xfs_do_writepage+0x174/0x550 [xfs]
[<ffffffffb69c9b7c>] write_cache_pages+0x21c/0x470
[<ffffffffc0899ffb>] xfs_vm_writepages+0x6b/0xa0 [xfs]
[<ffffffffb69cabc1>] do_writepages+0x21/0x50
[<ffffffffb69bee55>] __filemap_fdatawrite_range+0x65/0x80
[<ffffffffb69befa1>] filemap_write_and_wait_range+0x41/0x90
[<ffffffffc08a49a6>] xfs_file_fsync+0x66/0x1c0 [xfs]
[<ffffffffb6a7fb77>] do_fsync+0x67/0xb0
[<ffffffffb6a7fe60>] SyS_fsync+0x10/0x20
[<ffffffffb6f8e172>] tracesys+0xa6/0xcc
[<ffffffffffffffff>] 0xffffffffffffffff
-----------------
  PID STARTED CMD
36110 Wed Jan 8 03:45:01 2020 mandb -q
[<ffffffffc08af8b2>] xfs_iomap_write_allocate+0x182/0x380 [xfs]
[<ffffffffc0899166>] xfs_map_blocks+0x1a6/0x220 [xfs]
[<ffffffffc089a1a4>] xfs_do_writepage+0x174/0x550 [xfs]
[<ffffffffb69c9b7c>] write_cache_pages+0x21c/0x470
[<ffffffffc0899ffb>] xfs_vm_writepages+0x6b/0xa0 [xfs]
[<ffffffffb69cabc1>] do_writepages+0x21/0x50
[<ffffffffb69bee55>] __filemap_fdatawrite_range+0x65/0x80
[<ffffffffb69befa1>] filemap_write_and_wait_range+0x41/0x90
[<ffffffffc08a49a6>] xfs_file_fsync+0x66/0x1c0 [xfs]
[<ffffffffb6a7f930>] vfs_fsync_range+0x20/0x30
[<ffffffffb69fe52e>] SyS_msync+0x1fe/0x250
[<ffffffffb6f8dede>] system_call_fastpath+0x25/0x2a
[<ffffffffffffffff>] 0xffffffffffffffff
-----------------
  PID STARTED CMD
25368 Wed Dec 18 09:20:15 2019 [kworker/u97:0]
[<ffffffffffffffff>] 0xffffffffffffffff
-----------------
  PID STARTED CMD
35145 Tue Jan 7 17:09:20 2020 puppet agent: applying configuration
[<ffffffffc08af8b2>] xfs_iomap_write_allocate+0x182/0x380 [xfs]
[<ffffffffc0899166>] xfs_map_blocks+0x1a6/0x220 [xfs]
[<ffffffffc089a1a4>] xfs_do_writepage+0x174/0x550 [xfs]
[<ffffffffb69c9b7c>] write_cache_pages+0x21c/0x470
[<ffffffffc0899ffb>] xfs_vm_writepages+0x6b/0xa0 [xfs]
[<ffffffffb69cabc1>] do_writepages+0x21/0x50
[<ffffffffb69bee55>] __filemap_fdatawrite_range+0x65/0x80
[<ffffffffb69befa1>] filemap_write_and_wait_range+0x41/0x90
[<ffffffffc08a49a6>] xfs_file_fsync+0x66/0x1c0 [xfs]
[<ffffffffb6a7fb77>] do_fsync+0x67/0xb0
[<ffffffffb6a7fe60>] SyS_fsync+0x10/0x20
[<ffffffffb6f8dede>] system_call_fastpath+0x25/0x2a
[<ffffffffffffffff>] 0xffffffffffffffff
 
#### the affected filesystem also reports unreasonable free disk space:
# df
Filesystem 1K-blocks Used Available Use% Mounted on
devtmpfs 131805120 0 131805120 0% /dev
tmpfs 131817608 0 131817608 0% /dev/shm
tmpfs 131817608 313232 131504376 1% /run
tmpfs 131817608 0 131817608 0% /sys/fs/cgroup
/dev/mapper/vgroot-lvroot 5134336 2121364 3012972 42% /
/dev/sda1 999320 302600 627908 33% /boot
/dev/mapper/vgroot-lvvar 51271680 -17124254560 17175526240 - /var
/dev/mapper/vgroot-lvtmp 1038336 33408 1004928 4% /tmp
overlay 51271680 -17124254560 17175526240 - /var/lib/docker/overlay2/f1123f68f92f26f242aa88148c84faaaffdd058af58dda0efb856127748e64ba/merged
overlay 51271680 -17124254560 17175526240 - /var/lib/docker/overlay2/b4092a6efa1f516f6c694f269296c394549a8996aa5d04121b8e9be24dc6099d/merged
shm 65536 0 65536 0% /var/lib/docker/containers/1297eedb2c2e0c4b777f9771ea1c57afa418145feb31b9f31c1c5dc250d44f5f/mounts/shm
tmpfs 26363524 0 26363524 0% /run/user/0
tmpfs 26363524 0 26363524 0% /run/user/127470

there is also some output in the kernel logs (repeated multiple times):

2020-01-07T18:09:05.892210+01:00 <hostname> kernel: INFO: task dockerd:10963 blocked for more than 120 seconds.
2020-01-07T18:09:05.892271+01:00 <hostname> kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
2020-01-07T18:09:05.892314+01:00 <hostname> kernel: dockerd D ffff8d1d7f91ac80 0 10963 1 0x00000080
2020-01-07T18:09:05.892341+01:00 <hostname> kernel: Call Trace:
2020-01-07T18:09:05.892369+01:00 <hostname> kernel: [<ffffffffb6f80a09>] schedule+0x29/0x70
2020-01-07T18:09:05.892393+01:00 <hostname> kernel: [<ffffffffb6f7e511>] schedule_timeout+0x221/0x2d0
2020-01-07T18:09:05.892417+01:00 <hostname> kernel: [<ffffffffb68bc16c>] ? __queue_work+0x13c/0x3f0
2020-01-07T18:09:05.892449+01:00 <hostname> kernel: [<ffffffffb68bc51a>] ? __queue_delayed_work+0xaa/0x1a0
2020-01-07T18:09:05.892474+01:00 <hostname> kernel: [<ffffffffb68bc881>] ? try_to_grab_pending+0xb1/0x160
2020-01-07T18:09:05.892499+01:00 <hostname> kernel: [<ffffffffb6f80dbd>] wait_for_completion+0xfd/0x140
2020-01-07T18:09:05.892523+01:00 <hostname> kernel: [<ffffffffb68db4c0>] ? wake_up_state+0x20/0x20
2020-01-07T18:09:05.892547+01:00 <hostname> kernel: [<ffffffffb6a79e80>] writeback_inodes_sb_nr+0x90/0xd0
2020-01-07T18:09:05.892572+01:00 <hostname> kernel: [<ffffffffb6a79ee5>] writeback_inodes_sb+0x25/0x30
2020-01-07T18:09:05.892596+01:00 <hostname> kernel: [<ffffffffb6a7fc25>] sync_filesystem+0x35/0xb0
2020-01-07T18:09:05.892619+01:00 <hostname> kernel: [<ffffffffc070f2d0>] ovl_sync_fs+0x40/0x60 [overlay]
2020-01-07T18:09:05.892644+01:00 <hostname> kernel: [<ffffffffb6a7fc70>] sync_filesystem+0x80/0xb0
2020-01-07T18:09:05.892674+01:00 <hostname> kernel: [<ffffffffb6a4d257>] generic_shutdown_super+0x27/0x100
2020-01-07T18:09:05.892705+01:00 <hostname> kernel: [<ffffffffb6a4d6a2>] kill_anon_super+0x12/0x20
2020-01-07T18:09:05.892729+01:00 <hostname> kernel: [<ffffffffb6a4da7e>] deactivate_locked_super+0x4e/0x70
2020-01-07T18:09:05.892753+01:00 <hostname> kernel: [<ffffffffb6a4e206>] deactivate_super+0x46/0x60
2020-01-07T18:09:05.892782+01:00 <hostname> kernel: [<ffffffffb6a6cd7f>] cleanup_mnt+0x3f/0x80
2020-01-07T18:09:05.892811+01:00 <hostname> kernel: [<ffffffffb6a6ce12>] __cleanup_mnt+0x12/0x20
2020-01-07T18:09:05.892840+01:00 <hostname> kernel: [<ffffffffb68c2d2b>] task_work_run+0xbb/0xe0
2020-01-07T18:09:05.892868+01:00 <hostname> kernel: [<ffffffffb682cc65>] do_notify_resume+0xa5/0xc0
2020-01-07T18:09:05.892893+01:00 <hostname> kernel: [<ffffffffb6f8e23b>] int_signal+0x12/0x17

doing some sampling on the stack of one of the processes:

# for x in $(seq 1 100000); do cat /proc/36110/stack|head -n 1; done|sort|uniq -c > tmpfile
# cat tmpfile
      7 [<ffffffffc08af843>] xfs_iomap_write_allocate+0x113/0x380 [xfs]
  96773 [<ffffffffc08af8b2>] xfs_iomap_write_allocate+0x182/0x380 [xfs]
     13 [<ffffffffc08af8c6>] xfs_iomap_write_allocate+0x196/0x380 [xfs]
    489 [<ffffffffc08af8d7>] xfs_iomap_write_allocate+0x1a7/0x380 [xfs]
     12 [<ffffffffc08af8ec>] xfs_iomap_write_allocate+0x1bc/0x380 [xfs]
    196 [<ffffffffc08af922>] xfs_iomap_write_allocate+0x1f2/0x380 [xfs]
      4 [<ffffffffc08af937>] xfs_iomap_write_allocate+0x207/0x380 [xfs]
     12 [<ffffffffc08af945>] xfs_iomap_write_allocate+0x215/0x380 [xfs]
      3 [<ffffffffc08af958>] xfs_iomap_write_allocate+0x228/0x380 [xfs]
   2491 [<ffffffffffffffff>] 0xffffffffffffffff

extracting the line numbers from the kernel xfs module:

# cat tmpfile | cut -d ']' -f 2 | cut -d '/' -f 1 | while read x; do echo "list *($x)"; done | gdb /usr/lib/debug/usr/lib/modules/3.10.0-1062.9.1.el7.x86_64/kernel/fs/xfs/xfs.ko.debug | grep ' is in xfs'
 
(gdb) 0x5a873 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:773).
(gdb) 0x5a8e2 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:793).
(gdb) 0x5a8f6 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:797).
(gdb) 0x5a907 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:801).
(gdb) 0x5a91c is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:720).
(gdb) 0x5a952 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:730).
(gdb) 0x5a967 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:734).
(gdb) 0x5a975 is in xfs_iomap_write_allocate (fs/xfs/xfs_iomap.c:736).
(gdb) 0x5a988 is in xfs_iomap_write_allocate (fs/xfs/xfs_inode.h:94).

Doing a core dump unfortunately failed to write the dump, after booting again the xfs filesystem is corrupted.
Any idea what might be the root cause here?
Steps To ReproduceHappened just once now.
Tagskernel, xfs
abrt_hash
URL

Activities

dmt6823

dmt6823

2020-01-13 13:49

reporter   ~0036013

Error message after rebooting:

XFS (dm-3): Internal error xfs_trans_cancel at line 984 of file fs/xfs/xfs_trans.c. Caller xfs_create+0x46f/0x6a0 [xfs]
XFS (dm-3): Corruption of in-memory data detected. Shutting down filesystem
XFS (dm-3): writeback error on sector 136740
XFS (dm-3): Please umount the filesystem and rectify the problem(s)

After repairing the xfs in a recovery image now we see the partition has no space left on the device.

Looking at the monitoring data for this filesystem it turns out the strange capacity readings where introduced a few weeks earlier when a build process on the server was running (running in docker with the overlay2 filesystem driver on the filesystem in question).

Looking at the actual files on the filesystem it seems reasonable, that the filesystem was slowly filling up (undetected by monitoring, as the capacity was reported incorrectly) and when the FS was actually out of space this triggered the infinite loop in the next xfs_iomap_write_allocate call. Besides it was still possible to create empty files (with touch) though.

Issue History

Date Modified Username Field Change
2020-01-09 13:00 dmt6823 New Issue
2020-01-09 13:00 dmt6823 Tag Attached: kernel
2020-01-09 13:00 dmt6823 Tag Attached: xfs
2020-01-13 13:49 dmt6823 Note Added: 0036013