!PageLocked BUG_ON hit in clear_page_dirty_for_io

!PageLocked BUG_ON hit in clear_page_dirty_for_io

[Dave Jones]

Not sure if I've already reported this one, but I've been seeing this
a lot this last couple days.

kernel BUG at mm/page-writeback.c:2654!
invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
RSP: 0018:ffff8800cd80fa00  EFLAGS: 00010246
RAX: 800000000000080c RBX: ffffea0011098a00 RCX: ffff8800cd80fbb7
RDX: dffffc0000000000 RSI: 1ffff10019b01f76 RDI: ffffea0011098a00
RBP: ffff8800cd80fa20 R08: ffff880453272000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88045326f2c0
R13: ffff88046272a310 R14: 0000000000000000 R15: 0000000000000001
FS:  00007f186573d700(0000) GS:ffff880468a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000010dd580 CR3: 000000046261c000 CR4: 00000000001406e0
Stack:
 0000000000000001 ffff88046272a310 ffff88046272a310 0000000000000000
 ffff8800cd80fa90 ffffffffc03891b5 ffff8800cd80fb30 ffff880402400040
 ffff88045326f0e8 0000000000001000 ffff88045326ed88 ffff8800cd80fbb0
Call Trace:
 [<ffffffffc03891b5>] lock_and_cleanup_extent_if_need+0xa5/0x260 [btrfs]
 [<ffffffffc038acf4>] __btrfs_buffered_write+0x324/0x8a0 [btrfs]
 [<ffffffffc038a9d0>] ? btrfs_dirty_pages+0xf0/0xf0 [btrfs]
 [<ffffffff88261adc>] ? generic_file_direct_write+0x2ac/0x2c0
 [<ffffffff88261830>] ? generic_file_read_iter+0xa00/0xa00
 [<ffffffffc039066d>] btrfs_file_write_iter+0x6dd/0x800 [btrfs]
 [<ffffffff882f6a0d>] __vfs_write+0x21d/0x260
 [<ffffffff882f67f0>] ? __vfs_read+0x260/0x260
 [<ffffffff8812ed62>] ? __lock_is_held+0x92/0xd0
 [<ffffffff880ee3b1>] ? preempt_count_sub+0xc1/0x120
 [<ffffffff8812cd47>] ? percpu_down_read+0x57/0xa0
 [<ffffffff882fbde4>] ? __sb_start_write+0xb4/0xf0
 [<ffffffff882f77f6>] vfs_write+0xf6/0x260
 [<ffffffff882f8e0f>] SyS_write+0xbf/0x160
 [<ffffffff882f8d50>] ? SyS_read+0x160/0x160
 [<ffffffff88002017>] ? trace_hardirqs_on_thunk+0x17/0x19
 [<ffffffff88cea997>] entry_SYSCALL_64_fastpath+0x12/0x6b
Code: 61 01 49 8d bd f0 00 00 00 8d 14 c5 08 00 00 00 e8 b6 cd 31 00 f6 c7 02 74 20 e8 8c 41 ec ff 53 9d b8 01 00 00 00 e9 1d ff ff ff <0f> 0b 48 89 df e8 b6 f5 ff ff e9 41 ff ff ff 53 9d e8 0a e7 eb 


That BUG is..

2653 
2654         BUG_ON(!PageLocked(page));
2655 

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Markus Trippelsdorf]

On 2015.12.08 at 23:25 -0500, Dave Jones wrote:
> Not sure if I've already reported this one, but I've been seeing this
> a lot this last couple days.
> 
> kernel BUG at mm/page-writeback.c:2654!

Just hit the same issue trying to build ghc-7.10.3:

