[LU-11761] blocked MDT mount and high cpu usage from lodXXXX_recYYYY threads

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.13.0, Lustre 2.12.3
• Affects Version/s: Lustre 2.12.0
• Environment: CentOS 7.6 3.10.0-957.1.3.el7_lustre.x86_64 Lustre 2.12.0 RC2
• Severity: 3
• Assignee: Hongchao Zhang
• Reporter: Stephane Thiell

Description

Another issue when using 2.12.0 RC2 during testing... MDTs mount seems to never complete and the following threads take 100% cpu:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 20953 root 20 0 0 0 0 R 100.0 0.0 27:00.33 lod0002_rec0001
 20954 root 20 0 0 0 0 R 100.0 0.0 27:00.34 lod0002_rec0003

This is on fir-md1-s1 that handles MDT0 and MDT2 on this test system.

sysrq t shows:

Dec 11 09:50:13 fir-md1-s1 kernel: lod0002_rec0001 R  running task        0 20953      2 0x00000080
Dec 11 09:50:13 fir-md1-s1 kernel: Call Trace:
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3cc5d>] ? keys_fini+0x2d/0x1d0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3ce2b>] lu_context_fini+0x2b/0xa0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3d0da>] lu_env_init+0x1a/0x30 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0f19b68>] ptlrpc_set_wait+0x7d8/0x8d0 [ptlrpc]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d515e5>] ? lustre_get_jobid+0x185/0x2e0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d09f3c>] ? obd_get_request_slot+0x3c/0x280 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0f19ce3>] ptlrpc_queue_wait+0x83/0x230 [ptlrpc]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc088e334>] fld_client_rpc+0x104/0x540 [fld]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0892f5f>] fld_server_lookup+0x15f/0x320 [fld]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc1684587>] lod_fld_lookup+0x327/0x510 [lod]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc16997dd>] lod_object_init+0x7d/0x3c0 [lod]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3dfd5>] lu_object_alloc+0xe5/0x320 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3e2e6>] lu_object_find_at+0x76/0x280 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3f78d>] dt_locate_at+0x1d/0xb0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d02b4c>] llog_osd_open+0xfc/0xf30 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0d3e789>] ? lu_object_put+0x279/0x3d0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc0ceff20>] llog_open+0x140/0x3d0 [obdclass]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc16bdeed>] lod_sub_prep_llog+0x14d/0x783 [lod]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc16837ab>] lod_sub_recovery_thread+0x1cb/0xc80 [lod]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffc16835e0>] ? lod_obd_get_info+0x9d0/0x9d0 [lod]
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffa7ac1c31>] kthread+0xd1/0xe0
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffa7ac1b60>] ? insert_kthread_work+0x40/0x40
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffa8174c24>] ret_from_fork_nospec_begin+0xe/0x21
Dec 11 09:50:13 fir-md1-s1 kernel:  [<ffffffffa7ac1b60>] ? insert_kthread_work+0x40/0x40

and

