* Block Allocation Reservation Windows Map (ext3_try_to_allocate_with_rsv)
@ 2010-07-18 19:49 Sébastien Paolacci
2010-07-19 16:51 ` Sage Weil
0 siblings, 1 reply; 3+ messages in thread
From: Sébastien Paolacci @ 2010-07-18 19:49 UTC (permalink / raw)
To: ceph-devel
Hello,
I'm reproducibly facing the the following panic, server side, when
trying to cp -a /usr /mnt/ceph/ from a quite decent client onto a very
low end server (an atom nettop):
Jul 18 20:53:04 kernel: [ 825.096369] kjournald starting. Commit
interval 5 seconds
Jul 18 20:53:04 kernel: [ 825.096843] EXT3 FS on sda8, internal journal
Jul 18 20:53:04 kernel: [ 825.096853] EXT3-fs: mounted filesystem
with ordered data mode.
Jul 18 20:59:29 kernel: [ 1210.224202] Block Allocation Reservation
Windows Map (ext3_try_to_allocate_with_rsv):
Jul 18 20:59:29 kernel: [ 1210.224214] reservation window
0xffff880037b58958 start: 0, end: 0
Jul 18 20:59:29 kernel: [ 1210.224220] reservation window
0xffff8800378f2340 start: 25700771, end: 25700778
Jul 18 20:59:29 kernel: [ 1210.224226] reservation window
0xffff88006d34e380 start: 25700803, end: 25700810
Jul 18 20:59:29 kernel: [ 1210.224232] reservation window
0xffff8800378f2380 start: 25700811, end: 25700818
... (truncated, 1.9k "reservation window"-like lines) ...
Jul 18 20:59:29 kernel: [ 1210.253764] reservation window
0xffff88003796ff40 start: 30115046, end: 30115053
Jul 18 20:59:29 kernel: [ 1210.253772] reservation window
0xffff88006d0b64c0 start: 30115054, end: 30115061
Jul 18 20:59:29 kernel: [ 1210.253780] Window map complete.
Jul 18 20:59:29 kernel: [ 1210.254339] CPU 2
Jul 18 20:59:29 kernel: [ 1210.254468] Modules linked in: parport_pc
ppdev lp parport cpufreq_stats cpufreq_conservative cpufreq_userspace
cpufreq_powersave fuse lo
Jul 18 20:59:29 kernel: [ 1210.259400] Pid: 2199, comm: cosd Not
tainted 2.6.32-5-amd64 #1 To Be Filled By O.E.M.
Jul 18 20:59:29 kernel: [ 1210.259491] RIP: 0010:[<ffffffffa01c4332>]
[<ffffffffa01c4332>] ext3_try_to_allocate_with_rsv+0x4b1/0x5c1 [ext3]
Jul 18 20:59:29 kernel: [ 1210.259673] RSP: 0018:ffff8800376b59f8
EFLAGS: 00010246
Jul 18 20:59:29 kernel: [ 1210.259753] RAX: 0000000000000027 RBX:
0000000001c4037f RCX: 0000000000002b5b
Jul 18 20:59:29 kernel: [ 1210.259831] RDX: 0000000000000000 RSI:
0000000000000096 RDI: 0000000000000246
Jul 18 20:59:29 kernel: [ 1210.259906] RBP: ffff88006d0a5b80 R08:
ffff880037b58950 R09: ffffffff813a9526
Jul 18 20:59:29 kernel: [ 1210.259987] R10: 0000000000000000 R11:
00000000000186a0 R12: ffff88006d09b800
Jul 18 20:59:29 kernel: [ 1210.260067] R13: ffff880037b58800 R14:
00000000ffffffff R15: ffff88006d70f400
Jul 18 20:59:29 kernel: [ 1210.260150] FS: 00007fb45ac58710(0000)
GS:ffff880001900000(0000) knlGS:0000000000000000
Jul 18 20:59:29 kernel: [ 1210.260241] CS: 0010 DS: 0000 ES: 0000
CR0: 0000000080050033
Jul 18 20:59:29 kernel: [ 1210.260323] CR2: 00007fb44f5f4000 CR3:
0000000037bf6000 CR4: 00000000000006e0
Jul 18 20:59:29 kernel: [ 1210.260404] DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
Jul 18 20:59:29 kernel: [ 1210.260485] DR3: 0000000000000000 DR6:
00000000ffff0ff0 DR7: 0000000000000400
Jul 18 20:59:29 kernel: [ 1210.260572] Process cosd (pid: 2199,
threadinfo ffff8800376b4000, task ffff88006e618710)
Jul 18 20:59:29 kernel: [ 1210.260732] ffff88006f76d6c0
01c4000000008000 0000000000000010 ffff880030ee6310
Jul 18 20:59:29 kernel: [ 1210.260986] <0> 000003886d70f400
ffff88006f76d6c0 0000000000000388 ffff88006d0a5ba0
Jul 18 20:59:29 kernel: [ 1210.261372] <0> 0000000001c40000
0000000001c47fff ffff880037b58948 000000106ba9d100
Jul 18 20:59:29 kernel: [ 1210.261916] [<ffffffffa01c4650>] ?
ext3_new_blocks+0x20e/0x5e6 [ext3]
Jul 18 20:59:29 kernel: [ 1210.262018] [<ffffffffa01c4a45>] ?
ext3_new_block+0x1d/0x24 [ext3]
Jul 18 20:59:29 kernel: [ 1210.262118] [<ffffffffa01d426d>] ?
ext3_xattr_block_set+0x522/0x6ec [ext3]
Jul 18 20:59:29 kernel: [ 1210.262218] [<ffffffffa01d4713>] ?
ext3_xattr_set_handle+0x2dc/0x44c [ext3]
Jul 18 20:59:29 kernel: [ 1210.262309] [<ffffffff8103a417>] ?
enqueue_task+0x5c/0x65
Jul 18 20:59:29 kernel: [ 1210.262399] [<ffffffffa01d4904>] ?
ext3_xattr_set+0x81/0xc9 [ext3]
Jul 18 20:59:29 kernel: [ 1210.262488] [<ffffffff81105afc>] ?
__vfs_setxattr_noperm+0x3d/0xb1
Jul 18 20:59:29 kernel: [ 1210.262571] [<ffffffff81105be4>] ?
vfs_setxattr+0x74/0x8c
Jul 18 20:59:29 kernel: [ 1210.262655] [<ffffffff81105ca3>] ?
setxattr+0xa7/0xdc
Jul 18 20:59:29 kernel: [ 1210.262741] [<ffffffff81102781>] ?
mntput_no_expire+0x23/0xee
Jul 18 20:59:29 kernel: [ 1210.262827] [<ffffffff810e4f09>] ?
virt_to_head_page+0x9/0x2a
Jul 18 20:59:29 kernel: [ 1210.262913] [<ffffffff810f8e1c>] ?
user_path_at+0x52/0x79
Jul 18 20:59:29 kernel: [ 1210.262998] [<ffffffff810f838a>] ?
getname+0x23/0x1a0
Jul 18 20:59:29 kernel: [ 1210.263084] [<ffffffff81073b79>] ?
sys_futex+0x113/0x131
Jul 18 20:59:29 kernel: [ 1210.263169] [<ffffffff81105e2d>] ?
sys_setxattr+0x59/0x80
Jul 18 20:59:29 kernel: [ 1210.263261] [<ffffffff81010b42>] ?
system_call_fastpath+0x16/0x1b
Jul 18 20:59:29 kernel: [ 1210.267351] RSP <ffff8800376b59f8>
Jul 18 20:59:29 kernel: [ 1210.267436] ---[ end trace db503f602ea8578f ]---
It may actually not be directly related to ceph, I however have to
admit I never got this one in other situation on my stock Debian
kernel (and the multiple blocks allocation patch should be at least as
old as the 2.6.16 iirc).
I've also found this post describing an equivalent situation:
http://www.linuxquestions.org/questions/linux-general-1/alternative-to-nfs-602712/page2.html
(middle of page).
I don't know how (or even if) it's related but I'm simultaneously (and
regularly) getting a "mds laggy or crashed" messages during the test
(laggy seems to be the correct answer). I do however also got this
very message when using btrfs, with a better end;)
Sebastien
10.07.18_20:59:04.093645 pg v43: 264 pgs: 264
active+clean+degraded; 1429 MB data, 1725 MB used, 117 GB / 125 GB
avail; 16614/33228 degraded (50.000%)
10.07.18_20:59:08.348394 mds e13: 1/1/1 up {0=up:active(laggy or crashed)}
10.07.18_20:59:09.376428 pg v44: 264 pgs: 264
active+clean+degraded; 1661 MB data, 1963 MB used, 117 GB / 125 GB
avail; 17294/34588 degraded (50.000%)
10.07.18_20:59:10.687956 mds e14: 1/1/1 up {0=up:active}
10.07.18_20:59:11.707158 log 10.07.18_20:59:10.687549 mon0
192.168.0.3:6789/0 9 : [INF] mds0 192.168.0.3:6802/2217 up:active
10.07.18_20:59:12.493888 pg v45: 264 pgs: 264
active+clean+degraded; 1682 MB data, 1983 MB used, 117 GB / 125 GB
avail; 17301/34602 degraded (50.000%)
10.07.18_20:59:17.498511 pg v46: 264 pgs: 264
active+clean+degraded; 1689 MB data, 1989 MB used, 117 GB / 125 GB
avail; 17304/34608 degraded (50.000%)
10.07.18_20:59:22.498215 pg v47: 264 pgs: 264
active+clean+degraded; 1703 MB data, 2004 MB used, 117 GB / 125 GB
avail; 17312/34624 degraded (50.000%)
10.07.18_20:59:28.037937 pg v48: 264 pgs: 264
active+clean+degraded; 1743 MB data, 2044 MB used, 117 GB / 125 GB
avail; 17343/34686 degraded (50.000%)
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.253874] ------------[ cut here ]------------
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.254053] invalid opcode: 0000 [#1] SMP
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.254240] last sysfs file:
/sys/devices/pci0000:00/0000:00:0b.0/host2/target2:0:0/2:0:0:0/block/sda/removable
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.260661] Stack:
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.261813] Call Trace:
Message from syslogd at Jul 18 20:59:29 ...
kernel:[ 1210.263342] Code: 0b 48 8b 44 24 40 48 39 45 28 73 23 49 8b
bf 90 02 00 00 48 c7 c2 00 5b 1d a0 be 01 00 00 00 48 81 c7 50 01 00
00 e8 cd f0 ff ff <0f> 0b eb fe 48 8b 54 24 38 48 8b 4c 24 18 4c 8d 8c
24 80 00 00
10.07.18_20:59:32.539932 pg v49: 264 pgs: 264
active+clean+degraded; 1783 MB data, 2086 MB used, 117 GB / 125 GB
avail; 17450/34900 degraded (50.000%)
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Block Allocation Reservation Windows Map (ext3_try_to_allocate_with_rsv)
2010-07-18 19:49 Block Allocation Reservation Windows Map (ext3_try_to_allocate_with_rsv) Sébastien Paolacci
@ 2010-07-19 16:51 ` Sage Weil
2010-07-20 21:54 ` Sébastien Paolacci
0 siblings, 1 reply; 3+ messages in thread
From: Sage Weil @ 2010-07-19 16:51 UTC (permalink / raw)
To: Sébastien Paolacci; +Cc: ceph-devel
[-- Attachment #1: Type: TEXT/PLAIN, Size: 8713 bytes --]
Hi,
I hit a but like this myself on ext3 and 2.6.32 (I think?), but I wasn't
able to reproduce it on a newer kernel (2.6.34, iirc). Can you try
reproducing this on a newer kernel?
Thanks-
sage
On Sun, 18 Jul 2010, Sébastien Paolacci wrote:
> Hello,
>
> I'm reproducibly facing the the following panic, server side, when
> trying to cp -a /usr /mnt/ceph/ from a quite decent client onto a very
> low end server (an atom nettop):
>
> Jul 18 20:53:04 kernel: [ 825.096369] kjournald starting. Commit
> interval 5 seconds
> Jul 18 20:53:04 kernel: [ 825.096843] EXT3 FS on sda8, internal journal
> Jul 18 20:53:04 kernel: [ 825.096853] EXT3-fs: mounted filesystem
> with ordered data mode.
> Jul 18 20:59:29 kernel: [ 1210.224202] Block Allocation Reservation
> Windows Map (ext3_try_to_allocate_with_rsv):
> Jul 18 20:59:29 kernel: [ 1210.224214] reservation window
> 0xffff880037b58958 start: 0, end: 0
> Jul 18 20:59:29 kernel: [ 1210.224220] reservation window
> 0xffff8800378f2340 start: 25700771, end: 25700778
> Jul 18 20:59:29 kernel: [ 1210.224226] reservation window
> 0xffff88006d34e380 start: 25700803, end: 25700810
> Jul 18 20:59:29 kernel: [ 1210.224232] reservation window
> 0xffff8800378f2380 start: 25700811, end: 25700818
> ... (truncated, 1.9k "reservation window"-like lines) ...
> Jul 18 20:59:29 kernel: [ 1210.253764] reservation window
> 0xffff88003796ff40 start: 30115046, end: 30115053
> Jul 18 20:59:29 kernel: [ 1210.253772] reservation window
> 0xffff88006d0b64c0 start: 30115054, end: 30115061
> Jul 18 20:59:29 kernel: [ 1210.253780] Window map complete.
> Jul 18 20:59:29 kernel: [ 1210.254339] CPU 2
> Jul 18 20:59:29 kernel: [ 1210.254468] Modules linked in: parport_pc
> ppdev lp parport cpufreq_stats cpufreq_conservative cpufreq_userspace
> cpufreq_powersave fuse lo
> Jul 18 20:59:29 kernel: [ 1210.259400] Pid: 2199, comm: cosd Not
> tainted 2.6.32-5-amd64 #1 To Be Filled By O.E.M.
> Jul 18 20:59:29 kernel: [ 1210.259491] RIP: 0010:[<ffffffffa01c4332>]
> [<ffffffffa01c4332>] ext3_try_to_allocate_with_rsv+0x4b1/0x5c1 [ext3]
> Jul 18 20:59:29 kernel: [ 1210.259673] RSP: 0018:ffff8800376b59f8
> EFLAGS: 00010246
> Jul 18 20:59:29 kernel: [ 1210.259753] RAX: 0000000000000027 RBX:
> 0000000001c4037f RCX: 0000000000002b5b
> Jul 18 20:59:29 kernel: [ 1210.259831] RDX: 0000000000000000 RSI:
> 0000000000000096 RDI: 0000000000000246
> Jul 18 20:59:29 kernel: [ 1210.259906] RBP: ffff88006d0a5b80 R08:
> ffff880037b58950 R09: ffffffff813a9526
> Jul 18 20:59:29 kernel: [ 1210.259987] R10: 0000000000000000 R11:
> 00000000000186a0 R12: ffff88006d09b800
> Jul 18 20:59:29 kernel: [ 1210.260067] R13: ffff880037b58800 R14:
> 00000000ffffffff R15: ffff88006d70f400
> Jul 18 20:59:29 kernel: [ 1210.260150] FS: 00007fb45ac58710(0000)
> GS:ffff880001900000(0000) knlGS:0000000000000000
> Jul 18 20:59:29 kernel: [ 1210.260241] CS: 0010 DS: 0000 ES: 0000
> CR0: 0000000080050033
> Jul 18 20:59:29 kernel: [ 1210.260323] CR2: 00007fb44f5f4000 CR3:
> 0000000037bf6000 CR4: 00000000000006e0
> Jul 18 20:59:29 kernel: [ 1210.260404] DR0: 0000000000000000 DR1:
> 0000000000000000 DR2: 0000000000000000
> Jul 18 20:59:29 kernel: [ 1210.260485] DR3: 0000000000000000 DR6:
> 00000000ffff0ff0 DR7: 0000000000000400
> Jul 18 20:59:29 kernel: [ 1210.260572] Process cosd (pid: 2199,
> threadinfo ffff8800376b4000, task ffff88006e618710)
> Jul 18 20:59:29 kernel: [ 1210.260732] ffff88006f76d6c0
> 01c4000000008000 0000000000000010 ffff880030ee6310
> Jul 18 20:59:29 kernel: [ 1210.260986] <0> 000003886d70f400
> ffff88006f76d6c0 0000000000000388 ffff88006d0a5ba0
> Jul 18 20:59:29 kernel: [ 1210.261372] <0> 0000000001c40000
> 0000000001c47fff ffff880037b58948 000000106ba9d100
> Jul 18 20:59:29 kernel: [ 1210.261916] [<ffffffffa01c4650>] ?
> ext3_new_blocks+0x20e/0x5e6 [ext3]
> Jul 18 20:59:29 kernel: [ 1210.262018] [<ffffffffa01c4a45>] ?
> ext3_new_block+0x1d/0x24 [ext3]
> Jul 18 20:59:29 kernel: [ 1210.262118] [<ffffffffa01d426d>] ?
> ext3_xattr_block_set+0x522/0x6ec [ext3]
> Jul 18 20:59:29 kernel: [ 1210.262218] [<ffffffffa01d4713>] ?
> ext3_xattr_set_handle+0x2dc/0x44c [ext3]
> Jul 18 20:59:29 kernel: [ 1210.262309] [<ffffffff8103a417>] ?
> enqueue_task+0x5c/0x65
> Jul 18 20:59:29 kernel: [ 1210.262399] [<ffffffffa01d4904>] ?
> ext3_xattr_set+0x81/0xc9 [ext3]
> Jul 18 20:59:29 kernel: [ 1210.262488] [<ffffffff81105afc>] ?
> __vfs_setxattr_noperm+0x3d/0xb1
> Jul 18 20:59:29 kernel: [ 1210.262571] [<ffffffff81105be4>] ?
> vfs_setxattr+0x74/0x8c
> Jul 18 20:59:29 kernel: [ 1210.262655] [<ffffffff81105ca3>] ?
> setxattr+0xa7/0xdc
> Jul 18 20:59:29 kernel: [ 1210.262741] [<ffffffff81102781>] ?
> mntput_no_expire+0x23/0xee
> Jul 18 20:59:29 kernel: [ 1210.262827] [<ffffffff810e4f09>] ?
> virt_to_head_page+0x9/0x2a
> Jul 18 20:59:29 kernel: [ 1210.262913] [<ffffffff810f8e1c>] ?
> user_path_at+0x52/0x79
> Jul 18 20:59:29 kernel: [ 1210.262998] [<ffffffff810f838a>] ?
> getname+0x23/0x1a0
> Jul 18 20:59:29 kernel: [ 1210.263084] [<ffffffff81073b79>] ?
> sys_futex+0x113/0x131
> Jul 18 20:59:29 kernel: [ 1210.263169] [<ffffffff81105e2d>] ?
> sys_setxattr+0x59/0x80
> Jul 18 20:59:29 kernel: [ 1210.263261] [<ffffffff81010b42>] ?
> system_call_fastpath+0x16/0x1b
> Jul 18 20:59:29 kernel: [ 1210.267351] RSP <ffff8800376b59f8>
> Jul 18 20:59:29 kernel: [ 1210.267436] ---[ end trace db503f602ea8578f ]---
>
> It may actually not be directly related to ceph, I however have to
> admit I never got this one in other situation on my stock Debian
> kernel (and the multiple blocks allocation patch should be at least as
> old as the 2.6.16 iirc).
>
> I've also found this post describing an equivalent situation:
> http://www.linuxquestions.org/questions/linux-general-1/alternative-to-nfs-602712/page2.html
> (middle of page).
>
> I don't know how (or even if) it's related but I'm simultaneously (and
> regularly) getting a "mds laggy or crashed" messages during the test
> (laggy seems to be the correct answer). I do however also got this
> very message when using btrfs, with a better end;)
>
> Sebastien
>
>
> 10.07.18_20:59:04.093645 pg v43: 264 pgs: 264
> active+clean+degraded; 1429 MB data, 1725 MB used, 117 GB / 125 GB
> avail; 16614/33228 degraded (50.000%)
> 10.07.18_20:59:08.348394 mds e13: 1/1/1 up {0=up:active(laggy or crashed)}
> 10.07.18_20:59:09.376428 pg v44: 264 pgs: 264
> active+clean+degraded; 1661 MB data, 1963 MB used, 117 GB / 125 GB
> avail; 17294/34588 degraded (50.000%)
> 10.07.18_20:59:10.687956 mds e14: 1/1/1 up {0=up:active}
> 10.07.18_20:59:11.707158 log 10.07.18_20:59:10.687549 mon0
> 192.168.0.3:6789/0 9 : [INF] mds0 192.168.0.3:6802/2217 up:active
> 10.07.18_20:59:12.493888 pg v45: 264 pgs: 264
> active+clean+degraded; 1682 MB data, 1983 MB used, 117 GB / 125 GB
> avail; 17301/34602 degraded (50.000%)
> 10.07.18_20:59:17.498511 pg v46: 264 pgs: 264
> active+clean+degraded; 1689 MB data, 1989 MB used, 117 GB / 125 GB
> avail; 17304/34608 degraded (50.000%)
> 10.07.18_20:59:22.498215 pg v47: 264 pgs: 264
> active+clean+degraded; 1703 MB data, 2004 MB used, 117 GB / 125 GB
> avail; 17312/34624 degraded (50.000%)
> 10.07.18_20:59:28.037937 pg v48: 264 pgs: 264
> active+clean+degraded; 1743 MB data, 2044 MB used, 117 GB / 125 GB
> avail; 17343/34686 degraded (50.000%)
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.253874] ------------[ cut here ]------------
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.254053] invalid opcode: 0000 [#1] SMP
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.254240] last sysfs file:
> /sys/devices/pci0000:00/0000:00:0b.0/host2/target2:0:0/2:0:0:0/block/sda/removable
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.260661] Stack:
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.261813] Call Trace:
>
> Message from syslogd at Jul 18 20:59:29 ...
> kernel:[ 1210.263342] Code: 0b 48 8b 44 24 40 48 39 45 28 73 23 49 8b
> bf 90 02 00 00 48 c7 c2 00 5b 1d a0 be 01 00 00 00 48 81 c7 50 01 00
> 00 e8 cd f0 ff ff <0f> 0b eb fe 48 8b 54 24 38 48 8b 4c 24 18 4c 8d 8c
> 24 80 00 00
> 10.07.18_20:59:32.539932 pg v49: 264 pgs: 264
> active+clean+degraded; 1783 MB data, 2086 MB used, 117 GB / 125 GB
> avail; 17450/34900 degraded (50.000%)
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
>
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Block Allocation Reservation Windows Map (ext3_try_to_allocate_with_rsv)
2010-07-19 16:51 ` Sage Weil
@ 2010-07-20 21:54 ` Sébastien Paolacci
0 siblings, 0 replies; 3+ messages in thread
From: Sébastien Paolacci @ 2010-07-20 21:54 UTC (permalink / raw)
To: Sage Weil; +Cc: ceph-devel
Hello Sage,
I alas confirm that it does still happen on a 2.6.35-rc (Debian build).
That's not a domain I'm very familiar with, I just had quick look at
fs/ext3/balloc.c which seems to incriminate windows that overlap with
immediate neighbors (__rsv_window_dump). I've however checked the
traces and it seems to not be the case. FYI, here is a denser summary
of allocated windows (occurrences & block count):
1165 8
129 16
40 32
24 64
10 128
3 256
2 1024
Google is not very prolific on the subject and I don't have any damn
idea about what could lead to such a situation. Whatever ceph does,
the panic should anyway not happen.
Sebastien
Jul 20 20:35:04 kernel: [ 245.903097] EXT3-fs: barriers not enabled
Jul 20 20:35:04 kernel: [ 245.915298] kjournald starting. Commit
interval 5 seconds
Jul 20 20:35:04 kernel: [ 245.915910] EXT3-fs (sda8): using internal journal
Jul 20 20:35:04 kernel: [ 245.915920] EXT3-fs (sda8): mounted
filesystem with ordered data mode
Jul 20 20:40:48 kernel: [ 590.455751] Block Allocation Reservation
Windows Map (ext3_try_to_allocate_with_rsv):
Jul 20 20:40:48 kernel: [ 590.455766] reservation window
0xffff88006e5ff958 start: 0, end: 0
Jul 20 20:40:48 kernel: [ 590.455775] reservation window
0xffff88006e9a83c0 start: 2949908, end: 2949915
Jul 20 20:40:48 kernel: [ 590.455783] reservation window
0xffff8800379870c0 start: 2949916, end: 2949923
(...)
Jul 20 20:40:48 kernel: [ 590.477494] reservation window
0xffff88006d67a700 start: 7373396, end: 7373403
Jul 20 20:40:48 kernel: [ 590.477544] reservation window
0xffff88003476d080 start: 7373404, end: 7373411
Jul 20 20:40:48 kernel: [ 590.477567] Window map complete.
Jul 20 20:40:48 kernel: [ 590.489502] CPU 3
Jul 20 20:40:48 kernel: [ 590.489561] Modules linked in: parport_pc
ppdev lp parport mperf cpufreq_stats cpufreq_conservative
cpufreq_userspace cpufreq_powersave fJul 20 20:40:48 kernel: [
590.497930]
Jul 20 20:40:48 kernel: [ 590.498918] Pid: 2426, comm: cosd Not
tainted 2.6.35-rc5-amd64 #1 MCP7A-ION/To Be Filled By O.E.M.
Jul 20 20:40:48 kernel: [ 590.499939] RIP: 0010:[<ffffffffa02a7edb>]
[<ffffffffa02a7edb>] ext3_try_to_allocate_with_rsv+0x4e5/0x5f0 [ext3]
Jul 20 20:40:48 kernel: [ 590.501045] RSP: 0018:ffff88003745d998
EFLAGS: 00010292
Jul 20 20:40:48 kernel: [ 590.502117] RAX: 0000000000000027 RBX:
ffff88006e8cc680 RCX: 000000000000024e
Jul 20 20:40:48 kernel: [ 590.503164] RDX: 0000000000000000 RSI:
0000000000000046 RDI: 0000000000000246
Jul 20 20:40:48 kernel: [ 590.504185] RBP: ffff88006e5fd800 R08:
0000000000000002 R09: 0000000000000005
Jul 20 20:40:48 kernel: [ 590.504890] R10: 0000000000000000 R11:
000000000000000f R12: 00000000ffffffff
Jul 20 20:40:48 kernel: [ 590.505601] R13: ffff88003745daf0 R14:
ffff88006e5ff800 R15: 0000000000500000
Jul 20 20:40:48 kernel: [ 590.506329] FS: 00007f3f19fa7710(0000)
GS:ffff880001b80000(0000) knlGS:0000000000000000
Jul 20 20:40:48 kernel: [ 590.507036] CS: 0010 DS: 0000 ES: 0000
CR0: 0000000080050033
Jul 20 20:40:48 kernel: [ 590.507755] CR2: 00007f3f0e251000 CR3:
0000000044649000 CR4: 00000000000006e0
Jul 20 20:40:48 kernel: [ 590.508474] DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
Jul 20 20:40:48 kernel: [ 590.509194] DR3: 0000000000000000 DR6:
00000000ffff0ff0 DR7: 0000000000000400
Jul 20 20:40:48 kernel: [ 590.509952] Process cosd (pid: 2426,
threadinfo ffff88003745c000, task ffff8800447d2fb0)
Jul 20 20:40:48 kernel: [ 590.511423] ffff880014d013c8
ffffffffa02ab2a5 0000000000000000 000000000050023a
Jul 20 20:40:48 kernel: [ 590.511462] <0> ffff88001e9c1f40
0000000000000008 ffff880018b180d0 ffff88006f77e690
Jul 20 20:40:48 kernel: [ 590.512222] <0> 0000000000507fff
ffff88006e5ff948 00000000000000a0 ffff88006e5ff948
Jul 20 20:40:48 kernel: [ 590.514594] [<ffffffffa02ab2a5>] ?
ext3_mark_iloc_dirty+0x2d5/0x33a [ext3]
Jul 20 20:40:48 kernel: [ 590.515348] [<ffffffffa02a81f1>] ?
ext3_new_blocks+0x20b/0x565 [ext3]
Jul 20 20:40:48 kernel: [ 590.516082] [<ffffffff8105b70f>] ?
bit_waitqueue+0x14/0xa1
Jul 20 20:40:48 kernel: [ 590.516844] [<ffffffffa02a8565>] ?
ext3_new_block+0x1a/0x1f [ext3]
Jul 20 20:40:48 kernel: [ 590.517617] [<ffffffffa02b89c0>] ?
ext3_xattr_block_set+0x515/0x691 [ext3]
Jul 20 20:40:48 kernel: [ 590.518393] [<ffffffffa0297565>] ?
journal_put_journal_head+0x19/0x4e [jbd]
Jul 20 20:40:48 kernel: [ 590.519143] [<ffffffffa02b8e18>] ?
ext3_xattr_set_handle+0x2dc/0x42c [ext3]
Jul 20 20:40:48 kernel: [ 590.519897] [<ffffffffa02b8fe6>] ?
ext3_xattr_set+0x7e/0xd0 [ext3]
Jul 20 20:40:48 kernel: [ 590.520651] [<ffffffff810f819c>] ?
__d_lookup+0xc1/0x107
Jul 20 20:40:48 kernel: [ 590.521367] [<ffffffff810ff9ed>] ?
__vfs_setxattr_noperm+0x39/0xb6
Jul 20 20:40:48 kernel: [ 590.522140] [<ffffffff810ffad7>] ?
vfs_setxattr+0x6d/0x8c
Jul 20 20:40:48 kernel: [ 590.522865] [<ffffffff810ffbb0>] ?
setxattr+0xba/0xed
Jul 20 20:40:48 kernel: [ 590.523569] [<ffffffff810de71f>] ?
virt_to_head_page+0x9/0x2a
Jul 20 20:40:48 kernel: [ 590.524300] [<ffffffff810f2a0d>] ?
user_path_at+0x52/0x78
Jul 20 20:40:48 kernel: [ 590.525036] [<ffffffff810f0d9b>] ?
getname+0x23/0x1b1
Jul 20 20:40:48 kernel: [ 590.525755] [<ffffffff810ffcc5>] ?
sys_setxattr+0x60/0x85
Jul 20 20:40:48 kernel: [ 590.526466] [<ffffffff810089c2>] ?
system_call_fastpath+0x16/0x1b
Jul 20 20:40:48 kernel: [ 590.529817] RSP <ffff88003745d998>
Jul 20 20:40:48 kernel: [ 590.530550] ---[ end trace d8e7653724ca3e02 ]---
2010/7/19 Sage Weil <sage@newdream.net>:
> Hi,
>
> I hit a but like this myself on ext3 and 2.6.32 (I think?), but I wasn't
> able to reproduce it on a newer kernel (2.6.34, iirc). Can you try
> reproducing this on a newer kernel?
>
> Thanks-
> sage
>
> On Sun, 18 Jul 2010, Sébastien Paolacci wrote:
>
>> Hello,
>>
>> I'm reproducibly facing the the following panic, server side, when
>> trying to cp -a /usr /mnt/ceph/ from a quite decent client onto a very
>> low end server (an atom nettop):
>>
>> Jul 18 20:53:04 kernel: [ 825.096369] kjournald starting. Commit
>> interval 5 seconds
>> Jul 18 20:53:04 kernel: [ 825.096843] EXT3 FS on sda8, internal journal
>> Jul 18 20:53:04 kernel: [ 825.096853] EXT3-fs: mounted filesystem
>> with ordered data mode.
>> Jul 18 20:59:29 kernel: [ 1210.224202] Block Allocation Reservation
>> Windows Map (ext3_try_to_allocate_with_rsv):
>> Jul 18 20:59:29 kernel: [ 1210.224214] reservation window
>> 0xffff880037b58958 start: 0, end: 0
>> Jul 18 20:59:29 kernel: [ 1210.224220] reservation window
>> 0xffff8800378f2340 start: 25700771, end: 25700778
>> Jul 18 20:59:29 kernel: [ 1210.224226] reservation window
>> 0xffff88006d34e380 start: 25700803, end: 25700810
>> Jul 18 20:59:29 kernel: [ 1210.224232] reservation window
>> 0xffff8800378f2380 start: 25700811, end: 25700818
>> ... (truncated, 1.9k "reservation window"-like lines) ...
>> Jul 18 20:59:29 kernel: [ 1210.253764] reservation window
>> 0xffff88003796ff40 start: 30115046, end: 30115053
>> Jul 18 20:59:29 kernel: [ 1210.253772] reservation window
>> 0xffff88006d0b64c0 start: 30115054, end: 30115061
>> Jul 18 20:59:29 kernel: [ 1210.253780] Window map complete.
>> Jul 18 20:59:29 kernel: [ 1210.254339] CPU 2
>> Jul 18 20:59:29 kernel: [ 1210.254468] Modules linked in: parport_pc
>> ppdev lp parport cpufreq_stats cpufreq_conservative cpufreq_userspace
>> cpufreq_powersave fuse lo
>> Jul 18 20:59:29 kernel: [ 1210.259400] Pid: 2199, comm: cosd Not
>> tainted 2.6.32-5-amd64 #1 To Be Filled By O.E.M.
>> Jul 18 20:59:29 kernel: [ 1210.259491] RIP: 0010:[<ffffffffa01c4332>]
>> [<ffffffffa01c4332>] ext3_try_to_allocate_with_rsv+0x4b1/0x5c1 [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.259673] RSP: 0018:ffff8800376b59f8
>> EFLAGS: 00010246
>> Jul 18 20:59:29 kernel: [ 1210.259753] RAX: 0000000000000027 RBX:
>> 0000000001c4037f RCX: 0000000000002b5b
>> Jul 18 20:59:29 kernel: [ 1210.259831] RDX: 0000000000000000 RSI:
>> 0000000000000096 RDI: 0000000000000246
>> Jul 18 20:59:29 kernel: [ 1210.259906] RBP: ffff88006d0a5b80 R08:
>> ffff880037b58950 R09: ffffffff813a9526
>> Jul 18 20:59:29 kernel: [ 1210.259987] R10: 0000000000000000 R11:
>> 00000000000186a0 R12: ffff88006d09b800
>> Jul 18 20:59:29 kernel: [ 1210.260067] R13: ffff880037b58800 R14:
>> 00000000ffffffff R15: ffff88006d70f400
>> Jul 18 20:59:29 kernel: [ 1210.260150] FS: 00007fb45ac58710(0000)
>> GS:ffff880001900000(0000) knlGS:0000000000000000
>> Jul 18 20:59:29 kernel: [ 1210.260241] CS: 0010 DS: 0000 ES: 0000
>> CR0: 0000000080050033
>> Jul 18 20:59:29 kernel: [ 1210.260323] CR2: 00007fb44f5f4000 CR3:
>> 0000000037bf6000 CR4: 00000000000006e0
>> Jul 18 20:59:29 kernel: [ 1210.260404] DR0: 0000000000000000 DR1:
>> 0000000000000000 DR2: 0000000000000000
>> Jul 18 20:59:29 kernel: [ 1210.260485] DR3: 0000000000000000 DR6:
>> 00000000ffff0ff0 DR7: 0000000000000400
>> Jul 18 20:59:29 kernel: [ 1210.260572] Process cosd (pid: 2199,
>> threadinfo ffff8800376b4000, task ffff88006e618710)
>> Jul 18 20:59:29 kernel: [ 1210.260732] ffff88006f76d6c0
>> 01c4000000008000 0000000000000010 ffff880030ee6310
>> Jul 18 20:59:29 kernel: [ 1210.260986] <0> 000003886d70f400
>> ffff88006f76d6c0 0000000000000388 ffff88006d0a5ba0
>> Jul 18 20:59:29 kernel: [ 1210.261372] <0> 0000000001c40000
>> 0000000001c47fff ffff880037b58948 000000106ba9d100
>> Jul 18 20:59:29 kernel: [ 1210.261916] [<ffffffffa01c4650>] ?
>> ext3_new_blocks+0x20e/0x5e6 [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.262018] [<ffffffffa01c4a45>] ?
>> ext3_new_block+0x1d/0x24 [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.262118] [<ffffffffa01d426d>] ?
>> ext3_xattr_block_set+0x522/0x6ec [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.262218] [<ffffffffa01d4713>] ?
>> ext3_xattr_set_handle+0x2dc/0x44c [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.262309] [<ffffffff8103a417>] ?
>> enqueue_task+0x5c/0x65
>> Jul 18 20:59:29 kernel: [ 1210.262399] [<ffffffffa01d4904>] ?
>> ext3_xattr_set+0x81/0xc9 [ext3]
>> Jul 18 20:59:29 kernel: [ 1210.262488] [<ffffffff81105afc>] ?
>> __vfs_setxattr_noperm+0x3d/0xb1
>> Jul 18 20:59:29 kernel: [ 1210.262571] [<ffffffff81105be4>] ?
>> vfs_setxattr+0x74/0x8c
>> Jul 18 20:59:29 kernel: [ 1210.262655] [<ffffffff81105ca3>] ?
>> setxattr+0xa7/0xdc
>> Jul 18 20:59:29 kernel: [ 1210.262741] [<ffffffff81102781>] ?
>> mntput_no_expire+0x23/0xee
>> Jul 18 20:59:29 kernel: [ 1210.262827] [<ffffffff810e4f09>] ?
>> virt_to_head_page+0x9/0x2a
>> Jul 18 20:59:29 kernel: [ 1210.262913] [<ffffffff810f8e1c>] ?
>> user_path_at+0x52/0x79
>> Jul 18 20:59:29 kernel: [ 1210.262998] [<ffffffff810f838a>] ?
>> getname+0x23/0x1a0
>> Jul 18 20:59:29 kernel: [ 1210.263084] [<ffffffff81073b79>] ?
>> sys_futex+0x113/0x131
>> Jul 18 20:59:29 kernel: [ 1210.263169] [<ffffffff81105e2d>] ?
>> sys_setxattr+0x59/0x80
>> Jul 18 20:59:29 kernel: [ 1210.263261] [<ffffffff81010b42>] ?
>> system_call_fastpath+0x16/0x1b
>> Jul 18 20:59:29 kernel: [ 1210.267351] RSP <ffff8800376b59f8>
>> Jul 18 20:59:29 kernel: [ 1210.267436] ---[ end trace db503f602ea8578f ]---
>>
>> It may actually not be directly related to ceph, I however have to
>> admit I never got this one in other situation on my stock Debian
>> kernel (and the multiple blocks allocation patch should be at least as
>> old as the 2.6.16 iirc).
>>
>> I've also found this post describing an equivalent situation:
>> http://www.linuxquestions.org/questions/linux-general-1/alternative-to-nfs-602712/page2.html
>> (middle of page).
>>
>> I don't know how (or even if) it's related but I'm simultaneously (and
>> regularly) getting a "mds laggy or crashed" messages during the test
>> (laggy seems to be the correct answer). I do however also got this
>> very message when using btrfs, with a better end;)
>>
>> Sebastien
>>
>>
>> 10.07.18_20:59:04.093645 pg v43: 264 pgs: 264
>> active+clean+degraded; 1429 MB data, 1725 MB used, 117 GB / 125 GB
>> avail; 16614/33228 degraded (50.000%)
>> 10.07.18_20:59:08.348394 mds e13: 1/1/1 up {0=up:active(laggy or crashed)}
>> 10.07.18_20:59:09.376428 pg v44: 264 pgs: 264
>> active+clean+degraded; 1661 MB data, 1963 MB used, 117 GB / 125 GB
>> avail; 17294/34588 degraded (50.000%)
>> 10.07.18_20:59:10.687956 mds e14: 1/1/1 up {0=up:active}
>> 10.07.18_20:59:11.707158 log 10.07.18_20:59:10.687549 mon0
>> 192.168.0.3:6789/0 9 : [INF] mds0 192.168.0.3:6802/2217 up:active
>> 10.07.18_20:59:12.493888 pg v45: 264 pgs: 264
>> active+clean+degraded; 1682 MB data, 1983 MB used, 117 GB / 125 GB
>> avail; 17301/34602 degraded (50.000%)
>> 10.07.18_20:59:17.498511 pg v46: 264 pgs: 264
>> active+clean+degraded; 1689 MB data, 1989 MB used, 117 GB / 125 GB
>> avail; 17304/34608 degraded (50.000%)
>> 10.07.18_20:59:22.498215 pg v47: 264 pgs: 264
>> active+clean+degraded; 1703 MB data, 2004 MB used, 117 GB / 125 GB
>> avail; 17312/34624 degraded (50.000%)
>> 10.07.18_20:59:28.037937 pg v48: 264 pgs: 264
>> active+clean+degraded; 1743 MB data, 2044 MB used, 117 GB / 125 GB
>> avail; 17343/34686 degraded (50.000%)
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.253874] ------------[ cut here ]------------
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.254053] invalid opcode: 0000 [#1] SMP
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.254240] last sysfs file:
>> /sys/devices/pci0000:00/0000:00:0b.0/host2/target2:0:0/2:0:0:0/block/sda/removable
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.260661] Stack:
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.261813] Call Trace:
>>
>> Message from syslogd at Jul 18 20:59:29 ...
>> kernel:[ 1210.263342] Code: 0b 48 8b 44 24 40 48 39 45 28 73 23 49 8b
>> bf 90 02 00 00 48 c7 c2 00 5b 1d a0 be 01 00 00 00 48 81 c7 50 01 00
>> 00 e8 cd f0 ff ff <0f> 0b eb fe 48 8b 54 24 38 48 8b 4c 24 18 4c 8d 8c
>> 24 80 00 00
>> 10.07.18_20:59:32.539932 pg v49: 264 pgs: 264
>> active+clean+degraded; 1783 MB data, 2086 MB used, 117 GB / 125 GB
>> avail; 17450/34900 degraded (50.000%)
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" 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 ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2010-07-20 21:54 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-07-18 19:49 Block Allocation Reservation Windows Map (ext3_try_to_allocate_with_rsv) Sébastien Paolacci
2010-07-19 16:51 ` Sage Weil
2010-07-20 21:54 ` Sébastien Paolacci
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).