[55704.436096] ------------[ cut here ]------------
[55704.436155] kernel BUG at mm/page-writeback.c:2654!
[55704.436213] invalid opcode: 0000 [#1] SMP 
[55704.436261] CPU: 2 PID: 17177 Comm: ghc Not tainted 4.4.0-rc4-00060-g9a0f76fde9ad-dirty #69
[55704.436370] Hardware name: System manufacturer System Product Name/M4A78T-E, BIOS 3503    04/13/2011
[55704.436491] task: ffff88015c2c1d40 ti: ffff880199268000 task.ti: ffff880199268000
[55704.436585] RIP: 0010:[<ffffffff8113b4bd>]  [<ffffffff8113b4bd>] clear_page_dirty_for_io+0xdd/0x180
[55704.436710] RSP: 0018:ffff88019926bcd0  EFLAGS: 00010246
[55704.436770] RAX: 4000000000000868 RBX: ffffea00029f2080 RCX: 0000000000000000
[55704.436860] RDX: 0000000000000000 RSI: 0000000000000286 RDI: ffffea00029f2080
[55704.436949] RBP: ffff8801c7900e30 R08: 0000a2bc9694357c R09: 0000000000000000
[55704.437037] R10: 0000000000000000 R11: ffff88015c2c1da0 R12: ffff8801c7900e30
[55704.437131] R13: ffff88019926bda0 R14: 0007ffffffffffff R15: ffffea00029f2080
[55704.437222] FS:  00007f79ba21e700(0000) GS:ffff88021fd00000(0000) knlGS:0000000000000000
[55704.437326] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[55704.437395] CR2: 00007fffa6d2cff8 CR3: 000000007ee1b000 CR4: 00000000000006e0
[55704.437485] Stack:
[55704.437495]  ffff88019926bd38 ffff88019926be78 ffff8801c7900e30 ffffffff812f81ae
[55704.437595]  ffff88019926bdd8 0000000000400000 0000000000000000 0000000000000000
[55704.437693]  ffff8801c7900cf0 000000000000000e 000000000000000e 0000000000000000
[55704.437792] Call Trace:
[55704.437812]  [<ffffffff812f81ae>] ? extent_write_cache_pages.isra.39.constprop.74+0x14e/0x320
[55704.437925]  [<ffffffff812f8f0b>] ? extent_writepages+0x4b/0x120
[55704.437998]  [<ffffffff812d4840>] ? __start_delalloc_inodes+0x3a0/0x3a0
[55704.438080]  [<ffffffff8113ba45>] ? do_writepages+0x25/0x80
[55704.438152]  [<ffffffff81056747>] ? do_signal+0x2c7/0x540
[55704.438228]  [<ffffffff811299c5>] ? filemap_flush+0x65/0xa0
[55704.438303]  [<ffffffff812e2fee>] ? btrfs_release_file+0x2e/0x40
[55704.438378]  [<ffffffff81182dec>] ? ____fput+0xcc/0x1c0
[55704.438438]  [<ffffffff810b22ec>] ? task_work_run+0x6c/0xa0
[55704.438510]  [<ffffffff8100268c>] ? syscall_return_slowpath+0xcc/0xe0
[55704.438591]  [<ffffffff8108f2e3>] ? int_ret_from_sys_call+0x25/0x8f
[55704.438672] Code: e1 81 74 19 49 8b 44 24 18 48 3b 05 be e2 d2 00 0f 84 8a 00 00 00 48 8b a8 c8 00 00 00 f0 0f ba 33 04 72 82 31 c0 e9 76 ff ff ff <0f> 0b 48 c7 c0 60 ce e1 81 e9 59 ff ff ff 48 89 df e8 4d 00 01 
[55704.439055] RIP  [<ffffffff8113b4bd>] clear_page_dirty_for_io+0xdd/0x180
[55704.439144]  RSP <ffff88019926bcd0>
[55704.475600] ---[ end trace 09f06afe4a05a024 ]---

-- 
Markus

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Chris Mason]

On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
> Not sure if I've already reported this one, but I've been seeing this
> a lot this last couple days.
> 
> kernel BUG at mm/page-writeback.c:2654!
> invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
> CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
> task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
> RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0

Huh, are you able to reproduce at will?  From this code path it should
mean somebody else is unlocking a page they don't own.

-chris

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Dave Jones]

On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
 > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
 > > Not sure if I've already reported this one, but I've been seeing this
 > > a lot this last couple days.
 > > 
 > > kernel BUG at mm/page-writeback.c:2654!
 > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
 > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
 > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
 > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
 > 
 > Huh, are you able to reproduce at will?  From this code path it should
 > mean somebody else is unlocking a page they don't own.

pretty easily yeah. I hit it maybe a couple dozen times yesterday.
So if you've got some idea of printk's to spray anywhere I can give
that a shot.

	Dave

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Georg Lukas]