Dec 11 09:44:24 fir-md1-s1 kernel: lod0002_rec0003 R  running task        0 20954      2 0x00000080
Dec 11 09:44:24 fir-md1-s1 kernel: Call Trace:
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3cfa3>] ? lu_context_init+0xd3/0x1f0 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3ceba>] ? lu_env_fini+0x1a/0x30 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0f19b68>] ? ptlrpc_set_wait+0x7d8/0x8d0 [ptlrpc]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d515e5>] ? lustre_get_jobid+0x185/0x2e0 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d09f3c>] ? obd_get_request_slot+0x3c/0x280 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0f19ce3>] ? ptlrpc_queue_wait+0x83/0x230 [ptlrpc]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc088e421>] ? fld_client_rpc+0x1f1/0x540 [fld]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0892f5f>] ? fld_server_lookup+0x15f/0x320 [fld]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc1684587>] ? lod_fld_lookup+0x327/0x510 [lod]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc16997dd>] ? lod_object_init+0x7d/0x3c0 [lod]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3dfd5>] ? lu_object_alloc+0xe5/0x320 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3e2e6>] ? lu_object_find_at+0x76/0x280 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3f78d>] ? dt_locate_at+0x1d/0xb0 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d02b4c>] ? llog_osd_open+0xfc/0xf30 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0d3e789>] ? lu_object_put+0x279/0x3d0 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc0ceff20>] ? llog_open+0x140/0x3d0 [obdclass]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc16bdeed>] ? lod_sub_prep_llog+0x14d/0x783 [lod]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc16837ab>] ? lod_sub_recovery_thread+0x1cb/0xc80 [lod]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffc16835e0>] ? lod_obd_get_info+0x9d0/0x9d0 [lod]
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffa7ac1c31>] ? kthread+0xd1/0xe0
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffa7ac1b60>] ? insert_kthread_work+0x40/0x40
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffa8174c24>] ? ret_from_fork_nospec_begin+0xe/0x21
Dec 11 09:44:24 fir-md1-s1 kernel:  [<ffffffffa7ac1b60>] ? insert_kthread_work+0x40/0x40

Mount commands are stuck, even when using -o abort_recov

I took a crash dump just in case you're interested.

I believe it's a regression from earlier 2.11.x versions...

HTH,
Stephane

Issue Links

• is duplicated by: LU-10401 sanity test_133g: timeout during MDT mount
• is related to: LU-12360 Can't restart filesystem (2.12) even with abort_recov
• is related to: LU-13468 Timeout-ed FLD_QUERY rpc leads to client operation failure.
• is related to: LU-5871 Do not return -EAGAIN in lod_object_init

Comments

[Gerrit Updater]

Minh Diep ([e-mail]) uploaded a new patch: https://review.whamcloud.com/35661
Subject: LU-11761 fld: let's caller to retry FLD_QUERY
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: fe3d5156ac95e58c5fc62ab503dcff3619ccfbe0

[Peter Jones]

Landed for 2.13

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/34962/
Subject: LU-11761 fld: let's caller to retry FLD_QUERY
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: e3f6111dfd1c6f2266d0beef67e5a7514a6965d0

[Stephane Thiell]

Thanks Hongchao! FYI I'll use your current patch in case of emergency (eg. MDT restart) on our system, and rebuild when it's fully ready. We need to be able to abort the MDT recovery or better, the MDT recovery needs to be able to timeout, which is not always the case today as described in LU-12360.

[Gerrit Updater]

Hongchao Zhang ([e-mail]) uploaded a new patch: https://review.whamcloud.com/34962
Subject: LU-11761 fld: limit FLD_QUERY retry between MDTs
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: f2c831def8ac010b7a913633141deb2b5384e06c

[Hongchao Zhang]

In fld_client_rpc, the FLD_QUERY request will be retried in a loop if the connection to MDT0000 is not completed.

