Skip to contentSkip to conversation

bug in fs/xfs/xfs_aops.c:959! (kernel 3.1.5)

DISCUSSION Jeremy Sanders 3 participants 5 messages Dec 19, 2011 – Dec 29, 2011

lore
Share & tools
lore

Jeremy Sanders

author
#0 lore raw

Hello - this was just produced in kernel 3.1.5 (Fedora 16, x86-64, kernel-3.1.5-1.fc16.x86_64).

Jeremy

Dec 19 00:56:06 xback2 kernel: [374538.665353] ------------[ cut here 
]------------
Dec 19 00:56:06 xback2 kernel: [374538.665431] kernel BUG at 
fs/xfs/xfs_aops.c:959!
Dec 19 00:56:06 xback2 kernel: [374538.665504] invalid opcode: 0000 [#1] SMP 
Dec 19 00:56:06 xback2 kernel: [374538.665578] CPU 1 
Dec 19 00:56:06 xback2 kernel: [374538.665581] Modules linked in: btrfs

zlib_deflate libcrc32c nfs fscache it87 hwmon_vid xfs raid456 async_raid6_recov async_pq raid6_pq async_xor xor async_memcpy async_tx ppdev linear snd_intel8x0 snd_ac97_codec ac97_bus snd_seq snd_seq_device snd_pcm snd_timer snd edac_core k8temp edac_mce_amd forcedeth soundcore snd_page_alloc parport_pc parport nfsd lockd nfs_acl auth_rpcgss sunrpc nv_tco i2c_nforce2 i2c_core uinput firewire_ohci firewire_core pata_acpi ata_generic crc_itu_t sata_nv pata_amd 3w_9xxx [last unloaded: btrfs]

Dec 19 00:56:06 xback2 kernel: [374538.666079] 
Dec 19 00:56:06 xback2 kernel: [374538.666079] Pid: 22689, comm: flush-9:0 
Not tainted 3.1.5-1.fc16.x86_64 #1 WinFast C51GM03/C51MCP51
Dec 19 00:56:06 xback2 kernel: [374538.666079] RIP: 0010:
[<ffffffffa02ec7e2>]  [<ffffffffa02ec7e2>] xfs_vm_writepage+0x4c2/0x4f0 
[xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079] RSP: 0018:ffff88000017d920  
EFLAGS: 00010246
Dec 19 00:56:06 xback2 kernel: [374538.666079] RAX: 002000000002002d RBX: 
ffff88001812b6d0 RCX: 000000000000000c
Dec 19 00:56:06 xback2 kernel: [374538.666079] RDX: 0000000000000000 RSI: 
ffff88000017dc60 RDI: ffffea000038a600
Dec 19 00:56:06 xback2 kernel: [374538.666079] RBP: ffff88000017d9d0 R08: 
0000000000000000 R09: 0000000000016400
Dec 19 00:56:06 xback2 kernel: [374538.666079] R10: ffff88005fddc700 R11: 
0000000000000014 R12: 0000000000001023
Dec 19 00:56:06 xback2 kernel: [374538.666079] R13: ffffea000038a600 R14: 
ffff88001812b588 R15: ffff88000017da80
Dec 19 00:56:06 xback2 kernel: [374538.666079] FS:  00007f0ec79f07c0(0000) 
GS:ffff88005fb00000(0000) knlGS:00000000f7728840
Dec 19 00:56:06 xback2 kernel: [374538.666079] CS:  0010 DS: 0000 ES: 0000 
CR0: 000000008005003b
Dec 19 00:56:06 xback2 kernel: [374538.666079] CR2: 00007f4439b8c000 CR3: 
000000001fd2f000 CR4: 00000000000006e0
Dec 19 00:56:06 xback2 kernel: [374538.666079] DR0: 0000000000000000 DR1: 
0000000000000000 DR2: 0000000000000000
Dec 19 00:56:06 xback2 kernel: [374538.666079] DR3: 0000000000000000 DR6: 
00000000ffff0ff0 DR7: 0000000000000400
Dec 19 00:56:06 xback2 kernel: [374538.666079] Process flush-9:0 (pid: 
22689, threadinfo ffff88000017c000, task ffff88004fb49730)
Dec 19 00:56:06 xback2 kernel: [374538.666079] Stack:
Dec 19 00:56:06 xback2 kernel: [374538.666079]  ffff88000017d970 
ffffffff812aa14d 000000000003ffff ffff88000017dc60
Dec 19 00:56:06 xback2 kernel: [374538.666079]  0000000000040000 
0000000001b3fe15 0000000000001000 0000000001024000
Dec 19 00:56:06 xback2 kernel: [374538.666079]  0000000000000000 
000000000000000e ffff88000017d9d0 ffffffff81114df4
Dec 19 00:56:06 xback2 kernel: [374538.666079] Call Trace:
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff812aa14d>] ? 
radix_tree_gang_lookup_tag_slot+0x8d/0xd0
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff81114df4>] ? 
find_get_pages_tag+0x44/0x140
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffffa02ee67f>] ? 
xfs_buf_get+0x8f/0x1a0 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111dec7>] 
__writepage+0x17/0x40
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111e32d>] 
write_cache_pages+0x20d/0x460
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff81053162>] ? 
complete+0x52/0x60
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111deb0>] ? 
set_page_dirty_lock+0x60/0x60
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffffa02ee551>] ? 
xfs_buf_delwri_queue+0xb1/0x150 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffffa02eec5a>] ? 
xfs_bdwrite+0x4a/0xb0 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffffa033406b>] ? 
xfs_iflush+0x20b/0x220 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111e5ca>] 
generic_writepages+0x4a/0x70
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffffa02eb8fd>] 
xfs_vm_writepages+0x4d/0x60 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111f8d1>] 
do_writepages+0x21/0x40
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff81198af9>] 
writeback_single_inode+0x149/0x3e0
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff81198f30>] 
writeback_sb_inodes+0x1a0/0x240
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8119906e>] 
__writeback_inodes_wb+0x9e/0xd0
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8119a25b>] 
wb_writeback+0x25b/0x340
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8111eb4a>] ? 
determine_dirtyable_memory+0x1a/0x30
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8119a7b3>] 
wb_do_writeback+0x1c3/0x200
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff815cdfaf>] ? 
schedule_timeout+0x16f/0x320
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8119a873>] 
bdi_writeback_thread+0x83/0x2a0
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8119a7f0>] ? 
wb_do_writeback+0x200/0x200
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8108ddbc>] 
kthread+0x8c/0xa0
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff815d9974>] 
kernel_thread_helper+0x4/0x10
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff8108dd30>] ? 
kthread_worker_fn+0x190/0x190
Dec 19 00:56:06 xback2 kernel: [374538.666079]  [<ffffffff815d9970>] ? 
gs_change+0x13/0x13
Dec 19 00:56:06 xback2 kernel: [374538.666079] Code: f8 f5 74 bd 4c 89 ef 89 
85 58 ff ff ff e8 f7 ee ff ff f0 41 80 65 00 f7 4c 89 ef e8 59 7a e2 e0 8b 
85 58 ff ff ff e9 60 fd ff ff <0f> 0b 48 89 df e8 94 3a eb e0 44 8b 8d 58 ff 
ff ff e9 d0 fd ff 
Dec 19 00:56:06 xback2 kernel: [374538.666079] RIP  [<ffffffffa02ec7e2>] 
xfs_vm_writepage+0x4c2/0x4f0 [xfs]
Dec 19 00:56:06 xback2 kernel: [374538.666079]  RSP <ffff88000017d920>
Dec 19 00:56:06 xback2 kernel: [374538.671894] ---[ end trace

280e5e9ba559f193 ]---

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#1 lore raw
Quoted 7 lines · Jeremy Sanders