[-- Attachment #1: Type: text/plain, Size: 5406 bytes --]

* Chris Mason <clm@fb.com> [2015-12-10 20:02]:
> Huh, are you able to reproduce at will?  From this code path it should
> mean somebody else is unlocking a page they don't own.

I've got another code path causing this bug that happened during a
"btrfs dev delete missing". Didn't try to reproduce it though, but
downgraded to 4.3 where it doesn't happen:


[10661.929152] BTRFS info (device dm-1): relocating block group 19173384781824 flags 17
[10709.050290] ------------[ cut here ]------------
[10709.050316] kernel BUG at mm/page-writeback.c:2654!
[10709.050338] invalid opcode: 0000 [#1] SMP 
[10709.050366] Modules linked in: dm_crypt loop sha256_ssse3 sha256_generic hmac drbg ansi_cprng xts gf128mul algif_skcipher af_alg cpuid nfsd auth_rpcg
ss oid_registry nfs_acl nfs lockd grace fscache sunrpc btrfs xor intel_rapl iosf_mbi x86_pkg_temp_thermal intel_powerclamp kvm_intel kvm irqbypass snd_p
cm crct10dif_pclmul snd_timer evdev snd crc32_pclmul iTCO_wdt iTCO_vendor_support soundcore cryptd psmouse pcspkr serio_raw hpilo hpwdt lpc_ich raid6_pq
 8250_fintek mfd_core acpi_power_meter button pcc_cpufreq acpi_cpufreq tpm_tis tpm shpchp processor coretemp ipmi_watchdog dm_mod ipmi_si ipmi_poweroff ipmi_devintf ipmi_msghandler fuse autofs4 ext4 crc16 mbcache jbd2 hid_generic usbhid hid sg sd_mod ses enclosure usb_storage crc32c_intel ahci libahci libata scsi_mod uhci_hcd thermal xhci_pci xhci_hcd
[10709.050854]  tg3 ptp pps_core libphy ehci_pci ehci_hcd usbcore usb_common
[10709.050899] CPU: 1 PID: 14215 Comm: btrfs Tainted: G        W       4.4.0-rc4-gl+ #44
[10709.050933] Hardware name: HP ProLiant MicroServer Gen8, BIOS J06 06/06/2014
[10709.050956] task: ffff8800791e5100 ti: ffff880016a2c000 task.ti: ffff880016a2c000
[10709.050989] RIP: 0010:[<ffffffff81142dc3>]  [<ffffffff81142dc3>] clear_page_dirty_for_io+0xd3/0x190
[10709.051030] RSP: 0018:ffff880016a2f7c0  EFLAGS: 00010246
[10709.051051] RAX: 01ffff800000082c RBX: ffffea000185efc0 RCX: ffffea000185efc0
[10709.051073] RDX: 0000000000000000 RSI: ffff880016a2f7c0 RDI: ffffea000185efc0
[10709.051096] RBP: ffff880036a4b700 R08: 0000168a3405fe9c R09: 0000000000000000
[10709.051118] R10: 0000000000000000 R11: 00000000000003e5 R12: ffff880036a4b700
[10709.051140] R13: ffff880016a2f8a0 R14: ffffffffffffffff R15: ffffea000185efc0
[10709.051162] FS:  00007ff63f1708c0(0000) GS:ffff88007ac20000(0000) knlGS:0000000000000000
[10709.051196] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[10709.051217] CR2: 00007fbab82c8000 CR3: 000000002fc60000 CR4: 00000000001406e0
[10709.051238] Stack:
[10709.051255]  ffff880016a2f830 ffff880016a2f910 ffff880036a4b700 ffff880016a2f8a0
[10709.051298]  ffffffffffffffff ffffffffa0525bed ffff880016a2f8d8 0000000036a4b428
[10709.051340]  0000000000000000 0000000000000002 ffff880036a4b598 000000000000002a
[10709.051384] Call Trace:
[10709.051417]  [<ffffffffa0525bed>] ? extent_write_cache_pages.isra.31.constprop.51+0x14d/0x330 [btrfs]
[10709.051460]  [<ffffffffa0526e38>] ? extent_writepages+0x48/0x60 [btrfs]
[10709.051489]  [<ffffffffa050a660>] ? btrfs_real_readdir+0x4f0/0x4f0 [btrfs]
[10709.051513]  [<ffffffff81139d42>] ? __filemap_fdatawrite_range+0xa2/0xe0
[10709.051543]  [<ffffffffa051b5f6>] ? btrfs_fdatawrite_range+0x16/0x40 [btrfs]
[10709.051572]  [<ffffffffa05464e4>] ? __btrfs_write_out_cache.isra.25+0x3c4/0x410 [btrfs]
[10709.051613]  [<ffffffffa0547e73>] ? btrfs_write_out_cache+0x83/0xd0 [btrfs]
[10709.051641]  [<ffffffffa04f33d2>] ? btrfs_write_dirty_block_groups+0x232/0x2a0 [btrfs]
[10709.051679]  [<ffffffffa05771cd>] ? commit_cowonly_roots+0x206/0x2a3 [btrfs]
[10709.051708]  [<ffffffffa0506766>] ? btrfs_commit_transaction+0x516/0x9f0 [btrfs]
[10709.051748]  [<ffffffffa0506cd0>] ? start_transaction+0x90/0x480 [btrfs]
[10709.051776]  [<ffffffffa05545a8>] ? relocate_block_group+0x2b8/0x6a0 [btrfs]
[10709.051806]  [<ffffffffa05201a3>] ? btrfs_wait_ordered_roots+0x1a3/0x1c0 [btrfs]
[10709.051845]  [<ffffffffa0554b27>] ? btrfs_relocate_block_group+0x197/0x270 [btrfs]
[10709.051886]  [<ffffffffa052c92c>] ? btrfs_relocate_chunk.isra.38+0x3c/0xc0 [btrfs]
[10709.051926]  [<ffffffffa052d2d6>] ? btrfs_shrink_device+0x196/0x520 [btrfs]
[10709.051955]  [<ffffffffa0533d2e>] ? btrfs_rm_device+0x30e/0x7b0 [btrfs]
[10709.051984]  [<ffffffffa053cd5b>] ? btrfs_ioctl+0x20bb/0x2e10 [btrfs]
[10709.052007]  [<ffffffff8116f3ba>] ? page_add_file_rmap+0xa/0x50
[10709.052029]  [<ffffffff81163b48>] ? do_set_pte+0xc8/0xf0
[10709.052050]  [<ffffffff81139128>] ? filemap_map_pages+0x208/0x210
[10709.052073]  [<ffffffff8119977f>] ? mem_cgroup_try_charge+0x5f/0x1a0
[10709.052095]  [<ffffffff81164f1f>] ? handle_mm_fault+0x11df/0x16a0
[10709.052118]  [<ffffffff811af3da>] ? getname_flags+0x6a/0x1e0
[10709.052140]  [<ffffffff811b2fc3>] ? do_vfs_ioctl+0x293/0x470
[10709.052162]  [<ffffffff811b320f>] ? SyS_ioctl+0x6f/0x80
[10709.052183]  [<ffffffff81506a2e>] ? entry_SYSCALL_64_fastpath+0x12/0x6d
[10709.052205] Code: b4 24 00 01 00 00 f0 0f ba 33 04 72 20 31 db 48 85 ed 0f 85 9a 00 00 00 4c 89 ef e8 28 1a 05 00 89 d8 5b 5d 41 5c 41 5d 41 5e c3 <0f> 0b 4d 85 ed 74 0c 49 8b 85 68 02 00 00 65 48 ff 48 20 be 0b 
[10709.052472] RIP  [<ffffffff81142dc3>] clear_page_dirty_for_io+0xd3/0x190
[10709.052499]  RSP <ffff880016a2f7c0>
[10709.052860] ---[ end trace d5563d95fa19d835 ]---

Hope that helps,


Georg

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Chris Mason]

On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
> On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
>  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
>  > > Not sure if I've already reported this one, but I've been seeing this
>  > > a lot this last couple days.
>  > > 
>  > > kernel BUG at mm/page-writeback.c:2654!
>  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
>  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
>  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
>  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
>  > 
>  > Huh, are you able to reproduce at will?  From this code path it should
>  > mean somebody else is unlocking a page they don't own.
> 
> pretty easily yeah. I hit it maybe a couple dozen times yesterday.
> So if you've got some idea of printk's to spray anywhere I can give
> that a shot.

I'd rather try to trigger it here.  Going to have to add some way to
record which stack trace last unlocked and/or freed the page.

-chris

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Liu Bo]

