<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html; charset=ISO-8859-1"
http-equiv="Content-Type">
<title></title>
</head>
<body bgcolor="#ffffff" text="#000000">
On 9/14/10 5:21 PM, Temple Jason wrote:
<blockquote
cite="mid:AB48A31C4EC97E498F4235B7CEF74A194D3248C613@MBX00.d.ethz.ch"
type="cite">
<meta http-equiv="Content-Type" content="text/html;
charset=ISO-8859-1">
<meta name="Generator" content="Microsoft Word 12 (filtered
medium)">
<style>
<!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;}
@page Section1
{size:612.0pt 792.0pt;
margin:72.0pt 72.0pt 72.0pt 72.0pt;}
div.Section1
{page:Section1;}
-->
</style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
<div class="Section1">
<p class="MsoNormal">Hello,<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I have recently upgraded my lustre
filesystem from 1.8.3 to
1.8.4. The first day we brought our system online with the
new version, we
started seeing clients getting stuck in this soft lockup
loop. The load shoots
up over 120, and eventually the node becomes unusable and
requires a hard
reset. I’ve seen loops like this on the server side in
previous lustre
versions, but to have it happen on the client is completely
new. Here is a bit
of what I see in the logs:<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel: LustreError:
27016:0:(statahead.c:289:ll_sai_entry_fini())
ASSERTION(sa_is_stopped(sai))
failed<br>
</p>
</div>
</blockquote>
The soft lockup is caused by this ASSERTION, because when such
ASSERTION triggered, the thread holds a spin_lock, then caused other
threads busy waiting for such spin_lock.<br>
<br>
<blockquote
cite="mid:AB48A31C4EC97E498F4235B7CEF74A194D3248C613@MBX00.d.ethz.ch"
type="cite">
<div class="Section1">
<p class="MsoNormal"><o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel: LustreError:
27016:0:(statahead.c:289:ll_sai_entry_fini()) LBUG<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel: Pid: 27016,
comm: athena.py<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel: Call Trace:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff885cf6a1>]
libcfs_debug_dumpstack+0x51/0x60 [libcfs]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff885cfbda>]
lbug_with_loc+0x7a/0xd0 [libcfs]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff885d7f00>]
tracefile_init+0x0/0x110 [libcfs]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff889247e9>]
ll_statahead_exit+0x409/0x500 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8008a4b4>]
default_wake_function+0x0/0xe<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff888d2f2e>]
ll_intent_drop_lock+0x8e/0xb0 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8891c2bb>]
ll_lookup_it+0x30b/0x7c0 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff888e250d>]
__ll_inode_revalidate_it+0x5bd/0x650 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff886f34f4>]
ldlm_lock_add_to_lru+0x74/0xe0 [ptlrpc]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff88919431>]
ll_convert_intent+0xb1/0x170 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8891d4c7>]
ll_lookup_nd+0x207/0x400 [lustre]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8002229b>]
d_alloc+0x174/0x1a9<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8000cc40>]
do_lookup+0xe5/0x1e6<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff80009fce>]
__link_path_walk+0xa01/0xf42<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8000e803>]
link_path_walk+0x5c/0xe5<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff80034cd4>]
vfs_readdir+0x94/0xa9<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff800f4fa9>]
compat_sys_getdents+0xaf/0xbd<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8000c9df>]
do_path_lookup+0x270/0x2e8<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff800123f7>]
getname+0x15b/0x1c1<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff80023318>]
__user_walk_fd+0x37/0x4c<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff800320b8>]
sys_faccessat+0xe4/0x18d<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff80034cd4>]
vfs_readdir+0x94/0xa9<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff800f4fa9>]
compat_sys_getdents+0xaf/0xbd<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8006149b>]
sysenter_do_call+0x1b/0x67<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:
[<ffffffff8002c205>]
dummy_inode_permission+0x0/0x3<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:39 wn122 kernel: LustreError:
dumping log to
/tmp/lustre-log.1284405099.27016<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:44 wn122 dhclient: DHCPREQUEST
on eth0 to
148.187.67.113 port 67<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: BUG: soft
lockup - CPU#3 stuck
for 10s! [ptlrpcd:31817]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: CPU 3:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Modules
linked in: mgc(U)
lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U) ptlrpc(U)
obdclass(U)
lnet(U) lvfs(U) libcfs(U) nfs fscache nfs_acl loc<o:p></o:p></p>
<p class="MsoNormal">kd sunrpc bonding(U)
ip_conntrack_netbios_ns ipt_REJECT
xt_tcpudp xt_state iptable_filter iptable_nat ip_nat
ip_conntrack nfnetlink
iptable_mangle ip_tables x_tables rdma_ucm(U) ib<o:p></o:p></p>
<p class="MsoNormal">_sdp(U) rdma_cm(U) iw_cm(U) ib_addr(U)
ib_ipoib(U)
ipoib_helper(U) ib_cm(U) ipv6 xfrm_nalgo crypto_api
ib_uverbs(U) ib_umad(U)
mlx4_vnic(U) ib_sa(U) mlx4_ib(U) ib_mthca(U) ib_mad(U<o:p></o:p></p>
<p class="MsoNormal">) ib_core(U) dm_multipath scsi_dh video
hwmon backlight sbs
i2c_ec button battery asus_acpi acpi_memhotplug ac parport_pc
lp parport joydev
sg i2c_i801 i2c_core e1000e shpchp mlx4_<o:p></o:p></p>
<p class="MsoNormal">core(U) pcspkr dm_raid45 dm_message
dm_region_hash
dm_mem_cache dm_snapshot dm_zero dm_mirror dm_log dm_mod
ata_piix libata sd_mod
scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Pid: 31817,
comm: ptlrpcd Tainted:
G 2.6.18-128.7.1.el5 #1<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RIP:
0010:[<ffffffff80064cb7>] [<ffffffff80064cb7>]
.text.lock.spinlock+0x5/0x30<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RSP:
0018:ffff8101ec177cb8
EFLAGS: 00000282<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RAX:
000000000000004f RBX:
0000000000000000 RCX: 0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RDX:
ffff81035956b480 RSI:
ffff810253c2d400 RDI: ffff810552ccb500<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RBP:
ffff810192294000 R08:
5a5a5a5a5a5a5a5a R09: 5a5a5a5a5a5a5a5a<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: R10:
5a5a5a5a5a5a5a5a R11:
5a5a5a5a5a5a5a5a R12: 0000000000000038<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: R13:
ffff81045b0150c0 R14:
ffff81067fc57000 R15: ffffffff886f5168<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: FS:
00002b5af649d240(0000)
GS:ffff81010c4c8e40(0000) knlGS:0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: CS: 0010 DS:
0000 ES: 0000
CR0: 000000008005003b<o:p></o:p></p>
<p class="MsoNormal"><span lang="IT-CH">Sep 13 21:11:49 wn122
kernel: CR2:
0000000008183094 CR3: 0000000000201000 CR4: 00000000000006e0<o:p></o:p></span></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Call Trace:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff889249dc>]
:lustre:ll_statahead_interpret+0xfc/0x5b0<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88861779>]
:mdc:mdc_intent_getattr_async_interpret+0x459/0x490<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88729246>]
:ptlrpc:ptlrpc_check_set+0x1186/0x1440<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8004ac1b>]
try_to_del_timer_sync+0x51/0x5a<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8875d05d>]
:ptlrpc:ptlrpcd_check+0xdd/0x1f0<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff80095004>]
process_timeout+0x0/0x5<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8875d9a1>]
:ptlrpc:ptlrpcd+0x1b1/0x259<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8008a4b4>]
default_wake_function+0x0/0xe<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8005dfb1>]
child_rip+0xa/0x11<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8875d7f0>]
:ptlrpc:ptlrpcd+0x0/0x259<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8005dfa7>]
child_rip+0x0/0x11<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: BUG: soft
lockup - CPU#0 stuck
for 10s! [ll_sa_27016:28593]<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: CPU 0:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Modules
linked in: mgc(U)
lustre(U) lov(U) mdc(U) lquota(U) osc(U) ko2iblnd(U) ptlrpc(U)
obdclass(U)
lnet(U) lvfs(U) libcfs(U) nfs fscache nfs_acl lockd sunrpc
bonding(U)
ip_conntrack_netbios_ns ipt_REJECT xt_tcpudp xt_state
iptable_filter
iptable_nat ip_nat ip_conntrack nfnetlink iptable_mangle
ip_tables x_tables
rdma_ucm(U) ib_sdp(U) rdma_cm(U) iw_cm(U) ib_addr(U)
ib_ipoib(U)
ipoib_helper(U) ib_cm(U) ipv6 xfrm_nalgo crypto_api
ib_uverbs(U) ib_umad(U)
mlx4_vnic(U) ib_sa(U) mlx4_ib(U) ib_mthca(U) ib_mad(U)
ib_core(U) dm_multipath
scsi_dh video hwmon backlight sbs i2c_ec button battery
asus_acpi
acpi_memhotplug ac parport_pc lp parport joydev sg i2c_i801
i2c_core e1000e
shpchp mlx4_core(U) pcspkr dm_raid45 dm_message dm_region_hash
dm_mem_cache
dm_snapshot dm_zero dm_mirror dm_log dm_mod ata_piix libata
sd_mod scsi_mod
ext3 jbd uhci_hcd ohci_hcd ehci_hcd<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Pid: 28593,
comm: ll_sa_27016
Tainted: G 2.6.18-128.7.1.el5 #1<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RIP:
0010:[<ffffffff80064cb4>] [<ffffffff80064cb4>]
.text.lock.spinlock+0x2/0x30<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RSP:
0000:ffff810251edfcf8
EFLAGS: 00000282<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RAX:
0000000000000001 RBX:
ffff8101cf193e80 RCX: 0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RDX:
0000000000000012 RSI:
000000000abe79b0 RDI: ffff810552ccb500<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: RBP:
0000000000000286 R08: 0000000351edfde0
R09: 0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: R10:
ffff810311d9a400 R11:
0000000000000248 R12: ffff81023f907a00<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: R13:
ffffffff88726dba R14:
ffff810162543bc0 R15: 0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: FS:
0000000000000000(0000)
GS:ffffffff803ac000(0000) knlGS:0000000000000000<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: CS: 0010 DS:
002b ES: 002b
CR0: 000000008005003b<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: CR2:
000000000c0f900c CR3:
000000066b863000 CR4: 00000000000006e0<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel: Call Trace:<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88923787>]
:lustre:ll_sai_entry_to_stated+0x87/0x330<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8000d0de>]
dput+0x2c/0x114<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88923f8b>]
:lustre:do_statahead_interpret+0x55b/0x5c0<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88925641>]
:lustre:ll_statahead_thread+0x7b1/0x1750<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8008a4b4>]
default_wake_function+0x0/0xe<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8005dfb1>]
child_rip+0xa/0x11<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff88924e90>]
:lustre:ll_statahead_thread+0x0/0x1750<o:p></o:p></p>
<p class="MsoNormal">Sep 13 21:11:49 wn122 kernel:
[<ffffffff8005dfa7>]
child_rip+0x0/0x11<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">After we had 3 clients go into this state
the first day, and
2 the next, we decided to downgrade the clients back to 1.8.3,
while leaving
the servers at 1.8.4. This morning, we had 2 more clients get
stuck again, so my
assumption is that there is a problem with the 1.8.4 servers.</p>
</div>
</blockquote>
This ASSERTION looks related with statahead, such feature only
affects client-side behavior, but nothing for server. On the other
hand, we never saw that on lustre-1.8.3 or former version, and as I
known, there were almost no changes for statahead between
lustre-1.8.3 and lustre-1.8.4. So I am not sure whether your
assumption is right not.<br>
<br>
Anyway, to make your system run, you can disable statahead on
client-side firstly, to check what will happen after that. The
client-side proc interface "statahead_max" is for that.<br>
<br>
Cheers,<br>
Nasf<br>
<blockquote
cite="mid:AB48A31C4EC97E498F4235B7CEF74A194D3248C613@MBX00.d.ethz.ch"
type="cite">
<div class="Section1">
<p class="MsoNormal"><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">These are RedHat 5.4 servers and clients,
with the 2.6.18-194.3.1.el5_lustre.1.8.4
kernel.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Any help on this issue would be great.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Thanks,<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Jason Temple<o:p></o:p></p>
</div>
<pre wrap="">
<fieldset class="mimeAttachmentHeader"></fieldset>
_______________________________________________
Lustre-discuss mailing list
<a class="moz-txt-link-abbreviated" href="mailto:Lustre-discuss@lists.lustre.org">Lustre-discuss@lists.lustre.org</a>
<a class="moz-txt-link-freetext" href="http://lists.lustre.org/mailman/listinfo/lustre-discuss">http://lists.lustre.org/mailman/listinfo/lustre-discuss</a>
</pre>
</blockquote>
<br>
</body>
</html>