[#LU-1195] ll_sai_put()) ASSERTION(thread_is_stopped(&sai->sai_agl

[LU-1195] ll_sai_put()) ASSERTION(thread_is_stopped(&sai->sai_agl_thread)) failed Created: 07/Mar/12 Updated: 02/May/12 Resolved: 12/Mar/12
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	Lustre 2.2.0
Fix Version/s:	Lustre 2.2.0, Lustre 2.3.0

Type:

Improvement

Priority:

Blocker

Reporter:

James A Simmons

Assignee:

nasf (Inactive)

Resolution:

Fixed

Votes:

Labels:

None

Environment:

Lustre 2.1.56 cray clients with RHEL6 back end servers running Lustre 2.1.56

Rank (Obsolete):

4695

Description

With a mounted file system I power down the MDS server to test the IR functionality. The client I was one which was running a IOR job from the oops while waiting to recovery.

Comments

Comment by James A Simmons [ 07/Mar/12 ]

....
[2012-03-07 13:37:30][c0-0c0s0n2]Lustre: 5776:0:(client.c:1789:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 133114
5286/real 1331145286] req@ffff8803e8c09400 x1395803995574507/t0(0) o400->lustre-OST000e-osc-ffff8803fd817800@10.37.248.64@o2ib1:28/4 lens 192/192 e 0 t
o 1 dl 1331145448 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
[2012-03-07 13:37:30][c0-0c0s0n2]Lustre: 5776:0:(client.c:1789:ptlrpc_expire_one_request()) Skipped 4 previous similar messages
[2012-03-07 13:38:26][c0-0c0s0n2]Lustre: 5774:0:(client.c:1789:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 133114
5286/real 1331145286] req@ffff8803e1869c00 x1395803995574530/t0(0) o8->lustre-OST000e-osc-ffff8803fd817800@10.37.248.64@o2ib1:28/4 lens 368/512 e 0 to
1 dl 1331145506 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
[2012-03-07 13:38:32][c0-0c0s0n2]Lustre: 5781:0:(import.c:525:import_select_connection()) lustre-OST0002-osc-ffff8803fd817800: tried all connections, in
creasing latency to 70s
[2012-03-07 13:38:49][c0-0c0s0n2]Lustre: 6893:0:(client.c:1789:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 133114
5250/real 1331145250] req@ffff8803fd3b3c00 x1395803995574492/t0(0) o41->lustre-MDT0000-mdc-ffff8803fd817800@10.37.248.61@o2ib1:12/10 lens 192/336 e 0 t
o 1 dl 1331145527 ref 2 fl Rpc:IX/0/ffffffff rc 0/-1
[2012-03-07 13:38:49][c0-0c0s0n2]Lustre: 6893:0:(client.c:1789:ptlrpc_expire_one_request()) Skipped 5 previous similar messages
[2012-03-07 13:38:49][c0-0c0s0n2]Lustre: lustre-MDT0000-mdc-ffff8803fd817800: Connection to service lustre-MDT0000 via nid 10.37.248.61@o2ib1 was lost;
in progress operations using this service will wait for recovery to complete.
[2012-03-07 13:38:49][c0-0c0s0n2]Lustre: Skipped 1 previous similar message
[2012-03-07 13:38:49][c0-0c0s0n2]LustreError: 6893:0:(lmv_obd.c:1201:lmv_statfs()) can't stat MDS #0 (lustre-MDT0000-mdc-ffff8803fd817800), error -4
[2012-03-07 13:38:49][c0-0c0s0n2]LustreError: 6893:0:(llite_lib.c:1468:ll_statfs_internal()) md_statfs fails: rc = -4
[2012-03-07 13:40:39][c0-0c0s0n2]Lustre: 5779:0:(client.c:1789:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 133114
5362/real 1331145362] req@ffff880407af1000 x1395803995574534/t0(0) o400->lustre-MDT0000-mdc-ffff8803fd817800@10.37.248.61@o2ib1:12/10 lens 192/192 e 0
to 1 dl 1331145639 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
[2012-03-07 13:40:39][c0-0c0s0n2]LustreError: 6752:0:(ldlm_request.c:110:ldlm_expired_completion_wait()) ### lock timed out (enqueued at 1331145213, 426
s ago), entering recovery for lustre-MDT0000_UUID@10.37.248.61@o2ib1 ns: lustre-MDT0000-mdc-ffff8803fd817800 lock: ffff8803e2d26480/0xed3be0e0e9f93ca5 l
rc: 4/1,0 mode: --/PR res: 8589937636/4 bits 0x2 rrc: 2 type: IBT flags: 0x0 remote: 0x21d5ec1b43413938 expref: -99 pid: 6752 timeout: 0
[2012-03-07 13:41:19][c0-0c0s0n2]LustreError: 167-0: This client was evicted by lustre-OST0006; in progress operations using this service will fail.
[2012-03-07 13:41:55][c0-0c0s0n2]Lustre: 5775:0:(client.c:1789:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 133114
5437/real 1331145437] req@ffff8803e8bb6c00 x1395803995574557/t0(0) o400->lustre-MDT0000-mdc-ffff8803fd817800@10.37.248.61@o2ib1:12/10 lens 192/192 e 0
to 1 dl 1331145714 ref 1 fl Rpc:XN/0/ffffffff rc 0/-1
[2012-03-07 13:41:55][c0-0c0s0n2]Lustre: 5775:0:(client.c:1789:ptlrpc_expire_one_request()) Skipped 1 previous similar message
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 167-0: This client was evicted by lustre-OST0002; in progress operations using this service will fail.
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6309:0:(file.c:157:ll_close_inode_openhandle()) inode 144115239145701379 mdc close failed: rc = -4
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 7208:0:(client.c:1076:ptlrpc_import_delay_req()) @@@ IMP_INVALID req@ffff8803fd55cc00 x1395803995574695/t
0(0) o35->lustre-MDT0000-mdc-ffff8803fd817800@10.37.248.61@o2ib1:23/10 lens 360/2280 e 0 to 0 dl 0 ref 2 fl Rpc:/0/ffffffff rc 0/-1
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(mdc_locks.c:719:mdc_enqueue()) ldlm_cli_enqueue: -5
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(dir.c:410:ll_get_dir_page()) lock enqueue: [0x200000be4:0x4:0x0] at 0: rc -5
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(statahead.c:1424:is_first_dirent()) error reading dir [0x200000be4:0x4:0x0] at 0: [rc -5] [parent
6752]
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(statahead.c:1718:do_statahead_enter()) can't start ll_sa thread, rc: -513
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(statahead.c:542:ll_sai_put()) ASSERTION(thread_is_stopped(&sai->sai_agl_thread)) failed
[2012-03-07 13:42:32][c0-0c0s0n2]LustreError: 6752:0:(statahead.c:542:ll_sai_put()) LBUG
[2012-03-07 13:42:32][c0-0c0s0n2]Pid: 6752, comm: ls
[2012-03-07 13:42:32][c0-0c0s0n2]Call Trace:
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810072c9>] try_stack_unwind+0x149/0x190
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff81005ca0>] dump_trace+0x90/0x300
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0122812>] libcfs_debug_dumpstack+0x52/0x80 [libcfs]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0122e11>] lbug_with_loc+0x71/0xd0 [libcfs]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa012e461>] libcfs_assertion_failed+0x61/0x70 [libcfs]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0657a59>] ll_sai_put+0x579/0x5b0 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0659ef4>] do_statahead_enter+0x1344/0x1c30 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0641212>] ll_lookup_it+0xa62/0xd30 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0641ce7>] ll_lookup_nd+0x87/0x450 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e2186>] do_lookup+0x1a6/0x240
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e26c3>] __link_path_walk+0x293/0xf30
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e35ee>] path_walk+0x6e/0xe0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e36bb>] do_path_lookup+0x5b/0xa0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e4313>] user_path_at+0x73/0xa0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dacbc>] vfs_fstatat+0x3c/0x80
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dad19>] vfs_lstat+0x19/0x20
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dae9f>] sys_newlstat+0x1f/0x50
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[2012-03-07 13:42:32][c0-0c0s0n2] [<00007f1db3217605>] 0x7f1db3217605
[2012-03-07 13:42:32][c0-0c0s0n2]Kernel panic - not syncing: LBUG
[2012-03-07 13:42:32][c0-0c0s0n2]Pid: 6752, comm: ls Tainted: P 2.6.32.45-0.3.2_1.0400.6336-cray_gem_s #1
[2012-03-07 13:42:32][c0-0c0s0n2]Call Trace:
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810072c9>] try_stack_unwind+0x149/0x190
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff81005ca0>] dump_trace+0x90/0x300
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff81006e17>] show_trace_log_lvl+0x57/0x70
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff81006e40>] show_trace+0x10/0x20
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff813c9b3c>] dump_stack+0x72/0x7b
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff813c9bba>] panic+0x75/0x13d
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0122e67>] lbug_with_loc+0xc7/0xd0 [libcfs]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa012e461>] libcfs_assertion_failed+0x61/0x70 [libcfs]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0657a59>] ll_sai_put+0x579/0x5b0 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0659ef4>] do_statahead_enter+0x1344/0x1c30 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0641212>] ll_lookup_it+0xa62/0xd30 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffffa0641ce7>] ll_lookup_nd+0x87/0x450 [lustre]
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e2186>] do_lookup+0x1a6/0x240
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e26c3>] __link_path_walk+0x293/0xf30
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e35ee>] path_walk+0x6e/0xe0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e36bb>] do_path_lookup+0x5b/0xa0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810e4313>] user_path_at+0x73/0xa0
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dacbc>] vfs_fstatat+0x3c/0x80
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dad19>] vfs_lstat+0x19/0x20
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff810dae9f>] sys_newlstat+0x1f/0x50
[2012-03-07 13:42:32][c0-0c0s0n2] [<ffffffff8100272b>] system_call_fastpath+0x16/0x1b
[2012-03-07 13:42:32][c0-0c0s0n2] [<00007f1db3217605>] 0x7f1db3217605