On Thu, Dec 10, 2015 at 04:30:24PM -0500, Chris Mason wrote:
> On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
> > On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
> >  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
> >  > > Not sure if I've already reported this one, but I've been seeing this
> >  > > a lot this last couple days.
> >  > > 
> >  > > kernel BUG at mm/page-writeback.c:2654!
> >  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
> >  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
> >  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
> >  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
> >  > 
> >  > Huh, are you able to reproduce at will?  From this code path it should
> >  > mean somebody else is unlocking a page they don't own.
> > 
> > pretty easily yeah. I hit it maybe a couple dozen times yesterday.
> > So if you've got some idea of printk's to spray anywhere I can give
> > that a shot.
> 
> I'd rather try to trigger it here.  Going to have to add some way to
> record which stack trace last unlocked and/or freed the page.

Looks like a bisect with 4.3 might target the commit.

Thanks,

-liubo
> 
> -chris
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Filipe Manana]

On Thu, Dec 10, 2015 at 9:35 PM, Liu Bo <bo.li.liu@oracle.com> wrote:
> On Thu, Dec 10, 2015 at 04:30:24PM -0500, Chris Mason wrote:
>> On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
>> > On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
>> >  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
>> >  > > Not sure if I've already reported this one, but I've been seeing this
>> >  > > a lot this last couple days.
>> >  > >
>> >  > > kernel BUG at mm/page-writeback.c:2654!
>> >  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
>> >  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
>> >  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
>> >  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
>> >  >
>> >  > Huh, are you able to reproduce at will?  From this code path it should
>> >  > mean somebody else is unlocking a page they don't own.
>> >
>> > pretty easily yeah. I hit it maybe a couple dozen times yesterday.
>> > So if you've got some idea of printk's to spray anywhere I can give
>> > that a shot.
>>
>> I'd rather try to trigger it here.  Going to have to add some way to
>> record which stack trace last unlocked and/or freed the page.
>
> Looks like a bisect with 4.3 might target the commit.

