[LU-4195] MDT Slow with ptlrpcd using 100% cpu.

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.1.5
• Type: Bug
• Priority: Major
• Reporter: Mahmoud Hanafi
• Assignee: Amir Shehata (Inactive)
• Resolution: Cannot Reproduce

Environment

server running 2.1.5-2nas
our source is at git://github.com/jlan/lustre-nas.git

• Severity: 3
• Epic: hang, server

Description

mdt response very slow. Top showed ptlrpcd running at 100% cpu. Console showed errors. Was able to run debug trace. See attached files.

Lustre: Service thread pid 7065 was inactive for 200.00s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
Pid: 7065, comm: mdt_93

Call Trace:
[<ffffffff810539b2>] ? enqueue_task_fair+0x142/0x490
[<ffffffff81096f5d>] ? sched_clock_cpu+0xcd/0x110
[<ffffffffa04f960e>] cfs_waitq_wait+0xe/0x10 [libcfs]
[<ffffffffa0a9f6de>] qos_statfs_update+0x7fe/0xa70 [lov]
[<ffffffff8105fab0>] ? default_wake_function+0x0/0x20
[<ffffffffa0aa00fd>] alloc_qos+0x1ad/0x21a0 [lov]
[<ffffffffa0aa306c>] qos_prep_create+0x1ec/0x2380 [lov]
[<ffffffffa04f98be>] ? cfs_free+0xe/0x10 [libcfs]
[<ffffffffa0a9c63a>] lov_prep_create_set+0xea/0x390 [lov]
[<ffffffffa0a84b0c>] lov_create+0x1ac/0x1400 [lov]
[<ffffffffa0d8a50f>] ? obd_iocontrol+0xef/0x390 [mdd]
[<ffffffffa0d8f90e>] mdd_lov_create+0x9ee/0x1ba0 [mdd]
[<ffffffffa0da1871>] mdd_create+0xf81/0x1a90 [mdd]
[<ffffffffa0ea9df3>] ? osd_oi_lookup+0x83/0x110 [osd_ldiskfs]
[<ffffffffa0ea456c>] ? osd_object_init+0xdc/0x3e0 [osd_ldiskfs]
[<ffffffffa0eda3f7>] cml_create+0x97/0x250 [cmm]
[<ffffffffa0e165e1>] ? mdt_version_get_save+0x91/0xd0 [mdt]
[<ffffffffa0e2c06e>] mdt_reint_open+0x1aae/0x28a0 [mdt]
[<ffffffffa078f724>] ? lustre_msg_add_version+0x74/0xd0 [ptlrpc]
[<ffffffffa0da456e>] ? md_ucred+0x1e/0x60 [mdd]
[<ffffffffa0e14c81>] mdt_reint_rec+0x41/0xe0 [mdt]
[<ffffffffa0e0bed4>] mdt_reint_internal+0x544/0x8e0 [mdt]
[<ffffffffa0e0c53d>] mdt_intent_reint+0x1ed/0x530 [mdt]
[<ffffffffa0e0ac09>] mdt_intent_policy+0x379/0x690 [mdt]
[<ffffffffa074b351>] ldlm_lock_enqueue+0x361/0x8f0 [ptlrpc]
[<ffffffffa07711ad>] ldlm_handle_enqueue0+0x48d/0xf50 [ptlrpc]
[<ffffffffa0e0b586>] mdt_enqueue+0x46/0x130 [mdt]
[<ffffffffa0e00772>] mdt_handle_common+0x932/0x1750 [mdt]
[<ffffffffa0e01665>] mdt_regular_handle+0x15/0x20 [mdt]
[<ffffffffa079fb4e>] ptlrpc_main+0xc4e/0x1a40 [ptlrpc]
[<ffffffffa079ef00>] ? ptlrpc_main+0x0/0x1a40 [ptlrpc]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa079ef00>] ? ptlrpc_main+0x0/0x1a40 [ptlrpc]
[<ffffffffa079ef00>] ? ptlrpc_main+0x0/0x1a40 [ptlrpc]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20

Comments

[Mahmoud Hanafi]

Uploaded the following files to ftp site.

LU4195.lustre-log.dump.selected.tgz
LU4195.ptlrpcd.debug2.out.gz

I also have crash dump that can be uploaded if needed.

[Peter Jones]

Lai

What do you advise here?

Peter

[Niu Yawei (Inactive)]

