Details
-
Bug
-
Resolution: Unresolved
-
Major
-
None
-
Lustre 2.12.6
-
None
-
CentOS 7.9, ldiskfs
-
3
-
9223372036854775807
Description
We're enforcing group quota limits on Oak. They usually work great. After a MDS crash with 2.12.6 (we hit unrelated bug LU-14705) and restart of the MDTs, one OST (oak-OST0135) did not came back in sync with the quota master, and it's still out of sync. A few groups are out of quotas on this OST and this is generating hung I/Os at least new files that are stripped on this OST. As a workaround, I have set max_create_count=0 on all MDTs for this OST as a temporary workaround (and this worked).
Example of a group out of quotas on OST0135 (index 309):
# lfs quota -v -g oak_cblish /oak
[...]
oak-OST0134_UUID
243010468 - 246011728 - - - - -
oak-OST0135_UUID
256548944* - 256542812 - - - - -
oak-OST0136_UUID
85301696 - 86780916 - - - - -
oak-OST0137_UUID
156684012 - 160709804 - - - - -
oak-OST0138_UUID
35652032 - 36721800 - - - - -
oak-OST0139_UUID
8830024 - 12589328 - - - - -
Example of hung I/O on clients:
[2021-06-14T15:31:23-07:00] [3776399.960372] tar S ffff8b55ed7cb180 0 13047 4645 0x00000000^M [2021-06-14T15:31:23-07:00] [3776399.968457] Call Trace:^M [2021-06-14T15:31:23-07:00] [3776399.971387] [<ffffffffb90b042b>] ? recalc_sigpending+0x1b/0x70^M [2021-06-14T15:31:23-07:00] [3776399.978194] [<ffffffffb9788eb9>] schedule+0x29/0x70^M [2021-06-14T15:31:23-07:00] [3776399.983972] [<ffffffffc0e935b5>] cl_sync_io_wait+0x2b5/0x3d0 [obdclass]^M [2021-06-14T15:31:23-07:00] [3776399.991654] [<ffffffffb90dadf0>] ? wake_up_state+0x20/0x20^M [2021-06-14T15:31:23-07:00] [3776399.998377] [<ffffffffc0e93d78>] cl_io_submit_sync+0x178/0x270 [obdclass]^M [2021-06-14T15:31:23-07:00] [3776400.006298] [<ffffffffc125d1d6>] vvp_io_commit_sync+0x106/0x340 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.014084] [<ffffffffc125e5b6>] vvp_io_write_commit+0x4c6/0x600 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.021971] [<ffffffffc125ed25>] vvp_io_write_start+0x635/0xa70 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.029760] [<ffffffffc0e90225>] ? cl_lock_enqueue+0x65/0x120 [obdclass]^M [2021-06-14T15:31:23-07:00] [3776400.037550] [<ffffffffc0e92788>] cl_io_start+0x68/0x130 [obdclass]^M [2021-06-14T15:31:23-07:00] [3776400.044750] [<ffffffffc0e949fc>] cl_io_loop+0xcc/0x1c0 [obdclass]^M [2021-06-14T15:31:23-07:00] [3776400.051848] [<ffffffffc121407b>] ll_file_io_generic+0x63b/0xc90 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.059631] [<ffffffffc1214b69>] ll_file_aio_write+0x289/0x660 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.067317] [<ffffffffc1215040>] ll_file_write+0x100/0x1c0 [lustre]^M [2021-06-14T15:31:23-07:00] [3776400.074609] [<ffffffffb924de00>] vfs_write+0xc0/0x1f0^M [2021-06-14T15:31:23-07:00] [3776400.080541] [<ffffffffb924ebdf>] SyS_write+0x7f/0xf0^M [2021-06-14T15:31:23-07:00] [3776400.086380] [<ffffffffb9795f92>] system_call_fastpath+0x25/0x2a^M
I tried to trigger a force_reint for this OST by doing:
echo 1 > /proc/fs/lustre/osd-ldiskfs/oak-OST0135/quota_slave/force_reint
but that didn't seem to help. The status of the quota slave on this OST is now:
[root@oak-io6-s2 ~]# cat /proc/fs/lustre/osd-ldiskfs/oak-OST0135/quota_slave/info target name: oak-OST0135 pool ID: 0 type: dt quota enabled: g conn to master: setup space acct: ugp user uptodate: glb[0],slv[0],reint[0] group uptodate: glb[0],slv[0],reint[1] project uptodate: glb[0],slv[0],reint[0]
but should likely be:
group uptodate: glb[1],slv[1],reint[0]
like other healthy OSTs.
I've taken some debug logs with +trace and +quota from the OSS in question that I'm attaching as oak-OST0135_quota_issue.log.gz
We can see some -115 EINPROGRESS errors in the logs:
[root@oak-io6-s2 ~]# grep qsd:oak-OST0135 oak-OST0135_quota_issue.log | head 00040000:04000000:46.0:1623797919.334289:0:107324:0:(qsd_handler.c:732:qsd_op_begin0()) $$$ op_begin space:12 qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:0 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334291:0:107324:0:(qsd_handler.c:636:qsd_acquire()) $$$ acquiring:12 count=0 qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:12 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334312:0:107324:0:(qsd_entry.c:247:qsd_refresh_usage()) $$$ disk usage: 119769696 qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:12 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334316:0:107324:0:(qsd_handler.c:121:qsd_ready()) $$$ not up-to-date, dropping request and kicking off reintegration qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:12 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334320:0:107324:0:(qsd_handler.c:751:qsd_op_begin0()) $$$ acquire quota failed:-115 qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:12 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334330:0:107324:0:(qsd_entry.c:247:qsd_refresh_usage()) $$$ disk usage: 119769696 qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:0 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334332:0:107324:0:(qsd_handler.c:222:qsd_calc_adjust()) $$$ overrun, reporting usage qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:0 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334334:0:107324:0:(qsd_handler.c:121:qsd_ready()) $$$ not up-to-date, dropping request and kicking off reintegration qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:0 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:46.0:1623797919.334336:0:107324:0:(qsd_handler.c:929:qsd_adjust()) $$$ delaying adjustment since qsd isn't ready qsd:oak-OST0135 qtype:grp id:8663 enforced:1 granted: 119761748 pending:0 waiting:0 req:0 usage: 119769696 qunit:0 qtune:0 edquot:0 default:no 00040000:04000000:18.0:1623797930.024599:0:271450:0:(qsd_entry.c:247:qsd_refresh_usage()) $$$ disk usage: 232050092 qsd:oak-OST0135 qtype:grp id:4722 enforced:1 granted: 268435456 pending:0 waiting:0 req:0 usage: 232050092 qunit:0 qtune:0 edquot:0 default:no
Please let me know if you have any idea of what could be wrong, help troubleshoot, and/or if there is a way to force a resync in a different way. Otherwise, I'm going to restart this OST at a scheduled maintenance. Thanks!