Not necessarily a regression added in 4.3. We've had this issue
reported before on older releases, like 4.1 for example:

https://lkml.org/lkml/2015/5/19/190

>
> Thanks,
>
> -liubo
>>
>> -chris
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html



-- 
Filipe David Manana,

"Reasonable men adapt themselves to the world.
 Unreasonable men adapt the world to themselves.
 That's why all progress depends on unreasonable men."

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Dave Jones]

On Thu, Dec 10, 2015 at 04:30:24PM -0500, Chris Mason wrote:
 > On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
 > > On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
 > >  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
 > >  > > Not sure if I've already reported this one, but I've been seeing this
 > >  > > a lot this last couple days.
 > >  > > 
 > >  > > kernel BUG at mm/page-writeback.c:2654!
 > >  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
 > >  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
 > >  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
 > >  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
 > >  > 
 > >  > Huh, are you able to reproduce at will?  From this code path it should
 > >  > mean somebody else is unlocking a page they don't own.
 > > 
 > > pretty easily yeah. I hit it maybe a couple dozen times yesterday.
 > > So if you've got some idea of printk's to spray anywhere I can give
 > > that a shot.
 > 
 > I'd rather try to trigger it here.  Going to have to add some way to
 > record which stack trace last unlocked and/or freed the page.

I'm using..

trinity -q -l off -C8 -a64 -x fsync -x fdatasync -x syncfs -x sync --enable-fds=testfile,pseudo

interestingly, if I just use 'testfile' by itself, I can't reproduce it.
(That means "create a bunch a few files in current dir and use their fds")
the "pseudo" bit means "also use fds from /proc, /sys and /dev".

strange.

(also, using trinity.git rather than the last version released, though
 I doubt it makes a difference in this case)

	Dave

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Dave Jones]

On Thu, Dec 10, 2015 at 04:30:24PM -0500, Chris Mason wrote:
 > On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
 > > On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
 > >  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
 > >  > > Not sure if I've already reported this one, but I've been seeing this
 > >  > > a lot this last couple days.
 > >  > > 
 > >  > > kernel BUG at mm/page-writeback.c:2654!
 > >  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
 > >  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
 > >  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
 > >  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
 > >  > 
 > >  > Huh, are you able to reproduce at will?  From this code path it should
 > >  > mean somebody else is unlocking a page they don't own.
 > > 
 > > pretty easily yeah. I hit it maybe a couple dozen times yesterday.
 > > So if you've got some idea of printk's to spray anywhere I can give
 > > that a shot.
 > 
 > I'd rather try to trigger it here.  Going to have to add some way to
 > record which stack trace last unlocked and/or freed the page.

perhaps a clue.. this is the log fragment from the last trinity run..

[child4:1416] [25] splice(fd_in=257, off_in=0x0, fd_out=257, off_out=0x0, len=0xe000, flags=0x0) = -1 (Invalid argument)
[child4:1416] [26] pwrite64(fd=257, buf=0x2253530, count=782, pos=0x40404000) 
[child5:1414] [28] semop(semid=-16274, tsops=0x0, nsops=0x2000000000c6b4d5) = -1 (Invalid argument)
[child5:1414] [29] mlockall(flags=0x1) 
[child6:1427] [50] getgid() = 1000
[child6:1427] [51] mlock(addr=0x7f4c00d62000, len=0) 
[child7:1402] [79] setuid(uid=0x790617fe) = -1 (Invalid argument)
[child7:1402] [80] write(fd=257, buf=0x2255d90, count=2296) 