int fld_client_rpc(struct obd_export *exp,
                   struct lu_seq_range *range, u32 fld_op,
                   struct ptlrpc_request **reqp)
{
            ...
            if (rc != 0) {
                if (imp->imp_state != LUSTRE_IMP_CLOSED &&
                    !imp->imp_deactive &&
                    imp->imp_connect_flags_orig & OBD_CONNECT_MDS_MDS &&
                    OCD_HAS_FLAG(&imp->imp_connect_data, LIGHTWEIGHT) &&
                    rc != -ENOTSUPP) {
                        /*
                         * Since LWP is not replayable, so it will keep
                         * trying unless umount happens or the remote
                         * target does not support the operation, otherwise
                         * it would cause unecessary failure of the
                         * application.
                         */
                        ptlrpc_req_finished(req);
                        rc = 0;
                        goto again;
                }
                GOTO(out_req, rc);
                ...

In this case, the connection to the MDT0000 is actually lost, then the kernel thread "lodxxxx_recxxxx" is stuck in fld_client_rpc.

Apr 28 10:58:55 fir-md1-s1 kernel: LustreError: 137-5: fir-MDT0000_UUID: not available for connect from 10.9.105.54@o2ib4 (no target). If you are running an HA pair check that the target is mounted on the other 
Apr 28 10:58:55 fir-md1-s1 kernel: LustreError: Skipped 16004 previous similar messages

[Stephane Thiell]

Hit this again when mounting MDTs with -o abort_recov

Apr 28 10:56:16 fir-md1-s1 kernel: Lustre: fir-MDT0002: Imperative Recovery enabled, recovery window shrunk from 300-900 down to 150-900
Apr 28 10:56:17 fir-md1-s1 kernel: Lustre: fir-MDD0002: changelog on
Apr 28 10:56:17 fir-md1-s1 kernel: Lustre: fir-MDT0002: in recovery but waiting for the first client to connect
Apr 28 10:56:17 fir-md1-s1 kernel: LustreError: 39987:0:(mdt_handler.c:6447:mdt_iocontrol()) fir-MDT0002: Aborting recovery for device
Apr 28 10:56:17 fir-md1-s1 kernel: LustreError: 39987:0:(ldlm_lib.c:2605:target_stop_recovery_thread()) fir-MDT0002: Aborting recovery
Apr 28 10:56:17 fir-md1-s1 kernel: Lustre: Skipped 2 previous similar messages
Apr 28 10:56:17 fir-md1-s1 kernel: Lustre: 40232:0:(ldlm_lib.c:2058:target_recovery_overseer()) recovery is aborted, evict exports in recovery
Apr 28 10:56:17 fir-md1-s1 kernel: Lustre: 40232:0:(ldlm_lib.c:2058:target_recovery_overseer()) Skipped 2 previous similar messages
Apr 28 10:56:23 fir-md1-s1 kernel: LustreError: 23568:0:(ldlm_lockd.c:2322:ldlm_cancel_handler()) ldlm_cancel from 10.9.101.9@o2ib4 arrived at 1556474183 with bad export cookie 3999205256457834672
Apr 28 10:56:23 fir-md1-s1 kernel: LustreError: 23568:0:(ldlm_lockd.c:2322:ldlm_cancel_handler()) Skipped 2 previous similar messages
Apr 28 10:58:55 fir-md1-s1 kernel: LustreError: 137-5: fir-MDT0000_UUID: not available for connect from 10.9.105.54@o2ib4 (no target). If you are running an HA pair check that the target is mounted on the other 
Apr 28 10:58:55 fir-md1-s1 kernel: LustreError: Skipped 16004 previous similar messages
Apr 28 11:00:08 fir-md1-s1 kernel: INFO: task mount.lustre:39987 blocked for more than 120 seconds.
Apr 28 11:00:08 fir-md1-s1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 28 11:00:08 fir-md1-s1 kernel: mount.lustre    D ffff8b625635b0c0     0 39987  39986 0x00000082
Apr 28 11:00:08 fir-md1-s1 kernel: Call Trace:
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb67c49>] schedule+0x29/0x70
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb65721>] schedule_timeout+0x221/0x2d0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb67ffd>] wait_for_completion+0xfd/0x140
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b4d67b0>] ? wake_up_state+0x20/0x20
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0d6936d>] target_stop_recovery_thread.part.18+0x3d/0xd0 [ptlrpc]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0d69418>] target_stop_recovery_thread+0x18/0x20 [ptlrpc]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc146e868>] mdt_iocontrol+0x558/0xb00 [mdt]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b9a766>] server_start_targets+0x1c66/0x2a20 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b6eb10>] ? lustre_start_mgc+0x260/0x2510 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b67ea0>] ? class_config_dump_handler+0x7e0/0x7e0 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b9c5ec>] server_fill_super+0x10cc/0x1890 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b71828>] lustre_fill_super+0x328/0x950 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b71500>] ? lustre_common_put_super+0x270/0x270 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b6452cf>] mount_nodev+0x4f/0xb0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b69908>] lustre_mount+0x38/0x60 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b645e4e>] mount_fs+0x3e/0x1b0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b6639e7>] vfs_kern_mount+0x67/0x110
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b66600f>] do_mount+0x1ef/0xce0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b665d45>] ? copy_mount_options+0xc5/0x170
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b666e43>] SyS_mount+0x83/0xd0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb74ddb>] system_call_fastpath+0x22/0x27
Apr 28 11:00:08 fir-md1-s1 kernel: INFO: task mount.lustre:40007 blocked for more than 120 seconds.
Apr 28 11:00:08 fir-md1-s1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 28 11:00:08 fir-md1-s1 kernel: mount.lustre    D ffff8b625635e180     0 40007  40006 0x00000082
Apr 28 11:00:08 fir-md1-s1 kernel: Call Trace:
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb68b69>] schedule_preempt_disabled+0x29/0x70
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb66ab7>] __mutex_lock_slowpath+0xc7/0x1d0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb65e9f>] mutex_lock+0x1f/0x2f
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc104f398>] mgc_set_info_async+0xa98/0x15f0 [mgc]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b73bec>] ? keys_fill+0xfc/0x180 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b98e1a>] server_start_targets+0x31a/0x2a20 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b6eb10>] ? lustre_start_mgc+0x260/0x2510 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b69f90>] ? do_lcfg+0x2f0/0x500 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b9c5ec>] server_fill_super+0x10cc/0x1890 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b71828>] lustre_fill_super+0x328/0x950 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b71500>] ? lustre_common_put_super+0x270/0x270 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b6452cf>] mount_nodev+0x4f/0xb0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffffc0b69908>] lustre_mount+0x38/0x60 [obdclass]
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b645e4e>] mount_fs+0x3e/0x1b0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b6639e7>] vfs_kern_mount+0x67/0x110
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b66600f>] do_mount+0x1ef/0xce0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b63e2aa>] ? __check_object_size+0x1ca/0x250
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b61c74c>] ? kmem_cache_alloc_trace+0x3c/0x200
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9b666e43>] SyS_mount+0x83/0xd0
Apr 28 11:00:08 fir-md1-s1 kernel:  [<ffffffff9bb74ddb>] system_call_fastpath+0x22/0x27