Comment by Peter Jones [ 07/Mar/12 ]

Jinshan

Could you comment on this one please?

Thanks

Peter

Comment by Jinshan Xiong (Inactive) [ 07/Mar/12 ]

I'm wondering why this client was evicted by OST-0002 and OST-0006 while MDT was restarted. The assertion looks related to AGL so I add nasf into watch list.

Can you please collect log on the client side?

Comment by nasf (Inactive) [ 07/Mar/12 ]

In fact, the AGL was not started, some unknown reason caused cfs_create_thread() failed, and there is defect for error handling under the case of failing to statahead/agl thread, then LBUG() was triggered here. I will make patch to fix it.

As for why cfs_create_thread() failed to start some kernel threads, it is out of statahead/agl scope. So my patch cannot resolve the possible potential IR issues.

Comment by nasf (Inactive) [ 07/Mar/12 ]

This is the patch LBUG related with statahead/AGL start failure:

http://review.whamcloud.com/#change,2268

Comment by Jinshan Xiong (Inactive) [ 08/Mar/12 ]

I just changed the description of this bug. This is because there is no any evidence that this is related to IR

So let's ask them to apply nasf's patch and see what's going on next. Please let me know if you have any questions.

Comment by James A Simmons [ 08/Mar/12 ]

Strange that the cfs_create_thread failed client side since the problems were happening server server due to ~~LU-1135~~. This addes another clue to ~~LU-1135~~

Comment by Peter Jones [ 08/Mar/12 ]

James

Does this problem still exist or was it just a side-effect of the mismatch with the RHEL5 version as mentioned in ~~LU-1135~~?

Peter

Comment by James A Simmons [ 08/Mar/12 ]

I'm in the process of testing with the patch to see if this is the case. The failure of the cfs_create_thread might be from the rhel5 corruption but please apply this patch if it has no regression. The test failure did expose a real defect for error handing for a failing agl thread.

Comment by Jinshan Xiong (Inactive) [ 09/Mar/12 ]

Hi James, can you please turn panic_on_lbug off so that you can collect some log in case it runs into problem?

This is my Lustre config file:

[root@mercury tests]# cat /etc/modprobe.d/Lustre
#options obdclass lu_cache_percent=1
options libcfs libcfs_panic_on_lbug=0

or you can run `lctl set_param panic_on_lbug=0' on each node if there is no disks on client side.

Comment by James A Simmons [ 09/Mar/12 ]

Sure. This is something we should do for the IR test shot as well.