the oops I got was in write(), so it looked like a parallel write() with pwrite() was the trigger.

Sure enough, doing a run with -c write -c pwrite64 reproduces it even faster.

	Dave

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Dave Jones]

On Thu, Dec 10, 2015 at 05:57:20PM -0500, Dave Jones wrote:
 > On Thu, Dec 10, 2015 at 04:30:24PM -0500, Chris Mason wrote:
 >  > On Thu, Dec 10, 2015 at 02:35:55PM -0500, Dave Jones wrote:
 >  > > On Thu, Dec 10, 2015 at 02:02:20PM -0500, Chris Mason wrote:
 >  > >  > On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
 >  > >  > > Not sure if I've already reported this one, but I've been seeing this
 >  > >  > > a lot this last couple days.
 >  > >  > > 
 >  > >  > > kernel BUG at mm/page-writeback.c:2654!
 >  > >  > > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
 >  > >  > > CPU: 1 PID: 2566 Comm: trinity-c1 Tainted: G        W       4.4.0-rc4-think+ #14
 >  > >  > > task: ffff880462811b80 ti: ffff8800cd808000 task.ti: ffff8800cd808000
 >  > >  > > RIP: 0010:[<ffffffff8826ff40>]  [<ffffffff8826ff40>] clear_page_dirty_for_io+0x180/0x1d0
 >  > >  > 
 >  > >  > Huh, are you able to reproduce at will?  From this code path it should
 >  > >  > mean somebody else is unlocking a page they don't own.
 >  > > 
 >  > > pretty easily yeah. I hit it maybe a couple dozen times yesterday.
 >  > > So if you've got some idea of printk's to spray anywhere I can give
 >  > > that a shot.
 >  > 
 >  > I'd rather try to trigger it here.  Going to have to add some way to
 >  > record which stack trace last unlocked and/or freed the page.
 > 
 > I'm using..
 > 
 > trinity -q -l off -C8 -a64 -x fsync -x fdatasync -x syncfs -x sync --enable-fds=testfile,pseudo
 > 
 > interestingly, if I just use 'testfile' by itself, I can't reproduce it.
 > (That means "create a bunch a few files in current dir and use their fds")
 > the "pseudo" bit means "also use fds from /proc, /sys and /dev".

Actually scratch that. I finally got it to reproduce with just 'testfile'.
Which makes sense, given its a btrfs bug we're chasing, not anything to do
with sys/proc

	Dave

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Chris Mason]

On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
> Not sure if I've already reported this one, but I've been seeing this
> a lot this last couple days.
> 
> kernel BUG at mm/page-writeback.c:2654!
> invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN

We ended up discussing this in more detail on lkml, but I'll summarize
here.

There were two problems.  First lock_page() might not actually lock the
page in v4.4-rc4, it can bail out if a signal is pending.  This got
fixed just before v4.4-rc5, so if you were on rc4, upgrade asap.

Second, prepare_pages had a bug for single page writes:

>From f0be89af049857bcc537a53fe2a2fae080e7a5bd Mon Sep 17 00:00:00 2001
From: Chris Mason <clm@fb.com>
Date: Mon, 14 Dec 2015 15:40:44 -0800
Subject: [PATCH] Btrfs: check prepare_uptodate_page() error code earlier

prepare_pages() may end up calling prepare_uptodate_page() twice if our
write only spans a single page.  But if the first call returns an error,
our page will be unlocked and its not safe to call it again.

This bug goes all the way back to 2011, and it's not something commonly
hit.

While we're here, add a more explicit check for the page being truncated
away.  The bare lock_page() alone is protected only by good thoughts and
i_mutex, which we're sure to regret eventually.

Reported-by: Dave Jones <dsj@fb.com>
Signed-off-by: Chris Mason <clm@fb.com>
---
 fs/btrfs/file.c | 18 ++++++++++++++----
 1 file changed, 14 insertions(+), 4 deletions(-)

diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
index 72e7346..0f09526 100644
--- a/fs/btrfs/file.c
+++ b/fs/btrfs/file.c
@@ -1291,7 +1291,8 @@ out:
  * on error we return an unlocked page and the error value
  * on success we return a locked page and 0
  */
-static int prepare_uptodate_page(struct page *page, u64 pos,
+static int prepare_uptodate_page(struct inode *inode,
+				 struct page *page, u64 pos,
 				 bool force_uptodate)
 {
 	int ret = 0;
@@ -1306,6 +1307,10 @@ static int prepare_uptodate_page(struct page *page, u64 pos,
 			unlock_page(page);
 			return -EIO;
 		}
+		if (page->mapping != inode->i_mapping) {
+			unlock_page(page);
+			return -EAGAIN;
+		}
 	}
 	return 0;
 }
