Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755611Ab1FJRGz (ORCPT ); Fri, 10 Jun 2011 13:06:55 -0400 Received: from sentry-two.sandia.gov ([132.175.109.14]:52380 "EHLO sentry-two.sandia.gov" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751622Ab1FJRGw (ORCPT ); Fri, 10 Jun 2011 13:06:52 -0400 X-WSS-ID: 0LML3JF-0B-5K7-02 X-M-MSG: X-Server-Uuid: AF72F651-81B1-4134-BA8C-A8E1A4E620FF Message-ID: <4DF24F0E.4040306@sandia.gov> Date: Fri, 10 Jun 2011 11:06:22 -0600 From: "Jim Schutt" User-Agent: Thunderbird 2.0.0.24 (X11/20110418) MIME-Version: 1.0 To: dave@jikos.cz cc: jaschut@sandia.gov, miaox@cn.fujitsu.com, linux-kernel@vger.kernel.org, linux-btrfs@vger.kernel.org, "ceph-devel@vger.kernel.org" Subject: Re: 3.0-rcX BUG at fs/btrfs/ioctl.c:432 - bisected References: <4DF140AB.4030805@sandia.gov> <20110609234553.GN12709@twin.jikos.cz> In-Reply-To: <20110609234553.GN12709@twin.jikos.cz> X-Originating-IP: [134.253.95.179] X-TMWD-Spam-Summary: TS=20110610170629; ID=1; SEV=2.3.1; DFV=B2011061017; IFV=NA; AIF=B2011061017; RPD=5.03.0010; ENG=NA; RPDID=7374723D303030312E30413031303230322E34444632344631342E303039393A534346535441543838363133332C73733D312C6667733D30; CAT=NONE; CON=NONE; SIG=AAABAJsKIgAAAAAAAAAAAAAAAAAAAH0= X-MMS-Spam-Filter-ID: B2011061017_5.03.0010 X-WSS-ID: 61EC909E4FO786531-01-01 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit X-RSA-Inspected: yes X-RSA-Classifications: Healthcare Dictionaries, public X-RSA-Action: allow Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 11174 Lines: 195 David Sterba wrote: > Hi, > > a candidate fix: > > http://git.kernel.org/?p=linux/kernel/git/mason/btrfs-unstable.git;a=commit;h=aa0467d8d2a00e75b2bb6a56a4ee6d70c5d1928f > > " > With Linus' tree, today's linux-next build (powercp ppc64_defconfig) > produced this warning: > > fs/btrfs/delayed-inode.c: In function 'btrfs_delayed_update_inode': > fs/btrfs/delayed-inode.c:1598:6: warning: 'ret' may be used > uninitialized in this function > Introduced by commit 16cdcec736cd ("btrfs: implement delayed inode items > operation"). > > This fixes a bug in btrfs_update_inode(): if the returned value from > btrfs_delayed_update_inode is a nonzero garbage, inode stat data are not > updated and several call paths may hit a BUG_ON or fail with strange > code. > " > > if you can reproduce it reliably, add this patch on top of the delayed inodes. > I cherry-picked aa0467d8d2a00e on top of 16cdcec736cd21, which gave me the following instead of a BUG: [ 246.986087] ------------[ cut here ]------------ [ 246.990714] WARNING: at mm/page_alloc.c:2032 __alloc_pages_slowpath+0x54/0x3c5() [ 246.998100] Hardware name: PowerEdge 1950 [ 247.002110] Modules linked in: btrfs zlib_deflate lzo_compress ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp i2c_dev i2c_core ext3 jbd scsi_transport_iscsi rds ib_ipoib rdma_ucm rdma_cm ib_ucm ib_uverbs ib_umad ib_cm iw_cm ib_addr ipv6 ib_sa dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod video sbs sbshc pci_slot battery acpi_pad ac kvm sg ses sd_mod enclosure megaraid_sas ide_cd_mod cdrom ib_mthca qla2xxx serio_raw ib_mad ib_core scsi_transport_fc button scsi_tgt ata_piix libata scsi_mod dcdbas i5k_amb tpm_tis tpm ioatdma hwmon tpm_bios ehci_hcd dca i5000_edac pcspkr iTCO_wdt uhci_hcd iTCO_vendor_support edac_core rtc nfs nfs_acl auth_rpcgss fscache lockd sunrpc tg3 bnx2 e1000 [last unloaded: freq_table] [ 247.076305] Pid: 6044, comm: cosd Not tainted 2.6.39-00002-gf47e9fd #25 [ 247.082911] Call Trace: [ 247.085358] [] ? __alloc_pages_slowpath+0x54/0x3c5 [ 247.091793] [] ? warn_slowpath_common+0x85/0x9e [ 247.097974] [] ? warn_slowpath_null+0x1a/0x1c [ 247.103974] [] ? __alloc_pages_slowpath+0x54/0x3c5 [ 247.110409] [] ? get_page_from_freelist+0x166/0x198 [ 247.116928] [] ? __alloc_pages_nodemask+0xca/0xf4 [ 247.123297] [] ? unmap_extent_buffer+0x11/0x13 [btrfs] [ 247.130079] [] ? alloc_pages_current+0xa3/0xac [ 247.136166] [] ? alloc_pages+0xe/0x10 [ 247.141472] [] ? __get_free_pages+0xe/0x4b [ 247.147218] [] ? kmalloc_order_trace+0x27/0x55 [ 247.153304] [] ? __kmalloc+0x37/0x100 [ 247.158625] [] ? btrfs_batch_insert_items+0xe0/0x229 [btrfs] [ 247.165933] [] ? btrfs_block_rsv_release+0x39/0x3b [btrfs] [ 247.173072] [] ? btrfs_insert_delayed_items+0xac/0xef [btrfs] [ 247.180472] [] ? btrfs_run_delayed_items+0x68/0xd9 [btrfs] [ 247.187610] [] ? btrfs_commit_transaction+0x266/0x5c9 [btrfs] [ 247.195000] [] ? list_del_init+0x21/0x21 [ 247.200583] [] ? create_subvol+0x420/0x440 [btrfs] [ 247.207018] [] ? need_resched+0x23/0x2d [ 247.212511] [] ? btrfs_mksubvol+0x10e/0x167 [btrfs] [ 247.219043] [] ? btrfs_ioctl_snap_create_transid+0x9c/0x121 [btrfs] [ 247.226962] [] ? btrfs_ioctl_snap_create+0x50/0x67 [btrfs] [ 247.234101] [] ? btrfs_ioctl+0x1d0/0x2c6 [btrfs] [ 247.240364] [] ? vfs_ioctl+0x1d/0x34 [ 247.245582] [] ? do_vfs_ioctl+0x171/0x17a [ 247.251242] [] ? fget_light+0x69/0x81 [ 247.256549] [] ? sys_ioctl+0x5c/0x7c [ 247.261770] [] ? putname+0x33/0x37 [ 247.266819] [] ? system_call_fastpath+0x16/0x1b [ 247.272993] ---[ end trace 9c75d74017f060f5 ]--- The mkcephfs command I was attempting succeeded, so I'm not sure if the above matters; mm/page_alloc.c:2032 is /* * In the slowpath, we sanity check order to avoid ever trying to * reclaim >= MAX_ORDER areas which will never succeed. Callers may * be using allocators in order of preference for an area that is * too large. */ if (order >= MAX_ORDER) { WARN_ON_ONCE(!(gfp_mask & __GFP_NOWARN)); return NULL; } When I did my bisection, my criteria for success/failure was "did mkcephfs succeed?". When I apply this criteria to a recent linus kernel (e.g. 06e86849cf4019), which includes the fix you mentioned (aa0467d8d2a00e), I get still a different failure mode, which doesn't actually reference btrfs: [ 276.364178] BUG: unable to handle kernel NULL pointer dereference at 000000000000000a [ 276.365127] IP: [] journal_start+0x3e/0x9c [jbd] [ 276.365127] PGD 1e4469067 PUD 1e1658067 PMD 0 [ 276.365127] Oops: 0000 [#1] SMP [ 276.365127] CPU 2 [ 276.365127] Modules linked in: btrfs zlib_deflate lzo_compress ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp i2c_dev i2c_core ext3 jbd scsi_transport_iscsi rds ib_ipoib rdma_ucm rdma_cm ib_ucm ib_uverbs ib_umad ib_cm iw_cm ib_addr ipv6 ib_sa dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod video sbs sbshc pci_slot battery acpi_pad ac kvm sg ses sd_mod enclosure megaraid_sas ide_cd_mod cdrom ib_mthca ib_mad qla2xxx button ib_core serio_raw scsi_transport_fc scsi_tgt dcdbas ata_piix libata tpm_tis tpm i5k_amb ioatdma tpm_bios hwmon iTCO_wdt scsi_mod i5000_edac iTCO_vendor_support ehci_hcd dca edac_core uhci_hcd pcspkr rtc nfs nfs_acl auth_rpcgss fscache lockd sunrpc tg3 bnx2 e1000 [last unloaded: freq_table] [ 276.365127] [ 276.365127] Pid: 6076, comm: cosd Not tainted 3.0.0-rc2-00196-g06e8684 #26 Dell Inc. PowerEdge 1950/0DT097 [ 276.365127] RIP: 0010:[] [] journal_start+0x3e/0x9c [jbd] [ 276.365127] RSP: 0018:ffff8801e2897b28 EFLAGS: 00010286 [ 276.365127] RAX: 000000000000000a RBX: ffff8801de8e1090 RCX: 0000000000000002 [ 276.365127] RDX: 0000000019b2d000 RSI: 000000000000000e RDI: 000000000000000e [ 276.365127] RBP: ffff8801e2897b48 R08: 0000000000000003 R09: ffff8801e2897c38 [ 276.365127] R10: ffff8801e2897ed8 R11: 0000000000000001 R12: ffff880223ff4400 [ 276.365127] R13: ffff880218522d60 R14: 0000000000000ec6 R15: ffff88021f54d878 [ 276.365127] FS: 00007f8ff0bbb710(0000) GS:ffff88022fc80000(0000) knlGS:0000000000000000 [ 276.365127] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 276.365127] CR2: 000000000000000a CR3: 000000021744f000 CR4: 00000000000006e0 [ 276.365127] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 276.365127] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 276.365127] Process cosd (pid: 6076, threadinfo ffff8801e2896000, task ffff880218522d60) [ 276.365127] Stack: [ 276.365127] ffff8801e2897b68 ffffea000756e788 ffff88021f54d728 ffff8801e2897c78 [ 276.365127] ffff8801e2897b58 ffffffffa05670ce ffff8801e2897b68 ffffffffa055c72d [ 276.365127] ffff8801e2897be8 ffffffffa055f044 ffff8801e2897c38 0000007400000000 [ 276.365127] Call Trace: [ 276.365127] [] ext3_journal_start_sb+0x4f/0x51 [ext3] [ 276.365127] [] ext3_journal_start+0x12/0x14 [ext3] [ 276.365127] [] ext3_write_begin+0x93/0x1a1 [ext3] [ 276.365127] [] ? __kunmap_atomic+0xe/0x10 [ 276.365127] [] generic_perform_write+0xb1/0x172 [ 276.365127] [] ? need_resched+0x23/0x2d [ 276.365127] [] generic_file_buffered_write+0x44/0x6f [ 276.365127] [] __generic_file_aio_write+0x253/0x2a8 [ 276.365127] [] generic_file_aio_write+0x63/0xb8 [ 276.365127] [] do_sync_write+0xc7/0x10b [ 276.365127] [] ? should_resched+0xe/0x2f [ 276.365127] [] ? _cond_resched+0xe/0x22 [ 276.365127] [] ? security_file_permission+0x2c/0x31 [ 276.365127] [] ? rw_verify_area+0xac/0xdb [ 276.365127] [] vfs_write+0xac/0xe4 [ 276.365127] [] sys_write+0x4c/0x71 [ 276.365127] [] system_call_fastpath+0x16/0x1b [ 276.365127] Code: 89 fc 48 c7 c3 e2 ff ff ff 89 f7 65 4c 8b 2c 25 c0 b5 00 00 4d 85 e4 49 8b 85 48 06 00 00 74 5e 48 85 c0 74 14 48 89 c3 48 8b 00 <4c> 39 20 74 04 0f 0b eb fe ff 43 0c eb 45 e8 70 ff ff ff 48 85 [ 276.365127] RIP [] journal_start+0x3e/0x9c [jbd] [ 276.365127] RSP [ 276.365127] CR2: 000000000000000a [ 276.725157] ---[ end trace 8a802dc03e3972ad ]--- My ceph OSDs are using btrfs for data, but the cosd process is logging debug info to an ext3 filesystem, so when I bisected "mkcephfs fails" to commit 16cdcec736cd21, I assumed it was the root cause of the above. What else do I need to do to help sort this out? -- Jim > > > On Thu, Jun 09, 2011 at 03:52:43PM -0600, Jim Schutt wrote: >> Hi, >> >> I've run into the following BUG on 3.0-rcX kernels when >> running mkcephfs: >> >> Jun 9 15:14:50 an1 [ 299.446615] ------------[ cut here ]------------ >> Jun 9 15:14:50 an1 [ 299.447357] kernel BUG at fs/btrfs/ioctl.c:432! > > ioctl.c: > 431 ret = btrfs_update_inode(trans, root, dir); > 432 BUG_ON(ret); > >> Jun 9 15:14:50 an1 [ 299.447357] RSP: 0018:ffff88021b163c48 EFLAGS: 00010206 >> Jun 9 15:14:50 an1 [ 299.447357] RAX: 0000000019b201a0 RBX: ffff88022402d800 RCX: ffff88019206c028 > ^^^^^^^^^^^^^^^^ > ret, which seems to contain value of delayed_node from previous return value > (deduced from assembly): > > delayed-node.c: > 1600 delayed_node = btrfs_get_or_create_delayed_node(inode); > 1601 if (IS_ERR(delayed_node)) > 1602 return PTR_ERR(delayed_node); > > >> Please let me know what other information I can provide, or >> any testing I can do, that will help to resolve this issue. > > thanks, I think the stacktrace contains everything important. I was trying to > trigger the bugon myself when the report arrived, but did not succeed. the > issue is quite recent and seeing this report was a "cache" hit :) > > Note: there are two more possibilities to hit the bugon in the ioctl: ENOMEM > and ENOENT being retunred from btrfs_update_inode, but the symptoms fit the > case described above. > > > david > > -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/