[vfs] WARNING: CPU: 3 PID: 2339 at mm/truncate.c:758 pagecache_isize_extended+0xdd/0x120()

[Jan Kara]

Hi Jan,
Your patch gives a warning on the xfs code path. :)
git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4.git dev
commit be330474e2d0533a7a6185e567f3654fec096dbd ("vfs: fix data corruption when blocksize < pagesize for mmaped data")

...

<5>[ 25.956576] XFS (sda1): Mounting V4 Filesystem
<6>[ 26.194468] XFS (sda1): Ending clean mount
<4>[ 27.258450] ------------[ cut here ]------------
<4>[ 27.258789] WARNING: CPU: 3 PID: 2339 at mm/truncate.c:758 pagecache_isize_extended+0xdd/0x120()

Ah, I believe this is:
WARN_ON(!mutex_is_locked(&inode->i_mutex));
because XFS doesn't use i_mutex but its private rwlock. I forgot to check
dmesg after running xfstests for XFS and didn't notice this. Anyway, the
solution is to just remove the assertion since it doesn't hold for all
filesystems. Patch for that is attached. Thanks Fengguang for catching
this.

Honza

<4>[ 27.259443] Modules linked in: ipmi_watchdog ipmi_msghandler btrfs xor raid6_pq sg sr_mod cdrom sd_mod firewire_ohci firewire_core crc_itu_t snd_hda_codec_realtek pcspkr snd_hda_codec_generic ahci libahci libata snd_hda_intel i2c_i801 snd_hda_controller parport_pc parport snd_hda_codec snd_hwdep snd_pcm snd_timer shpchp snd x38_edac edac_core soundcore acpi_cpufreq
<4>[ 27.262734] CPU: 3 PID: 2339 Comm: fallocate Not tainted 3.17.0-gda9a9f1 #1
<4>[ 27.263153] Hardware name: / , BIOS VVRBLI9J.86A.2891.2007.0511.1144 05/11/2007
<4>[ 27.263780] 0000000000000009 ffff88007a43fd88 ffffffff81859ea6 0000000000000000
<4>[ 27.264492] ffff88007a43fdc0 ffffffff8106ef0d 0000000000001000 ffff88005b6f05a8
<4>[ 27.265199] 0000000000000000 ffff88005b6f05a8 0000000004000000 ffff88007a43fdd0
<4>[ 27.266165] [<ffffffff81859ea6>] dump_stack+0x4d/0x66
<4>[ 27.266511] [<ffffffff8106ef0d>] warn_slowpath_common+0x7d/0xa0
<4>[ 27.266900] [<ffffffff8106efea>] warn_slowpath_null+0x1a/0x20
<4>[ 27.267286] [<ffffffff8117020d>] pagecache_isize_extended+0xdd/0x120
<4>[ 27.267690] [<ffffffff811712b7>] truncate_setsize+0x27/0x40
<4>[ 27.268068] [<ffffffff8133eab7>] xfs_setattr_size+0x157/0x3a0
<4>[ 27.268442] [<ffffffff8134c827>] ? xfs_trans_commit+0x157/0x250
<4>[ 27.268821] [<ffffffff813336df>] xfs_file_fallocate+0x2df/0x300
<4>[ 27.269215] [<ffffffff811dbb09>] ? __sb_start_write+0x49/0xf0
<4>[ 27.269596] [<ffffffff813923b4>] ? selinux_file_permission+0xc4/0x120
<4>[ 27.270009] [<ffffffff811d7563>] do_fallocate+0x123/0x1b0
<4>[ 27.270380] [<ffffffff811d7633>] SyS_fallocate+0x43/0x70
<4>[ 27.270738] [<ffffffff81862c69>] system_call_fastpath+0x16/0x1b
<4>[ 27.271119] ---[ end trace 6a3b1350ad399610 ]---
<4>[ 27.274498] ------------[ cut here ]------------

[Fengguang Wu]

Hi Jan,

Your patch gives a warning on the xfs code path. :)

git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4.git dev
commit be330474e2d0533a7a6185e567f3654fec096dbd ("vfs: fix data corruption when blocksize < pagesize for mmaped data")


testbox/testcase/testparams: bay/fileio/performance-600s-100%-1HDD-xfs-64G-1024f-seqrewr-sync