Hello - this was just produced in kernel 3.1.5 (Fedora 16, x86-64, kernel-3.1.5-1.fc16.x86_64).

Jeremy

Dec 19 00:56:06 xback2 kernel: [374538.665353] ------------[ cut here ]------------

There was a line above this about an assert failure? What was it?

Quoted 5 lines
Dec 19 00:56:06 xback2 kernel: [374538.665431] kernel BUG at 
fs/xfs/xfs_aops.c:959!
Dec 19 00:56:06 xback2 kernel: [374538.665504] invalid opcode: 0000 [#1] SMP 
Dec 19 00:56:06 xback2 kernel: [374538.665578] CPU 1 
Dec 19 00:56:06 xback2 kernel: [374538.665581] Modules linked in: btrfs

.....
Pid: 22689, comm: flush-9:0 Not tainted 3.1.5-1.fc16.x86_64 #1 WinFast C51GM03/C51MCP51

RIP: 0010: [<ffffffffa02ec7e2>]  [<ffffffffa02ec7e2>] xfs_vm_writepage+0x4c2/0x4f0 [xfs]

 [<ffffffff8111dec7>] __writepage+0x17/0x40
 [<ffffffff8111e32d>] write_cache_pages+0x20d/0x460
 [<ffffffff8111e5ca>] generic_writepages+0x4a/0x70
 [<ffffffffa02eb8fd>] xfs_vm_writepages+0x4d/0x60 [xfs]
 [<ffffffff8111f8d1>] do_writepages+0x21/0x40
 [<ffffffff81198af9>] writeback_single_inode+0x149/0x3e0
 [<ffffffff81198f30>] writeback_sb_inodes+0x1a0/0x240
 [<ffffffff8119906e>] __writeback_inodes_wb+0x9e/0xd0
 [<ffffffff8119a25b>] wb_writeback+0x25b/0x340
 [<ffffffff8119a7b3>] wb_do_writeback+0x1c3/0x200
 [<ffffffff8119a873>] bdi_writeback_thread+0x83/0x2a0
 [<ffffffff8108ddbc>] kthread+0x8c/0xa0
 [<ffffffff815d9974>] kernel_thread_helper+0x4/0x10

If it tripped the assert I think it did, it looks like the system was trying to do write IO into a hole in the file. What workload were you running, and what are the details of your machine + storage config?

Cheers,

Dave.

Signature · 7 lines
Dave Chinner
[email protected]

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs
author
#2 lore raw
Quoted 1 line · Dave Chinner

There was a line above this about an assert failure? What was it?

Unfortunately there's are no other messages above this in /var/log/messages. I checked carefully for any asserts.

Quoted 4 lines

If it tripped the assert I think it did, it looks like the system was trying to do write IO into a hole in the file. What workload were you running, and what are the details of your machine + storage config?

It's xfs (nobarrier opts) running from a Linux MD software raid device (no LVM). It uses raid6 on 11 1TB discs, using a chunk size of 32 kB. The filesystem is 88% full. The discs are on a 3ware 9650SE controller.

The array has a set of backup "snapshots" with hard links created using the rsync --link-dest feature. We also used --sparse when doing the rsyncs. We have snapshots for a set of user directories, one for each day.

The message occured while rsync was writing to the array (creating the snapshots) and it was being read by rsync or a tar to tar pipe to a second btrfs array.

Jeremy

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

#3 lore raw
In reply to Jeremy Sanders
Quoted 2 lines · Jeremy Sanders

Hello - this was just produced in kernel 3.1.5 (Fedora 16, x86-64, kernel-3.1.5-1.fc16.x86_64).

Line 959 in 3.1.5 is this:

        bh = head = page_buffers(page);

page_buffers expands to:

#define page_buffers(page)                                      \
	({                                                      \
		BUG_ON(!PagePrivate(page));			\
		((struct buffer_head *)page_private(page));     \
	})

so what we got here is a page without buffers. Very odd.

[<ffffffff8111dec7>]  __writepage+0x17/0x40
[<ffffffff8111e32d>]  write_cache_pages+0x20d/0x460
[<ffffffff8111e5ca>]  generic_writepages+0x4a/0x70
[<ffffffffa02eb8fd>]  xfs_vm_writepages+0x4d/0x60 [xfs]
[<ffffffff8111f8d1>]  do_writepages+0x21/0x40
[<ffffffff81198af9>]  writeback_single_inode+0x149/0x3e0
[<ffffffff81198f30>]  writeback_sb_inodes+0x1a0/0x240
[<ffffffff8119906e>]  __writeback_inodes_wb+0x9e/0xd0
[<ffffffff8119a25b>]  wb_writeback+0x25b/0x340
[<ffffffff8119a7b3>]  wb_do_writeback+0x1c3/0x200
[<ffffffff8119a873>]  bdi_writeback_thread+0x83/0x2a0
[<ffffffff8108ddbc>]  kthread+0x8c/0xa0
[<ffffffff815d9974>]  kernel_thread_helper+0x4/0x10

And this looks like an entirely normal callchain for the flusher thread.

Something must have set the page dirty without going through the normal XFS codepath. Did you use any interesting virtualization things, or utrace / systemtap or anything odd?

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

author
#4 lore raw
Quoted 3 lines · Christoph Hellwig

Something must have set the page dirty without going through the normal XFS codepath. Did you use any interesting virtualization things, or utrace / systemtap or anything odd?

This is plain hardware running a Fedora 16 standard x86-64 kernel. The hardware has been fine running F14 a long time for a few years, though I got the same error when I tried to run a rebuilt F15 kernel on F14 (2.6.38.8). See http://oss.sgi.com/archives/xfs/2011-07/msg00310.html

The problem happened very soon on upgrading from F14->F16.

Jeremy

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs