[#LU-7988] HSM: high lock contention for cdt_llog

[LU-7988] HSM: high lock contention for cdt_llog_lock Created: 05/Apr/16 Updated: 21/Jan/19 Resolved: 06/Nov/17
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	None
Fix Version/s:	Lustre 2.11.0, Lustre 2.10.4, Lustre 2.10.7

Type:

Bug

Priority:

Critical

Reporter:

Frank Zago (Inactive)

Assignee:

Frank Zago (Inactive)

Resolution:

Fixed

Votes:

Labels:

cea

Attachments:

mdt-cdt-250000.svg

Issue Links:

Related
is related to	LU-9959	hsm: cannot schedule two different re...	Open
is related to	LU-8626	limit number of items in HSM action q...	Reopened

Severity:

Rank (Obsolete):

9223372036854775807

Description

There is an important locking issue around cdt_llog_lock when adding new HSM requests.

# time wc -l /proc/fs/lustre/mdt/snx11133-MDT0000/hsm/actions
219759 /proc/fs/lustre/mdt/snx11133-MDT0000/hsm/actions

real    11m45.068s
user    0m0.020s
sys     0m21.372s

11 minutes to cat the list is too high. Such operation should take a couple seconds at most.

The contention appears to come from the coordinator. Every time a new request is posted, the whole list of request is browsed, under that lock. That's not a problem when there is only a handful of request, but it doesn't scale when there is hundreds of thousands of them.

I recompiled a centos 7 kernel with CONFIG_LOCK_STAT on a VM. I ran test creating 10000 files and archiving them without a copytool present. Total time was 146 seconds. Lock contention result:

lock_stat version 0.3
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
                              class name    con-bounces    contentions   waittime-min   waittime-max waittime-total    acq-bounces   acquisitions   holdtime-min   holdtime-max holdtime-total
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

[...]

                     &cdt->cdt_llog_lock:          6296           6296          15.45       23074.17    43436574.06          17791          27134          25.09       37745.03   138558199.24
                     -------------------
                     &cdt->cdt_llog_lock           6296          [<ffffffffa0fb096d>] cdt_llog_process+0x9d/0x3a0 [mdt]
                     -------------------
                     &cdt->cdt_llog_lock           6296          [<ffffffffa0fb096d>] cdt_llog_process+0x9d/0x3a0 [mdt]
[...]

(time units are micro-seconds).

With waittime-total=43 seconds and holdtime-total=138s, this is a very contentious lock, way above the other locks in Lustre or the whole system.

AFAICS, contention is between these mechanisms:

adding a new request (lfs hsm_archive, ...)
changing a request status (WAITING->STARTED->SUCCEED)
removing a request (archive completed)
housekeeping (coordinator loop every 10 seconds)
dumping the list of actions from /proc

The net result is that when there is a lot of requests, they trickle down to the copytool, exacerbating the problem by increasing the number in the list.

Comments

Comment by Gerrit Updater [ 05/Apr/16 ]

Frank Zago (fzago@cray.com) uploaded a new patch: http://review.whamcloud.com/19341
Subject: ~~LU-7988~~ hsm: execute HSM coordinator once per second at most
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 6aa634f1d28e16300dbf428dcec0e38e01b5a2dc

Comment by Frank Zago (Inactive) [ 05/Apr/16 ]

Above patch is only a partial fix. Maybe executing the loop once per second is too much, and should be configurable too.

Comment by Frank Zago (Inactive) [ 06/Apr/16 ]

250000 empty files are created on a filesystem, and hsm_archive is done on them. A copytool is then started to perform these archive requests. The MDT has the patch above.

mdt-cdt-250000.svg shows, the number of records completed per second over the duration of the archival. The max number was 389 at the end. The total duration was 1h:29min:39s. It shows that the processed records is getting faster over time as the backlog queue diminishes.

Comment by Frank Zago (Inactive) [ 06/Apr/16 ]

As a side note, the creation of these 250000 files + hsm_archive by batch of 10 took 3160 seconds with this patch. Without the patch, it takes 11822 seconds.

Comment by Frank Zago (Inactive) [ 06/Apr/16 ]

I think the graph shows that things could be improved. For instance, the MDT shouldn't need to parse the whole backlog of HSM request, as only the first ones (up to /proc/.../hsm/max_requests?) have been seen by a client. The other ones need to be checked regularly possibly for timeout or cancelation, but this is not an operation that needs to be done as frequently.

In my test setup, we should be able to perform constantly at least 200 requests per seconds, as seen during the last minute, for the duration of the archival (1250 seconds total), instead of the average of 46 per seconds (5379 total).