Home » Mailing lists » Users » Infinite loop in __d_lookup ?
| Infinite loop in __d_lookup ? [message #30126] |
Mon, 12 May 2008 23:12  |
Jakob Goldbach
Messages: 14
Registered: January 2008
|
Junior Member |
|
|
Hi,
I regularly have processes that gets stock eating all cpu. SysRq-p says
it is stock in __d_lookup+0x10b as seen in dmesg output below.
I run vanilla 2.6.18 with 028stab053 and the lustre filesystem. I also
run lustre on non-openvz kernel without problems, hence this mail to
this group.
I believe I've found where the problem is, but I'm not a kernel hacker
so I don't know what to do about this information.
I'd appreciate any hints on what to do next to get this solved.
Below is what I could find out.
Thanks,
Jakob
gdb find that the process is in the hlist_for_each_entry_rcu loop:
(gdb) list *__d_lookup+0x10b
0x12f0 is in __d_lookup (fs/dcache.c:1153).
1148 struct dentry *dentry, *found;
1149
1150 rcu_read_lock();
1151
1152 found = NULL;
1153 hlist_for_each_entry_rcu(dentry, node, head, d_hash) {
1154 struct qstr *qstr;
1155
1156 if (dentry->d_name.hash != hash)
1157 continue;
I believe this is the relevant part (0x12f0) of the disassembled object:
12e0: 4d 8b 24 24 mov (%r12),%r12
12e4: 4d 85 e4 test %r12,%r12
12e7: 74 2c je 1315 <__d_lookup+0x130>
12e9: 49 8b 04 24 mov (%r12),%rax
12ed: 0f 18 08 prefetcht0 (%rax)
12f0: 49 8d 5c 24 d8 lea 0xffffffffffffffd8(%r12),
%rbx
12f5: 8b 45 cc mov 0xffffffffffffffcc(%rbp),
%eax
12f8: 39 43 40 cmp %eax,0x40(%rbx)
12fb: 75 e3 jne 12e0 <__d_lookup+0xfb>
Dmesg after sysrq-p:
[186124.494329] SysRq: Show Regs
[186124.495218] ----------- IPI show regs -----------
[186124.496136] CPU 3, VCPU 0:1
[186124.496804] Modules linked in: simfs vznetdev vzethdev vzrst ip_nat
vzcpt ip_conntrack nfnetlink vzdquota vzmon vzdev xt_length ipt_ttl xt_
tcpmss ipt_TCPMSS iptable_mangle xt_multiport xt_limit ipt_tos
ipt_REJECT iptable_filter ip_tables x_tables 8021q osc mgc lustre lov
lquota mdc
ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding xfs
[186124.503636] Pid: 22699, comm: find Not tainted
2.6.18.8-openvz-028stab053-bnx2-1.6.7b-arpannounce1 #3 028stab053
[186124.505535] RIP: 0060:[<ffffffff8029b314>] [<ffffffff8029b314>]
__d_lookup+0x10b/0x142
[186124.507265] RSP: 0068:ffff810073d63bc8 EFLAGS: 00000282
[186124.508296] RAX: ffff8101016dc298 RBX: ffff8101016dc270 RCX:
0000000000000013
[186124.509768] RDX: 0000000000025ff5 RSI: 00c38320c56a5ff5 RDI:
ffff810118b056b0
[186124.511480] RBP: ffff810073d63c08 R08: ffff8100ac9e8000 R09:
ffff810118b056b0
[186124.512963] R10: 0000000000000000 R11: 0000000000000000 R12:
ffff8101016dc298
[186124.514452] R13: ffff810073d63e38 R14: ffff810118b056b0 R15:
ffff810073d63c78
[186124.515931] FS: 00002ba786cb56d0(0000) GS:ffff81012a693340(0000)
knlGS:0000000000000000
[186124.517538] CS: 0060 DS: 0000 ES: 0000 CR0: 0000000080050033
[186124.518587] CR2: 0000000000539938 CR3: 0000000073f06000 CR4:
00000000000006e0
[186124.520022]
[186124.520023] Call Trace:
[186124.521245] [<ffffffff8029105d>] do_lookup+0x2c/0x193
[186124.522363] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
[186124.523642] [<ffffffff8029374e>] link_path_walk+0x87/0x140
[186124.524818] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
[186124.526000] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
[186124.527156] [<ffffffff8028cecb>] vfs_lstat_fd+0x24/0x5a
[186124.528278] [<ffffffff8028cf23>] sys_newlstat+0x22/0x3c
[186124.529383] [<ffffffff80209902>] system_call+0x7e/0x83
[186124.530362] DWARF2 unwinder stuck at system_call+0x7e/0x83
[186124.531460] Leftover inexact backtrace:
[186124.532563]
|
|
|
|
| Re: Infinite loop in __d_lookup ? [message #30195 is a reply to message #30126] |
Thu, 15 May 2008 11:39  |
Pavel Emelianov
Messages: 1149
Registered: September 2006
|
Senior Member |
|
|
Jakob Goldbach wrote:
> Hi,
>
> I regularly have processes that gets stock eating all cpu. SysRq-p says
> it is stock in __d_lookup+0x10b as seen in dmesg output below.
If you can reproduce this in a reasonable time I can send you
a debugging patch to find out what's going on there.
Let's try with it?
> I run vanilla 2.6.18 with 028stab053 and the lustre filesystem. I also
> run lustre on non-openvz kernel without problems, hence this mail to
> this group.
>
> I believe I've found where the problem is, but I'm not a kernel hacker
> so I don't know what to do about this information.
>
> I'd appreciate any hints on what to do next to get this solved.
>
> Below is what I could find out.
>
> Thanks,
> Jakob
>
> gdb find that the process is in the hlist_for_each_entry_rcu loop:
>
> (gdb) list *__d_lookup+0x10b
> 0x12f0 is in __d_lookup (fs/dcache.c:1153).
> 1148 struct dentry *dentry, *found;
> 1149
> 1150 rcu_read_lock();
> 1151
> 1152 found = NULL;
> 1153 hlist_for_each_entry_rcu(dentry, node, head, d_hash) {
> 1154 struct qstr *qstr;
> 1155
> 1156 if (dentry->d_name.hash != hash)
> 1157 continue;
>
> I believe this is the relevant part (0x12f0) of the disassembled object:
>
> 12e0: 4d 8b 24 24 mov (%r12),%r12
> 12e4: 4d 85 e4 test %r12,%r12
> 12e7: 74 2c je 1315 <__d_lookup+0x130>
> 12e9: 49 8b 04 24 mov (%r12),%rax
> 12ed: 0f 18 08 prefetcht0 (%rax)
> 12f0: 49 8d 5c 24 d8 lea 0xffffffffffffffd8(%r12),
> %rbx
> 12f5: 8b 45 cc mov 0xffffffffffffffcc(%rbp),
> %eax
> 12f8: 39 43 40 cmp %eax,0x40(%rbx)
> 12fb: 75 e3 jne 12e0 <__d_lookup+0xfb>
>
>
> Dmesg after sysrq-p:
>
>
>
>
> [186124.494329] SysRq: Show Regs
> [186124.495218] ----------- IPI show regs -----------
> [186124.496136] CPU 3, VCPU 0:1
> [186124.496804] Modules linked in: simfs vznetdev vzethdev vzrst ip_nat
> vzcpt ip_conntrack nfnetlink vzdquota vzmon vzdev xt_length ipt_ttl xt_
> tcpmss ipt_TCPMSS iptable_mangle xt_multiport xt_limit ipt_tos
> ipt_REJECT iptable_filter ip_tables x_tables 8021q osc mgc lustre lov
> lquota mdc
> ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding xfs
> [186124.503636] Pid: 22699, comm: find Not tainted
> 2.6.18.8-openvz-028stab053-bnx2-1.6.7b-arpannounce1 #3 028stab053
> [186124.505535] RIP: 0060:[<ffffffff8029b314>] [<ffffffff8029b314>]
> __d_lookup+0x10b/0x142
> [186124.507265] RSP: 0068:ffff810073d63bc8 EFLAGS: 00000282
> [186124.508296] RAX: ffff8101016dc298 RBX: ffff8101016dc270 RCX:
> 0000000000000013
> [186124.509768] RDX: 0000000000025ff5 RSI: 00c38320c56a5ff5 RDI:
> ffff810118b056b0
> [186124.511480] RBP: ffff810073d63c08 R08: ffff8100ac9e8000 R09:
> ffff810118b056b0
> [186124.512963] R10: 0000000000000000 R11: 0000000000000000 R12:
> ffff8101016dc298
> [186124.514452] R13: ffff810073d63e38 R14: ffff810118b056b0 R15:
> ffff810073d63c78
> [186124.515931] FS: 00002ba786cb56d0(0000) GS:ffff81012a693340(0000)
> knlGS:0000000000000000
> [186124.517538] CS: 0060 DS: 0000 ES: 0000 CR0: 0000000080050033
> [186124.518587] CR2: 0000000000539938 CR3: 0000000073f06000 CR4:
> 00000000000006e0
> [186124.520022]
> [186124.520023] Call Trace:
> [186124.521245] [<ffffffff8029105d>] do_lookup+0x2c/0x193
> [186124.522363] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
> [186124.523642] [<ffffffff8029374e>] link_path_walk+0x87/0x140
> [186124.524818] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
> [186124.526000] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
> [186124.527156] [<ffffffff8028cecb>] vfs_lstat_fd+0x24/0x5a
> [186124.528278] [<ffffffff8028cf23>] sys_newlstat+0x22/0x3c
> [186124.529383] [<ffffffff80209902>] system_call+0x7e/0x83
> [186124.530362] DWARF2 unwinder stuck at system_call+0x7e/0x83
> [186124.531460] Leftover inexact backtrace:
> [186124.532563]
>
>
|
|
|
|
| Sv: Re: Infinite loop in __d_lookup ? [message #30198 is a reply to message #30126] |
Thu, 15 May 2008 14:39 |
Jakob Goldbach
Messages: 14
Registered: January 2008
|
Junior Member |
|
|
That would be great. Thanks.There are usually a few days between it gets stuck.
/jakob
- oprindelig besked -
Emne: Re: [Users] Infinite loop in __d_lookup ?
Fra: Pavel Emelyanov <xemul@openvz.org>
Dato: 15-05-2008 12:34
Jakob Goldbach wrote:
> Hi,
>
> I regularly have processes that gets stock eating all cpu. SysRq-p says
> it is stock in __d_lookup+0x10b as seen in dmesg output below.
If you can reproduce this in a reasonable time I can send you
a debugging patch to find out what's going on there.
Let's try with it?
> I run vanilla 2.6.18 with 028stab053 and the lustre filesystem. I also
> run lustre on non-openvz kernel without problems, hence this mail to
> this group.
>
> I believe I've found where the problem is, but I'm not a kernel hacker
> so I don't know what to do about this information.
>
> I'd appreciate any hints on what to do next to get this solved.
>
> Below is what I could find out.
>
> Thanks,
> Jakob
>
> gdb find that the process is in the hlist_for_each_entry_rcu loop:
>
> (gdb) list *__d_lookup+0x10b
> 0x12f0 is in __d_lookup (fs/dcache.c:1153).
> 1148 struct dentry *dentry, *found;
> 1149
> 1150 rcu_read_lock();
> 1151
> 1152 found = NULL;
> 1153 hlist_for_each_entry_rcu(dentry, node, head, d_hash) {
> 1154 struct qstr *qstr;
> 1155
> 1156 if (dentry->d_name.hash != hash)
> 1157 continue;
>
> I believe this is the relevant part (0x12f0) of the disassembled object:
>
> 12e0: 4d 8b 24 24 mov (%r12),%r12
> 12e4: 4d 85 e4 test %r12,%r12
> 12e7: 74 2c je 1315 <__d_lookup+0x130>
> 12e9: 49 8b 04 24 mov (%r12),%rax
> 12ed: 0f 18 08 prefetcht0 (%rax)
> 12f0: 49 8d 5c 24 d8 lea 0xffffffffffffffd8(%r12),
> %rbx
> 12f5: 8b 45 cc mov 0xffffffffffffffcc(%rbp),
> %eax
> 12f8: 39 43 40 cmp %eax,0x40(%rbx)
> 12fb: 75 e3 jne 12e0 <__d_lookup+0xfb>
>
>
> Dmesg after sysrq-p:
>
>
>
>
> [186124.494329] SysRq: Show Regs
> [186124.495218] ----------- IPI show regs -----------
> [186124.496136] CPU 3, VCPU 0:1
> [186124.496804] Modules linked in: simfs vznetdev vzethdev vzrst ip_nat
> vzcpt ip_conntrack nfnetlink vzdquota vzmon vzdev xt_length ipt_ttl xt_
> tcpmss ipt_TCPMSS iptable_mangle xt_multiport xt_limit ipt_tos
> ipt_REJECT iptable_filter ip_tables x_tables 8021q osc mgc lustre lov
> lquota mdc
> ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding xfs
> [186124.503636] Pid: 22699, comm: find Not tainted
> 2.6.18.8-openvz-028stab053-bnx2-1.6.7b-arpannounce1 #3 028stab053
> [186124.505535] RIP: 0060:[<ffffffff8029b314>] [<ffffffff8029b314>]
> __d_lookup+0x10b/0x142
> [186124.507265] RSP: 0068:ffff810073d63bc8 EFLAGS: 00000282
> [186124.508296] RAX: ffff8101016dc298 RBX: ffff8101016dc270 RCX:
> 0000000000000013
> [186124.509768] RDX: 0000000000025ff5 RSI: 00c38320c56a5ff5 RDI:
> ffff810118b056b0
> [186124.511480] RBP: ffff810073d63c08 R08: ffff8100ac9e8000 R09:
> ffff810118b056b0
> [186124.512963] R10: 0000000000000000 R11: 0000000000000000 R12:
> ffff8101016dc298
> [186124.514452] R13: ffff810073d63e38 R14: ffff810118b056b0 R15:
> ffff810073d63c78
> [186124.515931] FS: 00002ba786cb56d0(0000) GS:ffff81012a693340(0000)
> knlGS:0000000000000000
> [186124.517538] CS: 0060 DS: 0000 ES: 0000 CR0: 0000000080050033
> [186124.518587] CR2: 0000000000539938 CR3: 0000000073f06000 CR4:
> 00000000000006e0
> [186124.520022]
> [186124.520023] Call Trace:
> [186124.521245] [<ffffffff8029105d>] do_lookup+0x2c/0x193
> [186124.522363] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
> [186124.523642] [<ffffffff8029374e>] link_path_walk+0x87/0x140
> [186124.524818] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
> [186124.526000] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
> [186124.527156] [<ffffffff8028cecb>] vfs_lstat_fd+0x24/0x5a
> [186124.528278] [<ffffffff8028cf23>] sys_newlstat+0x22/0x3c
> [186124.529383] [<ffffffff80209902>] system_call+0x7e/0x83
> [186124.530362] DWARF2 unwinder stuck at system_call+0x7e/0x83
> [186124.531460] Leftover inexact backtrace:
> [186124.532563]
>
>
|
|
|
|
| Re: Sv: Re: Infinite loop in __d_lookup ? [message #30199 is a reply to message #30198] |
Thu, 15 May 2008 16:21 |
Pavel Emelianov
Messages: 1149
Registered: September 2006
|
Senior Member |
|
|
Jakob Goldbach wrote:
> That would be great. Thanks.There are usually a few days between it gets stuck.
Ok. Happily, I've managed to invent what I need to check first
before it's too late here in Moscow ;)
I presume, that the infinite loop is really somewhere near the
__d_lookup. Please, apply this patch in attach (I made it against
2.6.18-028stab053.5, but should fit OK all the other 028stab053
releases) and check for warnings in dmesg ;)
Let's see whether this is really __d_lookup.
> /jakob
> - oprindelig besked -
> Emne: Re: [Users] Infinite loop in __d_lookup ?
> Fra: Pavel Emelyanov <xemul@openvz.org>
> Dato: 15-05-2008 12:34
>
> Jakob Goldbach wrote:
>> Hi,
>>
>> I regularly have processes that gets stock eating all cpu. SysRq-p says
>> it is stock in __d_lookup+0x10b as seen in dmesg output below.
>
> If you can reproduce this in a reasonable time I can send you
> a debugging patch to find out what's going on there.
>
> Let's try with it?
>
>> I run vanilla 2.6.18 with 028stab053 and the lustre filesystem. I also
>> run lustre on non-openvz kernel without problems, hence this mail to
>> this group.
>>
>> I believe I've found where the problem is, but I'm not a kernel hacker
>> so I don't know what to do about this information.
>>
>> I'd appreciate any hints on what to do next to get this solved.
>>
>> Below is what I could find out.
>>
>> Thanks,
>> Jakob
>>
>> gdb find that the process is in the hlist_for_each_entry_rcu loop:
>>
>> (gdb) list *__d_lookup+0x10b
>> 0x12f0 is in __d_lookup (fs/dcache.c:1153).
>> 1148 struct dentry *dentry, *found;
>> 1149
>> 1150 rcu_read_lock();
>> 1151
>> 1152 found = NULL;
>> 1153 hlist_for_each_entry_rcu(dentry, node, head, d_hash) {
>> 1154 struct qstr *qstr;
>> 1155
>> 1156 if (dentry->d_name.hash != hash)
>> 1157 continue;
>>
>> I believe this is the relevant part (0x12f0) of the disassembled object:
>>
>> 12e0: 4d 8b 24 24 mov (%r12),%r12
>> 12e4: 4d 85 e4 test %r12,%r12
>> 12e7: 74 2c je 1315 <__d_lookup+0x130>
>> 12e9: 49 8b 04 24 mov (%r12),%rax
>> 12ed: 0f 18 08 prefetcht0 (%rax)
>> 12f0: 49 8d 5c 24 d8 lea 0xffffffffffffffd8(%r12),
>> %rbx
>> 12f5: 8b 45 cc mov 0xffffffffffffffcc(%rbp),
>> %eax
>> 12f8: 39 43 40 cmp %eax,0x40(%rbx)
>> 12fb: 75 e3 jne 12e0 <__d_lookup+0xfb>
>>
>>
>> Dmesg after sysrq-p:
>>
>>
>>
>>
>> [186124.494329] SysRq: Show Regs
>> [186124.495218] ----------- IPI show regs -----------
>> [186124.496136] CPU 3, VCPU 0:1
>> [186124.496804] Modules linked in: simfs vznetdev vzethdev vzrst ip_nat
>> vzcpt ip_conntrack nfnetlink vzdquota vzmon vzdev xt_length ipt_ttl xt_
>> tcpmss ipt_TCPMSS iptable_mangle xt_multiport xt_limit ipt_tos
>> ipt_REJECT iptable_filter ip_tables x_tables 8021q osc mgc lustre lov
>> lquota mdc
>> ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding xfs
>> [186124.503636] Pid: 22699, comm: find Not tainted
>> 2.6.18.8-openvz-028stab053-bnx2-1.6.7b-arpannounce1 #3 028stab053
>> [186124.505535] RIP: 0060:[<ffffffff8029b314>] [<ffffffff8029b314>]
>> __d_lookup+0x10b/0x142
>> [186124.507265] RSP: 0068:ffff810073d63bc8 EFLAGS: 00000282
>> [186124.508296] RAX: ffff8101016dc298 RBX: ffff8101016dc270 RCX:
>> 0000000000000013
>> [186124.509768] RDX: 0000000000025ff5 RSI: 00c38320c56a5ff5 RDI:
>> ffff810118b056b0
>> [186124.511480] RBP: ffff810073d63c08 R08: ffff8100ac9e8000 R09:
>> ffff810118b056b0
>> [186124.512963] R10: 0000000000000000 R11: 0000000000000000 R12:
>> ffff8101016dc298
>> [186124.514452] R13: ffff810073d63e38 R14: ffff810118b056b0 R15:
>> ffff810073d63c78
>> [186124.515931] FS: 00002ba786cb56d0(0000) GS:ffff81012a693340(0000)
>> knlGS:0000000000000000
>> [186124.517538] CS: 0060 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [186124.518587] CR2: 0000000000539938 CR3: 0000000073f06000 CR4:
>> 00000000000006e0
>> [186124.520022]
>> [186124.520023] Call Trace:
>> [186124.521245] [<ffffffff8029105d>] do_lookup+0x2c/0x193
>> [186124.522363] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
>> [186124.523642] [<ffffffff8029374e>] link_path_walk+0x87/0x140
>> [186124.524818] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
>> [186124.526000] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
>> [186124.527156] [<ffffffff8028cecb>] vfs_lstat_fd+0x24/0x5a
>> [186124.528278] [<ffffffff8028cf23>] sys_newlstat+0x22/0x3c
>> [186124.529383] [<ffffffff80209902>] system_call+0x7e/0x83
>> [186124.530362] DWARF2 unwinder stuck at system_call+0x7e/0x83
>> [186124.531460] Leftover inexact backtrace:
>> [186124.532563]
>>
>>
--- ./fs/dcache.c.loopdebug 2008-05-15 20:09:04.000000000 +0400
+++ ./fs/dcache.c 2008-05-15 20:16:19.000000000 +0400
@@ -1128,12 +1128,24 @@ struct dentry * d_lookup(struct dentry *
{
struct dentry * dentry = NULL;
unsigned long seq;
+ unsigned long loops = 0;
+ static int once = 1;
do {
seq = read_seqbegin(&rename_lock);
dentry = __d_lookup(parent, name);
if (dentry)
break;
+
+ if (loops++ > 200) {
+ printk("%s: Abort on 200 seq-retry iteration\n",
+ __func__);
+ if (once) {
+ once = 0;
+ dump_stack();
+ }
+ break;
+ }
} while (read_seqretry(&rename_lock, seq));
return dentry;
}
@@ -1146,6 +1158,8 @@ struct dentry * __d_lookup(struct dentry
struct hlist_head *head = d_hash(parent,hash);
struct hlist_node *node;
struct dentry *dentry, *found;
+ unsigned long loops = 0;
+ static int once = 1;
rcu_read_lock();
@@ -1154,9 +1168,9 @@ struct dentry * __d_lookup(struct dentry
struct qstr *qstr;
if (dentry->d_name.hash != hash)
- continue;
+ goto next_nolock;
if (dentry->d_parent != parent)
- continue;
+ goto next_nolock;
spin_lock(&dentry->d_lock);
@@ -1193,6 +1207,16 @@ struct dentry * __d_lookup(struct dentry
break;
next:
spin_unlock(&dentry->d_lock);
+next_nolock:
+ if (loops++ > 5000) {
+ printk("%s: Abort on 5000 loop iteration in a chain\n",
+ __func__);
+ if (once) {
+ once = 0;
+ dump_stack();
+ }
+ break;
+ }
}
rcu_read_unlock();
|
|
|
|
| Re: Sv: Re: Infinite loop in __d_lookup ? [message #30309 is a reply to message #30199] |
Tue, 20 May 2008 19:22 |
Jakob Goldbach
Messages: 14
Registered: January 2008
|
Junior Member |
|
|
Hi Pavel (and others)
Loop is in __d_lookup as trace show. Any ideas ?
/Jakob
[76893.524305] __d_lookup: Abort on 5000 loop iteration in a chain
[76893.525411]
[76893.525412] Call Trace:
[76893.526538] [<ffffffff8020ae20>] show_trace+0xae/0x360
[76893.527619] [<ffffffff8020b0e7>] dump_stack+0x15/0x17
[76893.528677] [<ffffffff8029b343>] __d_lookup+0x13a/0x187
[76893.529779] [<ffffffff8029105d>] do_lookup+0x2c/0x193
[76893.530846] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
[76893.532066] [<ffffffff8029374e>] link_path_walk+0x87/0x140
[76893.533230] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
[76893.534404] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
[76893.535559] [<ffffffff80282a09>] sys_faccessat+0xf4/0x1b5
[76893.536705] [<ffffffff80282add>] sys_access+0x13/0x15
[76893.537873] [<ffffffff80209902>] system_call+0x7e/0x83
[76893.538898] DWARF2 unwinder stuck at system_call+0x7e/0x83
[76893.539964] Leftover inexact backtrace:
[76893.540768]
[76893.541202] __d_lookup: Abort on 5000 loop iteration in a chain
On Thu, 2008-05-15 at 20:21 +0400, Pavel Emelyanov wrote:
> Jakob Goldbach wrote:
> > That would be great. Thanks.There are usually a few days between it gets stuck.
>
> Ok. Happily, I've managed to invent what I need to check first
> before it's too late here in Moscow ;)
>
> I presume, that the infinite loop is really somewhere near the
> __d_lookup. Please, apply this patch in attach (I made it against
> 2.6.18-028stab053.5, but should fit OK all the other 028stab053
> releases) and check for warnings in dmesg ;)
>
> Let's see whether this is really __d_lookup.
>
> > /jakob
> > - oprindelig besked -
> > Emne: Re: [Users] Infinite loop in __d_lookup ?
> > Fra: Pavel Emelyanov <xemul@openvz.org>
> > Dato: 15-05-2008 12:34
> >
> > Jakob Goldbach wrote:
> >> Hi,
> >>
> >> I regularly have processes that gets stock eating all cpu. SysRq-p says
> >> it is stock in __d_lookup+0x10b as seen in dmesg output below.
> >
> > If you can reproduce this in a reasonable time I can send you
> > a debugging patch to find out what's going on there.
> >
> > Let's try with it?
> >
> >> I run vanilla 2.6.18 with 028stab053 and the lustre filesystem. I also
> >> run lustre on non-openvz kernel without problems, hence this mail to
> >> this group.
> >>
> >> I believe I've found where the problem is, but I'm not a kernel hacker
> >> so I don't know what to do about this information.
> >>
> >> I'd appreciate any hints on what to do next to get this solved.
> >>
> >> Below is what I could find out.
> >>
> >> Thanks,
> >> Jakob
> >>
> >> gdb find that the process is in the hlist_for_each_entry_rcu loop:
> >>
> >> (gdb) list *__d_lookup+0x10b
> >> 0x12f0 is in __d_lookup (fs/dcache.c:1153).
> >> 1148 struct dentry *dentry, *found;
> >> 1149
> >> 1150 rcu_read_lock();
> >> 1151
> >> 1152 found = NULL;
> >> 1153 hlist_for_each_entry_rcu(dentry, node, head, d_hash) {
> >> 1154 struct qstr *qstr;
> >> 1155
> >> 1156 if (dentry->d_name.hash != hash)
> >> 1157 continue;
> >>
> >> I believe this is the relevant part (0x12f0) of the disassembled object:
> >>
> >> 12e0: 4d 8b 24 24 mov (%r12),%r12
> >> 12e4: 4d 85 e4 test %r12,%r12
> >> 12e7: 74 2c je 1315 <__d_lookup+0x130>
> >> 12e9: 49 8b 04 24 mov (%r12),%rax
> >> 12ed: 0f 18 08 prefetcht0 (%rax)
> >> 12f0: 49 8d 5c 24 d8 lea 0xffffffffffffffd8(%r12),
> >> %rbx
> >> 12f5: 8b 45 cc mov 0xffffffffffffffcc(%rbp),
> >> %eax
> >> 12f8: 39 43 40 cmp %eax,0x40(%rbx)
> >> 12fb: 75 e3 jne 12e0 <__d_lookup+0xfb>
> >>
> >>
> >> Dmesg after sysrq-p:
> >>
> >>
> >>
> >>
> >> [186124.494329] SysRq: Show Regs
> >> [186124.495218] ----------- IPI show regs -----------
> >> [186124.496136] CPU 3, VCPU 0:1
> >> [186124.496804] Modules linked in: simfs vznetdev vzethdev vzrst ip_nat
> >> vzcpt ip_conntrack nfnetlink vzdquota vzmon vzdev xt_length ipt_ttl xt_
> >> tcpmss ipt_TCPMSS iptable_mangle xt_multiport xt_limit ipt_tos
> >> ipt_REJECT iptable_filter ip_tables x_tables 8021q osc mgc lustre lov
> >> lquota mdc
> >> ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding xfs
> >> [186124.503636] Pid: 22699, comm: find Not tainted
> >> 2.6.18.8-openvz-028stab053-bnx2-1.6.7b-arpannounce1 #3 028stab053
> >> [186124.505535] RIP: 0060:[<ffffffff8029b314>] [<ffffffff8029b314>]
> >> __d_lookup+0x10b/0x142
> >> [186124.507265] RSP: 0068:ffff810073d63bc8 EFLAGS: 00000282
> >> [186124.508296] RAX: ffff8101016dc298 RBX: ffff8101016dc270 RCX:
> >> 0000000000000013
> >> [186124.509768] RDX: 0000000000025ff5 RSI: 00c38320c56a5ff5 RDI:
> >> ffff810118b056b0
> >> [186124.511480] RBP: ffff810073d63c08 R08: ffff8100ac9e8000 R09:
> >> ffff810118b056b0
> >> [186124.512963] R10: 0000000000000000 R11: 0000000000000000 R12:
> >> ffff8101016dc298
> >> [186124.514452] R13: ffff810073d63e38 R14: ffff810118b056b0 R15:
> >> ffff810073d63c78
> >> [186124.515931] FS: 00002ba786cb56d0(0000) GS:ffff81012a693340(0000)
> >> knlGS:0000000000000000
> >> [186124.517538] CS: 0060 DS: 0000 ES: 0000 CR0: 0000000080050033
> >> [186124.518587] CR2: 0000000000539938 CR3: 0000000073f06000 CR4:
> >> 00000000000006e0
> >> [186124.520022]
> >> [186124.520023] Call Trace:
> >> [186124.521245] [<ffffffff8029105d>] do_lookup+0x2c/0x193
> >> [186124.522363] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
> >> [186124.523642] [<ffffffff8029374e>] link_path_walk+0x87/0x140
> >> [186124.524818] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
> >> [186124.526000] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
> >> [186124.527156] [<ffffffff8028cecb>] vfs_lstat_fd+0x24/0x5a
> >> [186124.528278] [<ffffffff8028cf23>] sys_newlstat+0x22/0x3c
> >> [186124.529383] [<ffffffff80209902>] system_call+0x7e/0x83
> >> [186124.530362] DWARF2 unwinder stuck at system_call+0x7e/0x83
> >> [186124.531460] Leftover inexact backtrace:
> >> [186124.532563]
> >>
> >>
> plain text document attachment (diff-dlookup-lockup-debug)
> --- ./fs/dcache.c.loopdebug 2008-05-15 20:09:04.000000000 +0400
> +++ ./fs/dcache.c 2008-05-15 20:16:19.000000000 +0400
> @@ -1128,12 +1128,24 @@ struct dentry * d_lookup(struct dentry *
> {
> struct dentry * dentry = NULL;
> unsigned long seq;
> + unsigned long loops = 0;
> + static int once = 1;
>
> do {
> seq = read_seqbegin(&rename_lock);
> dentry = __d_lookup(parent, name);
> if (dentry)
> break;
> +
> + if (loops++ > 200) {
> + printk("%s: Abort on 200 seq-retry iteration\n",
> + __func__);
> + if (once) {
> + once = 0;
> + dump_stack();
> + }
> + break;
> + }
> } while (read_seqretry(&rename_lock, seq));
> return dentry;
> }
> @@ -1146,6 +1158,8 @@ struct dentry * __d_lookup(struct dentry
> struct hlist_head *head = d_hash(parent,hash);
> struct hlist_node *node;
> struct dentry *dentry, *found;
> + unsigned long loops = 0;
> + static int once = 1;
>
> rcu_read_lock();
>
> @@ -1154,9 +1168,9 @@ struct dentry * __d_lookup(struct dentry
> struct qstr *qstr;
>
> if (dentry->d_name.hash != hash)
> - continue;
> + goto next_nolock;
> if (dentry->d_parent != parent)
> - continue;
> + goto next_nolock;
>
> spin_lock(&dentry->d_lock);
>
> @@ -1193,6 +1207,16 @@ struct dentry * __d_lookup(struct dentry
> break;
> next:
> spin_unlock(&dentry->d_lock);
> +next_nolock:
> + if (loops++ > 5000) {
> + printk("%s: Abort on 5000 loop iteration in a chain\n",
> + __func__);
> + if (once) {
> + once = 0;
> + dump_stack();
> + }
> + break;
> + }
> }
> rcu_read_unlock();
>
|
|
|
|
|
|
|
|
|
|
| Re: Sv: Re: Infinite loop in __d_lookup ? [message #30454 is a reply to message #30309] |
Wed, 21 May 2008 11:46 |
xemul
Messages: 248
Registered: November 2005
|
Senior Member |
|
|
Jakob Goldbach wrote:
> Hi Pavel (and others)
>
> Loop is in __d_lookup as trace show. Any ideas ?
Well. It this really happens, then we have a corrupted
chain of dentries. Let's try to catch this corruption
early.
Here's the debugging patch that checks the chain to be
consistent when entries are added/removed from it.
Thanks for your help, Jakob :)
I've added a BUG with this issue - please, continue
communication via bugzilla since now:
http://bugzilla.openvz.org/show_bug.cgi?id=895
> /Jakob
>
>
> [76893.524305] __d_lookup: Abort on 5000 loop iteration in a chain
> [76893.525411]
> [76893.525412] Call Trace:
> [76893.526538] [<ffffffff8020ae20>] show_trace+0xae/0x360
> [76893.527619] [<ffffffff8020b0e7>] dump_stack+0x15/0x17
> [76893.528677] [<ffffffff8029b343>] __d_lookup+0x13a/0x187
> [76893.529779] [<ffffffff8029105d>] do_lookup+0x2c/0x193
> [76893.530846] [<ffffffff80293122>] __link_path_walk+0xb07/0x10ac
> [76893.532066] [<ffffffff8029374e>] link_path_walk+0x87/0x140
> [76893.533230] [<ffffffff80293c76>] do_path_lookup+0x2d3/0x2f8
> [76893.534404] [<ffffffff802945e2>] __user_walk_fd+0x41/0x62
> [76893.535559] [<ffffffff80282a09>] sys_faccessat+0xf4/0x1b5
> [76893.536705] [<ffffffff80282add>] sys_access+0x13/0x15
> [76893.537873] [<ffffffff80209902>] system_call+0x7e/0x83
> [76893.538898] DWARF2 unwinder stuck at system_call+0x7e/0x83
> [76893.539964] Leftover inexact backtrace:
> [76893.540768]
> [76893.541202] __d_lookup: Abort on 5000 loop iteration in a chain
--- ./fs/dcache.c.ddebug2 2008-05-21 14:52:15.000000000 +0400
+++ ./fs/dcache.c 2008-05-21 15:10:06.000000000 +0400
@@ -1350,6 +1350,18 @@ static void __d_rehash(struct dentry * e
{
entry->d_flags &= ~DCACHE_UNHASHED;
+ if (!spin_is_locked(&dcache_lock)) {
+ printk(KERN_ERR "Dcache lock is not taken on add\n");
+ dump_stack();
+ } else if (list->first != NULL &&
+ list->first->pprev != &list->first) {
+ printk(KERN_ERR "Dcache chain corruption:\n");
+ printk(KERN_ERR "Chain %p --next-> %p\n",
+ list, list->first);
+ printk(KERN_ERR "First %p <-pprev- %p\n",
+ list->first, list->first->pprev);
+ dump_stack();
+ }
hlist_add_head_rcu(&entry->d_hash, list);
}
@@ -1443,6 +1455,32 @@ static void switch_names(struct dentry *
* dcache entries should not be moved in this way.
*/
+void d_node_check(struct hlist_node *n)
+{
+ if (!spin_is_locked(&dcache_lock)) {
+ printk(KERN_ERR "Dcache lock is not taken on del\n");
+ dump_stack();
+ }
+
+ if (n->next != NULL &&
+ n->next->pprev != &n->next) {
+ printk(KERN_ERR "Dentry d_hash node corruption(m1):\n");
+ printk(KERN_ERR "Node %p --next-> %p\n",
+ n, n->next);
+ printk(KERN_ERR "Next %p <-pprev- %p\n",
+ n->next, n->next->pprev);
+ dump_stack();
+ }
+
+ if (*n->pprev != n) {
+ printk(KERN_ERR "Dentry d_hash node corruption(m2):\n");
+ printk(KERN_ERR "Node %p <-pprev- %p -> %p\n",
+ n, n->pprev, *n->pprev);
+ dump_stack();
+ }
+}
+EXPORT_SYMBOL(d_node_check);
+
void d_move(struct dentry * dentry, struct dentry * target)
{
struct hlist_head *list;
@@ -1467,6 +1505,7 @@ void d_move(struct dentry * dentry, stru
if (dentry->d_flags & DCACHE_UNHASHED)
goto already_unhashed;
+ d_node_check(&dentry->d_hash);
hlist_del_rcu(&dentry->d_hash);
already_unhashed:
--- ./include/linux/dcache.h.ddebug2 2008-05-21 14:50:31.000000000 +0400
+++ ./include/linux/dcache.h 2008-05-21 15:09:03.000000000 +0400
@@ -203,10 +203,13 @@ extern spinlock_t dcache_lock;
* __d_drop requires dentry->d_lock.
*/
+void d_node_check(struct hlist_node *n);
+
static inline void __d_drop(struct dentry *dentry)
{
if (!(dentry->d_flags & DCACHE_UNHASHED)) {
dentry->d_flags |= DCACHE_UNHASHED;
+ d_node_check(&dentry->d_hash);
hlist_del_rcu(&dentry->d_hash);
}
}
|
|
|
|
Goto Forum:
Current Time: Sat Oct 05 12:42:02 GMT 2024
Total time taken to generate the page: 0.06337 seconds
|
OpenVZ Forum
Members
Search
Help
Register
Login
Home