Mahmoud, do you know what kind of application/operation caused the problem? I see there are quite lot of transaction commits in the log, looks like heavy load was on mds.

Is it possible to get a full stack trace (especially the stack trace for ptlrpcd) by sysrq when this happened again? Thanks.

[Mahmoud Hanafi]

Hope this helps

crash> bt 5560
PID: 5560 TASK: ffff881fb5e87540 CPU: 8 COMMAND: "ptlrpcd"
#0 [ffff8820b0c07e90] crash_nmi_callback at ffffffff81029956
#1 [ffff8820b0c07ea0] notifier_call_chain at ffffffff815222f5
#2 [ffff8820b0c07ee0] atomic_notifier_call_chain at ffffffff8152235a
#3 [ffff8820b0c07ef0] notify_die at ffffffff81095f1e
#4 [ffff8820b0c07f20] do_nmi at ffffffff8151ff2f
#5 [ffff8820b0c07f50] nmi at ffffffff8151f7e0
[exception RIP: _spin_lock+33]
RIP: ffffffff8151f051 RSP: ffff881fac2b3bf0 RFLAGS: 00000297
RAX: 0000000000000d28 RBX: 0000000000000004 RCX: 0000000000000000
RDX: 0000000000000d27 RSI: 0000000000000007 RDI: ffffffffa05ada40
RBP: ffff881fac2b3bf0 R8: 0000000000000246 R9: 0000000000000001
R10: ffff883343e44cc0 R11: 0000000000000000 R12: 000500000a971b57
R13: 0000000000003039 R14: 0000000000000000 R15: 000527015f9078c7
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
— <NMI exception stack> —
#6 [ffff881fac2b3bf0] _spin_lock at ffffffff8151f051
#7 [ffff881fac2b3bf8] LNetMEAttach at ffffffffa057f99f [lnet]
#8 [ffff881fac2b3c68] ptl_send_rpc at ffffffffa078b532 [ptlrpc]
#9 [ffff881fac2b3d28] ptlrpc_send_new_req at ffffffffa0781993 [ptlrpc]
#10 [ffff881fac2b3d98] ptlrpc_check_set at ffffffffa07840a8 [ptlrpc]
#11 [ffff881fac2b3e38] ptlrpcd_check at ffffffffa07b4ed0 [ptlrpc]
#12 [ffff881fac2b3e68] ptlrpcd at ffffffffa07b516e [ptlrpc]
#13 [ffff881fac2b3f48] kernel_thread at ffffffff8100c0ca

crash> bt 5560 -l
PID: 5560 TASK: ffff881fb5e87540 CPU: 8 COMMAND: "ptlrpcd"
#0 [ffff8820b0c07e90] crash_nmi_callback at ffffffff81029956
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/arch/x86/include/asm/paravirt.h: 115
#1 [ffff8820b0c07ea0] notifier_call_chain at ffffffff815222f5
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/kernel/notifier.c: 95
#2 [ffff8820b0c07ee0] atomic_notifier_call_chain at ffffffff8152235a
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/kernel/notifier.c: 192
#3 [ffff8820b0c07ef0] notify_die at ffffffff81095f1e
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/kernel/notifier.c: 573
#4 [ffff8820b0c07f20] do_nmi at ffffffff8151ff2f
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/arch/x86/kernel/traps.c: 513
#5 [ffff8820b0c07f50] nmi at ffffffff8151f7e0
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/arch/x86_64/kernel/entry.S
[exception RIP: _spin_lock+33]
RIP: ffffffff8151f051 RSP: ffff881fac2b3bf0 RFLAGS: 00000297
RAX: 0000000000000d28 RBX: 0000000000000004 RCX: 0000000000000000
RDX: 0000000000000d27 RSI: 0000000000000007 RDI: ffffffffa05ada40
RBP: ffff881fac2b3bf0 R8: 0000000000000246 R9: 0000000000000001
R10: ffff883343e44cc0 R11: 0000000000000000 R12: 000500000a971b57
R13: 0000000000003039 R14: 0000000000000000 R15: 000527015f9078c7
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
— <NMI exception stack> —
#6 [ffff881fac2b3bf0] _spin_lock at ffffffff8151f051
/usr/src/debug/kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/arch/x86/include/asm/spinlock.h: 127
#7 [ffff881fac2b3bf8] LNetMEAttach at ffffffffa057f99f [lnet]
/usr/src/redhat/BUILD/lustre-2.1.5/lnet/lnet/lib-me.c: 158
#8 [ffff881fac2b3c68] ptl_send_rpc at ffffffffa078b532 [ptlrpc]
/usr/src/redhat/BUILD/lustre-2.1.5/lustre/ptlrpc/niobuf.c: 614
#9 [ffff881fac2b3d28] ptlrpc_send_new_req at ffffffffa0781993 [ptlrpc]
/usr/src/redhat/BUILD/lustre-2.1.5/lustre/ptlrpc/client.c: 1437
#10 [ffff881fac2b3d98] ptlrpc_check_set at ffffffffa07840a8 [ptlrpc]
/usr/src/redhat/BUILD/lustre-2.1.5/lustre/ptlrpc/client.c: 1468
#11 [ffff881fac2b3e38] ptlrpcd_check at ffffffffa07b4ed0 [ptlrpc]
/usr/src/redhat/BUILD/lustre-2.1.5/lustre/ptlrpc/ptlrpcd.c: 240
#12 [ffff881fac2b3e68] ptlrpcd at ffffffffa07b516e [ptlrpc]
/usr/src/redhat/BUILD/lustre-2.1.5/lustre/ptlrpc/ptlrpcd.c: 326
#13 [ffff881fac2b3f48] kernel_thread at ffffffff8100c0ca
/usr/src/debug////////kernel-lustre215-2.6.32-279.19.1.el6/linux-2.6.32-279.19.1.el6.x86_64/arch/x86/kernel/entry_64.S: 1213