top:

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                      
 40230 root      20   0       0      0      0 R 100.0  0.0   4:14.53 lod0002_rec0001  

[Lai Siyao]

This will be fixed in LU-10888, but it's not finished yet.

[Lai Siyao]

Peter, this looks to be caused by corrupt update log, which may be generated by LU-11753. I'll check logs for details.

Stephane, did you use multiple MDT before? the update log is used on DNE system only.

[Stephane Thiell]

Sure, I uploaded the vmcore and corresponding debuginfo rpms to ftp.whamcloud.com:

* vmcore as LU-11761-vmcore-fir-md1-s1-2018-12-11-10-05-46

debuginfo rpms as:

• lustre-debuginfo-2.12.0_RC2-1.el7.x86_64.rpm
• kernel-debuginfo-3.10.0-957.1.3.el7_lustre.x86_64.rpm.1 (please disregard kernel-debuginfo-3.10.0-957.1.3.el7_lustre.x86_64.rpm)
• kernel-debuginfo-common-x86_64-3.10.0-957.1.3.el7_lustre.x86_64.rpm

And yes this could be a fallout from LU-11753 as I started having this issue after the problematic lfs migrate -m ...

[Peter Jones]

Lai

Could you please make an assessment of this issue? Does this seem to be fallout from LU-11753?

Stephane

Could you please attach the debug logs to the Jira ticket and upload the crash dump to the Whamcloud ftp site?

Thanks

Peter