f6e63f90809946d4 be330474e2d0533a7a6185e567
---------------- --------------------------
fail:runs %reproduction fail:runs
| | |
:1 100% 5:5 kmsg.WARNING:at_mm/truncate.c:pagecache_isize_extended()
:1 100% 5:5 dmesg.WARNING:at_mm/truncate.c:pagecache_isize_extended()
%stddev %change %stddev
\ | \
4272 ± 29% +224.1% 13848 ± 20% sched_debug.cfs_rq[2]:/.spread0
5 ± 25% +84.0% 9 ± 18% sched_debug.cpu#1.cpu_load[1]
3 ± 22% +88.9% 6 ± 21% sched_debug.cpu#1.cpu_load[2]
6 ± 23% +53.1% 9 ± 16% sched_debug.cpu#1.cpu_load[0]
15780 ± 5% +50.5% 23751 ± 8% sched_debug.cfs_rq[3]:/.exec_clock
20615 ± 6% +52.2% 31371 ± 15% sched_debug.cfs_rq[3]:/.min_vruntime
193118 ± 16% +33.9% 258650 ± 15% sched_debug.cpu#1.ttwu_local
277966 ± 10% -26.1% 205411 ± 13% sched_debug.cpu#2.ttwu_local
24040 ± 6% +38.2% 33230 ± 11% sched_debug.cfs_rq[2]:/.min_vruntime
98 ± 15% +57.8% 154 ± 23% sched_debug.cfs_rq[1]:/.blocked_load_avg
23851 ± 0% +33.9% 31941 ± 0% proc-vmstat.nr_free_pages
95193 ± 0% +34.0% 127532 ± 0% meminfo.MemFree
96061 ± 0% +33.4% 128133 ± 0% vmstat.memory.free
19715 ± 3% +27.7% 25185 ± 5% sched_debug.cfs_rq[2]:/.exec_clock
690451 ± 9% -18.2% 564810 ± 6% sched_debug.cpu#2.ttwu_count
640 ± 12% +27.3% 815 ± 9% slabinfo.proc_inode_cache.active_objs
704 ± 6% +21.3% 854 ± 9% slabinfo.proc_inode_cache.num_objs
52372 ± 6% +18.8% 62197 ± 4% sched_debug.cpu#3.nr_load_updates
32780 ± 0% +18.7% 38924 ± 4% meminfo.DirectMap4k
1252 ± 2% +20.8% 1512 ± 9% slabinfo.kmalloc-128.num_objs
1252 ± 2% +20.8% 1512 ± 9% slabinfo.kmalloc-128.active_objs
89552 ± 0% +9.1% 97715 ± 1% softirqs.TIMER
51602 ± 2% +10.4% 56947 ± 7% sched_debug.cpu#1.nr_load_updates
81.08 ± 1% +14.8% 93.05 ± 1% time.system_time
8413 ± 1% -9.1% 7649 ± 6% time.involuntary_context_switches
14 ± 0% +10.0% 15 ± 3% time.percent_of_cpu_this_job_got
14850 ± 0% -8.1% 13644 ± 11% vmstat.system.cs
7715 ± 0% -7.7% 7118 ± 11% vmstat.system.in
603 ± 0% +2.4% 617 ± 0% time.elapsed_time
141 ± 0% -2.2% 138 ± 0% iostat.sda.avgqu-sz


<5>[ 25.956576] XFS (sda1): Mounting V4 Filesystem
<6>[ 26.194468] XFS (sda1): Ending clean mount
<4>[ 27.258450] ------------[ cut here ]------------
<4>[ 27.258789] WARNING: CPU: 3 PID: 2339 at mm/truncate.c:758 pagecache_isize_extended+0xdd/0x120()
<4>[ 27.259443] Modules linked in: ipmi_watchdog ipmi_msghandler btrfs xor raid6_pq sg sr_mod cdrom sd_mod firewire_ohci firewire_core crc_itu_t snd_hda_codec_realtek pcspkr snd_hda_codec_generic ahci libahci libata snd_hda_intel i2c_i801 snd_hda_controller parport_pc parport snd_hda_codec snd_hwdep snd_pcm snd_timer shpchp snd x38_edac edac_core soundcore acpi_cpufreq
<4>[ 27.262734] CPU: 3 PID: 2339 Comm: fallocate Not tainted 3.17.0-gda9a9f1 #1
<4>[ 27.263153] Hardware name: / , BIOS VVRBLI9J.86A.2891.2007.0511.1144 05/11/2007
<4>[ 27.263780] 0000000000000009 ffff88007a43fd88 ffffffff81859ea6 0000000000000000
<4>[ 27.264492] ffff88007a43fdc0 ffffffff8106ef0d 0000000000001000 ffff88005b6f05a8
<4>[ 27.265199] 0000000000000000 ffff88005b6f05a8 0000000004000000 ffff88007a43fdd0
<4>[ 27.265906] Call Trace:
<4>[ 27.266165] [<ffffffff81859ea6>] dump_stack+0x4d/0x66
<4>[ 27.266511] [<ffffffff8106ef0d>] warn_slowpath_common+0x7d/0xa0
<4>[ 27.266900] [<ffffffff8106efea>] warn_slowpath_null+0x1a/0x20
<4>[ 27.267286] [<ffffffff8117020d>] pagecache_isize_extended+0xdd/0x120
<4>[ 27.267690] [<ffffffff811712b7>] truncate_setsize+0x27/0x40
<4>[ 27.268068] [<ffffffff8133eab7>] xfs_setattr_size+0x157/0x3a0
<4>[ 27.268442] [<ffffffff8134c827>] ? xfs_trans_commit+0x157/0x250
<4>[ 27.268821] [<ffffffff813336df>] xfs_file_fallocate+0x2df/0x300
<4>[ 27.269215] [<ffffffff811dbb09>] ? __sb_start_write+0x49/0xf0
<4>[ 27.269596] [<ffffffff813923b4>] ? selinux_file_permission+0xc4/0x120
<4>[ 27.270009] [<ffffffff811d7563>] do_fallocate+0x123/0x1b0
<4>[ 27.270380] [<ffffffff811d7633>] SyS_fallocate+0x43/0x70
<4>[ 27.270738] [<ffffffff81862c69>] system_call_fastpath+0x16/0x1b
<4>[ 27.271119] ---[ end trace 6a3b1350ad399610 ]---
<4>[ 27.274498] ------------[ cut here ]------------


Thanks,
Fengguang