[Niu Yawei (Inactive)]

Could you provide the full stack trace (for all tasks on all CPUs) as well? What about the memmory usage? Can this situation be recovered?

[Lai Siyao]

In debug logs there are lots of messages like this:

00000400:02000400:2.0:1383201992.510338:0:7620:0:(lib-move.c:1454:lnet_send()) No route to 12345-10.153.1.199@o2ib233 via 10.151.27.60@o2ib (all routers down)

It looks like routers are down, and all connections are down too, and clients kept reconnecting to MDS (but failed), so ptlrpcd are always 100% busy.

[Mahmoud Hanafi]

We were not able to recover from this and had to dump the system.
See attached files for memory and stack track info

We have 7 other filesystem that use the same routers and clients and they were not experiencing this issue.

There is "some" evidence that this may have been triggered by running a "lfs setquota" command.

[Niu Yawei (Inactive)]

I agree with Lai, the log shows that no router for o2ib to o2ib233, and the stack trace shows all ptlrpcd threads were busy on acquiring LNET_LOCK (which I think is caused by the router problem).

Mahmoud, I didn't see anything related to quota in the log, what kind of evidence indicating it's triggered by 'lfs setquota' command?

[Jodi Levi (Inactive)]

Amir,
Could you take a look at this one?
Thank you!

[Amir Shehata (Inactive)]

Would it be possible to grab the route configuration for one of the nodes that have the problem? Also if you could please highlight the problematic routes.

As basic sanity check, please make sure that routers are actually configured as routers, IE: forwarding="enabled". If not, then the node will drop all messages not destined to itself.

This error message is hit whenever LNET tries to send a message to a final destination that exists on a net that do not have a route from the net the current node is on. Thus an appropriate route is chosen.

Furthermore, the routes can exist but they might be down because the NID specified is not reachable. Is it possible to try and do an lctl ping <nid> from the node that's having the problem. That should return a list of NIDs of the target router and their status (up/down). If one of these nids are down and avoid_asym_router_failure is 1 (which it is by default), then the entire router is considered down and when sending messages we'll hit the above error.

NOTE: if you have a router that has multiple nids, but one of the nids is "unused" (IE, it sends/receives no messages), this would cause that NID to be considered down, and will lead to the above described scenario.

[John Fuchs-Chesney (Inactive)]

Hello Mahmoud,
Just want to check in to see if this is still a 'live' issue for you?
If the problem has been dealt with, can we mark this issue as 'resolved'?
Thanks,
~ jfc.

[John Fuchs-Chesney (Inactive)]

Hello again Mahmoud,
Please advise if you want us to keep this ticket open?

If we don't hear back we'll mark it as resolved, with no fix, and we can re-open it if requested to do that.

Thanks,
~ jfc.

[Mahmoud Hanafi]

please close.

[Peter Jones]

ok thanks Mahmoud