@@ -1324,6 +1329,7 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
 	int faili;
 
 	for (i = 0; i < num_pages; i++) {
+again:
 		pages[i] = find_or_create_page(inode->i_mapping, index + i,
 					       mask | __GFP_WRITE);
 		if (!pages[i]) {
@@ -1333,13 +1339,17 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
 		}
 
 		if (i == 0)
-			err = prepare_uptodate_page(pages[i], pos,
+			err = prepare_uptodate_page(inode, pages[i], pos,
 						    force_uptodate);
-		if (i == num_pages - 1)
-			err = prepare_uptodate_page(pages[i],
+		if (!err && i == num_pages - 1)
+			err = prepare_uptodate_page(inode, pages[i],
 						    pos + write_bytes, false);
 		if (err) {
 			page_cache_release(pages[i]);
+			if (err == -EAGAIN) {
+				err = 0;
+				goto again;
+			}
 			faili = i - 1;
 			goto fail;
 		}
-- 
2.4.6

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Liu Bo]

On Mon, Dec 14, 2015 at 07:03:24PM -0500, Chris Mason wrote:
> On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
> > Not sure if I've already reported this one, but I've been seeing this
> > a lot this last couple days.
> > 
> > kernel BUG at mm/page-writeback.c:2654!
> > invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
> 
> We ended up discussing this in more detail on lkml, but I'll summarize
> here.
> 
> There were two problems.  First lock_page() might not actually lock the
> page in v4.4-rc4, it can bail out if a signal is pending.  This got
> fixed just before v4.4-rc5, so if you were on rc4, upgrade asap.
> 
> Second, prepare_pages had a bug for single page writes:
> 
> From f0be89af049857bcc537a53fe2a2fae080e7a5bd Mon Sep 17 00:00:00 2001
> From: Chris Mason <clm@fb.com>
> Date: Mon, 14 Dec 2015 15:40:44 -0800
> Subject: [PATCH] Btrfs: check prepare_uptodate_page() error code earlier
> 
> prepare_pages() may end up calling prepare_uptodate_page() twice if our
> write only spans a single page.  But if the first call returns an error,
> our page will be unlocked and its not safe to call it again.
> 
> This bug goes all the way back to 2011, and it's not something commonly
> hit.
> 
> While we're here, add a more explicit check for the page being truncated
> away.  The bare lock_page() alone is protected only by good thoughts and
> i_mutex, which we're sure to regret eventually.

Reviewed-by: Liu Bo <bo.li.liu@oracle.com>

Thanks,

-liubo
> 
> Reported-by: Dave Jones <dsj@fb.com>
> Signed-off-by: Chris Mason <clm@fb.com>
> ---
>  fs/btrfs/file.c | 18 ++++++++++++++----
>  1 file changed, 14 insertions(+), 4 deletions(-)
> 
> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
> index 72e7346..0f09526 100644
> --- a/fs/btrfs/file.c
> +++ b/fs/btrfs/file.c
> @@ -1291,7 +1291,8 @@ out:
>   * on error we return an unlocked page and the error value
>   * on success we return a locked page and 0
>   */
> -static int prepare_uptodate_page(struct page *page, u64 pos,
> +static int prepare_uptodate_page(struct inode *inode,
> +				 struct page *page, u64 pos,
>  				 bool force_uptodate)
>  {
>  	int ret = 0;
> @@ -1306,6 +1307,10 @@ static int prepare_uptodate_page(struct page *page, u64 pos,
>  			unlock_page(page);
>  			return -EIO;
>  		}
> +		if (page->mapping != inode->i_mapping) {
> +			unlock_page(page);
> +			return -EAGAIN;
> +		}
>  	}
>  	return 0;
>  }
> @@ -1324,6 +1329,7 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
>  	int faili;
>  
>  	for (i = 0; i < num_pages; i++) {
> +again:
>  		pages[i] = find_or_create_page(inode->i_mapping, index + i,
>  					       mask | __GFP_WRITE);
>  		if (!pages[i]) {
> @@ -1333,13 +1339,17 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
>  		}
>  
>  		if (i == 0)
> -			err = prepare_uptodate_page(pages[i], pos,
> +			err = prepare_uptodate_page(inode, pages[i], pos,
>  						    force_uptodate);
> -		if (i == num_pages - 1)
> -			err = prepare_uptodate_page(pages[i],
> +		if (!err && i == num_pages - 1)
> +			err = prepare_uptodate_page(inode, pages[i],
>  						    pos + write_bytes, false);
>  		if (err) {
>  			page_cache_release(pages[i]);
> +			if (err == -EAGAIN) {
> +				err = 0;
> +				goto again;
> +			}
>  			faili = i - 1;
>  			goto fail;
>  		}
> -- 
> 2.4.6
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: !PageLocked BUG_ON hit in clear_page_dirty_for_io

[Filipe Manana]

On Tue, Dec 15, 2015 at 12:03 AM, Chris Mason <clm@fb.com> wrote:
> On Tue, Dec 08, 2015 at 11:25:28PM -0500, Dave Jones wrote:
>> Not sure if I've already reported this one, but I've been seeing this
>> a lot this last couple days.
>>
>> kernel BUG at mm/page-writeback.c:2654!
>> invalid opcode: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC KASAN
>
> We ended up discussing this in more detail on lkml, but I'll summarize
> here.
>
> There were two problems.  First lock_page() might not actually lock the
> page in v4.4-rc4, it can bail out if a signal is pending.  This got
> fixed just before v4.4-rc5, so if you were on rc4, upgrade asap.
>
> Second, prepare_pages had a bug for single page writes:
>
> From f0be89af049857bcc537a53fe2a2fae080e7a5bd Mon Sep 17 00:00:00 2001
> From: Chris Mason <clm@fb.com>
> Date: Mon, 14 Dec 2015 15:40:44 -0800
> Subject: [PATCH] Btrfs: check prepare_uptodate_page() error code earlier
>
> prepare_pages() may end up calling prepare_uptodate_page() twice if our
> write only spans a single page.  But if the first call returns an error,
> our page will be unlocked and its not safe to call it again.
>
> This bug goes all the way back to 2011, and it's not something commonly
> hit.
>
> While we're here, add a more explicit check for the page being truncated
> away.  The bare lock_page() alone is protected only by good thoughts and
> i_mutex, which we're sure to regret eventually.
>
> Reported-by: Dave Jones <dsj@fb.com>
> Signed-off-by: Chris Mason <clm@fb.com>

Reviewed-by: Filipe Manana <fdmanana@suse.com>

> ---
>  fs/btrfs/file.c | 18 ++++++++++++++----
>  1 file changed, 14 insertions(+), 4 deletions(-)
>
> diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
> index 72e7346..0f09526 100644
> --- a/fs/btrfs/file.c
> +++ b/fs/btrfs/file.c
> @@ -1291,7 +1291,8 @@ out:
>   * on error we return an unlocked page and the error value
>   * on success we return a locked page and 0
>   */
> -static int prepare_uptodate_page(struct page *page, u64 pos,
> +static int prepare_uptodate_page(struct inode *inode,
> +                                struct page *page, u64 pos,
>                                  bool force_uptodate)
>  {
>         int ret = 0;
> @@ -1306,6 +1307,10 @@ static int prepare_uptodate_page(struct page *page, u64 pos,
>                         unlock_page(page);
>                         return -EIO;
>                 }
> +               if (page->mapping != inode->i_mapping) {
> +                       unlock_page(page);
> +                       return -EAGAIN;
> +               }
>         }
>         return 0;
>  }
> @@ -1324,6 +1329,7 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
>         int faili;
>
>         for (i = 0; i < num_pages; i++) {
> +again:
>                 pages[i] = find_or_create_page(inode->i_mapping, index + i,
>                                                mask | __GFP_WRITE);
>                 if (!pages[i]) {
> @@ -1333,13 +1339,17 @@ static noinline int prepare_pages(struct inode *inode, struct page **pages,
>                 }
>
>                 if (i == 0)
> -                       err = prepare_uptodate_page(pages[i], pos,
> +                       err = prepare_uptodate_page(inode, pages[i], pos,
>                                                     force_uptodate);
> -               if (i == num_pages - 1)
> -                       err = prepare_uptodate_page(pages[i],
> +               if (!err && i == num_pages - 1)
> +                       err = prepare_uptodate_page(inode, pages[i],
>                                                     pos + write_bytes, false);
>                 if (err) {
>                         page_cache_release(pages[i]);
> +                       if (err == -EAGAIN) {
> +                               err = 0;
> +                               goto again;
> +                       }
>                         faili = i - 1;
>                         goto fail;
>                 }
> --
> 2.4.6
>