|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/40712
Subject: LU-14139 llite: simply callback handling for async getattr
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: bdbf864aa6d02b93ed2977b2e48c3890d055f1b3
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/40720
Subject: LU-14139 statahead: batched statahead processing
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 993903398a61e4dd515b3fcc2ae264511e34fad5
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/40943
Subject: LU-14139 statahead: add stats for batch rpc requests
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: fe3ba9bd088fa5b218a288acf0e34a4485dcbb41
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/40945
Subject: LU-14139 ptlrpc: grow reply buffer properly for batch request
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: b39b4e7897dda3737eb874bbdd2e69ce19a84f93
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/41220
Subject: LU-14139 statahead: add test for batch statahead processing
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 6de31acdd0804ad8b5d656a00a1f687423c1c042
|
|
Here is benchmark resutls of batch statahead patch.
It created a single shared directory and also created 1M files (47001 byte) in the directory.
The workload is "ls -l" to that directory on the client without any caching (servers and client) and mesured elapsed time.
| statahead_max |
statahead_batch_max
(only with patch) |
master
(sec) |
master+patch
(sec) |
| 32 |
0 |
- |
181 |
| 32 |
32 |
180 |
40 |
| 64 |
64 |
183 |
35 |
| 128 |
128 |
181 |
33 |
| 256 |
256 |
183 |
30 |
| 512 |
512 |
178 |
29 |
| 1024 |
1024 |
179 |
28 |
This is a great improvement and the patch demonstrated 6x speeds up (180sec down to 30sec) for "ls -l" workload.
However, it's still limited use case with current statahead. sthatahead needs to start stat() invoked to files before close() of that directory.
"ls -l" was a good example, but statahead doesn't trigger for other cases with few general command today. (e.g. "du <dir>" or "find <dir> -size X") It would be nice to have additional improvements for them if it's possible.
|
|
Verify that it work with the command:
mkdir $dir || error "failed to mkdir $dir"
touch $dir/$tfile.{0..9}
$LCTL set_param mdc.*.batch_stats=0
lctl get_param -n llite.*.statahead_stats
strace -o output du -a $dir
lctl get_param -n llite.*.statahead_stats
lctl get_param -n mdc.*.batch_stats
The output of the test scripts:
mdc.lustre-MDT0000-mdc-ffff97f3bde68000.batch_stats=0
statahead total: 0
statahead wrong: 0
agl total: 0
0 /mnt/lustre/d123d.sanity/f123d.sanity.6
0 /mnt/lustre/d123d.sanity/f123d.sanity.2
0 /mnt/lustre/d123d.sanity/f123d.sanity.5
0 /mnt/lustre/d123d.sanity/f123d.sanity.3
0 /mnt/lustre/d123d.sanity/f123d.sanity.7
0 /mnt/lustre/d123d.sanity/f123d.sanity.9
0 /mnt/lustre/d123d.sanity/f123d.sanity.4
0 /mnt/lustre/d123d.sanity/f123d.sanity.8
0 /mnt/lustre/d123d.sanity/f123d.sanity.1
0 /mnt/lustre/d123d.sanity/f123d.sanity.0
4 /mnt/lustre/d123d.sanity
statahead total: 1
statahead wrong: 0
agl total: 1
snapshot_time: 1611218329. 88052008 (secs.nsecs)
subreqs per batch batchs % cum %
1: 1 50 50
2: 0 0 50
4: 0 0 50
8: 1 50 100
|
|
Yingjin, for the next refresh of this patch, please include the benchmark results from Shuichi in the commit message of the patch.
Note that different versions of userspace tools (e.g. du, find) may sometimes behave differently between e.g. RHEL7 and 8, or if run as root or a regular user, so it is always useful to include the version of the utility that is working or not.
|
|
See and try the following test cases. There are still something wrong and batch doesn't trigger properly if the number of file are increased in the directory.
100 files
1000 files
10000 files
|
|
I thought I found the reason why statahead does not trigger:
9 dentries:
0 /mnt/lustre/d123d.sanity/f123d.sanity.6
0 /mnt/lustre/d123d.sanity/f123d.sanity.2
0 /mnt/lustre/d123d.sanity/f123d.sanity.5
0 /mnt/lustre/d123d.sanity/f123d.sanity.3
0 /mnt/lustre/d123d.sanity/f123d.sanity.7
0 /mnt/lustre/d123d.sanity/f123d.sanity.9
0 /mnt/lustre/d123d.sanity/f123d.sanity.4
0 /mnt/lustre/d123d.sanity/f123d.sanity.8
0 /mnt/lustre/d123d.sanity/f123d.sanity.1
0 /mnt/lustre/d123d.sanity/f123d.sanity.0
4 /mnt/lustre/d123d.sanity
10000 dentries
newfstatat(4, "f123d.sanity.1", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.2", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.3", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.4", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.5", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.6", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.7", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.8", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.9", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.10", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.11", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.12", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(4, "f123d.sanity.13", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_SYMLINK_NOFOLLOW) = 0
...
When the entry count within a directory is larger than 10000, the program 'du' will first sort according to the file name.
While in Lustre the dentries are obtained from MDT by the order of the name hash, the first dentry are not same, so it will not start the statahead thread...
I though if the file name has certain kind of the regular pattern, i.e. mdtest.$(i+step), we can optimize to do statahead also.
i.e.
- mdtest.0000~mdtest.1000 could do batched/async statahead by thread A;
- mdtest.1001 ~mdtest.2000 could do batched/async statahead by thread B;
...
|
I though if the file name has certain kind of the regular pattern, i.e. mdtest.$(i+step), we can optimize to do statahead also.
i.e.
mdtest.0000~mdtest.1000 could do batched/async statahead by thread A;
mdtest.1001 ~mdtest.2000 could do batched/async statahead by thread B;
Okey, then "ls -l dir/*" could be also optimized as well if filename is a pattern. This is very useful for ML/AI with ingested data that have typically a rule of filename in the directory.
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/43707
Subject: LU-14139 ptlrpc: grow PtlRPC properly when prepare sub request
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: dd29ac0b580430c12b838f7a16fe66cb18638eb9
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/40712/
Subject: LU-14139 llite: simplify callback handling for async getattr
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: cbaaa7cde45f59372c75577d7274f7e2e38acd24
|
|
Hi Andreas, SiYao
Any idea and suggestions about how to reproduce the hang caused by LU-14139?
I added a racer test case between rm -rf and ls -l, but can not reproduce the bug...
Thanks,
Qian
|
|
Yingjin Qian (qian@ddn.com) uploaded a new patch: https://review.whamcloud.com/44488
Subject: LU-14139 llite: simplify callback handling for async getattr
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 93e998a154bef2aaea5b1e527da57e1bcce11a5a
|
|
After discussed with Lai, found the following stack dump:
schedule+0x38/0xa0
[24373.096771] obd_get_request_slot+0x19e/0x2b0 [obdclass]
[24373.097828] ? finish_wait+0x80/0x80
[24373.098595] ldlm_cli_enqueue+0x5f2/0x9c0 [ptlrpc]
[24373.099578] ? ldlm_expired_completion_wait+0x250/0x250 [ptlrpc]
[24373.100929] ? ll_md_need_convert+0x160/0x160 [lustre]
[24373.101985] ? mdc_changelog_cdev_finish+0x210/0x210 [mdc]
[24373.103062] mdc_enqueue_base+0x335/0x1340 [mdc]
[24373.103996] ? mdc_revalidate_lock+0x1a4/0x1d0 [mdc]
[24373.104972] mdc_intent_lock+0x210/0x530 [mdc]
[24373.105872] ? ll_md_need_convert+0x160/0x160 [lustre]
[24373.106904] ? ldlm_expired_completion_wait+0x250/0x250 [ptlrpc]
[24373.108080] ? mdc_changelog_cdev_finish+0x210/0x210 [mdc]
[24373.109211] lmv_revalidate_slaves+0x607/0x9e0 [lmv]
[24373.110236] ? ll_md_need_convert+0x160/0x160 [lustre]
[24373.111258] lmv_merge_attr+0x32/0x170 [lmv]
[24373.112183] ll_update_lsm_md+0xb10/0xe60 [lustre]
[24373.113163] ll_update_inode+0x41f/0x650 [lustre]
[24373.114109] ll_read_inode2+0x4e/0x3a0 [lustre]
[24373.115023] ll_iget+0xbd/0x320 [lustre]
[24373.115843] ll_prep_inode+0x374/0x990 [lustre]
[24373.116754] ? mdc_revalidate_lock+0x5b/0x1d0 [mdc]
[24373.117739] ? lprocfs_counter_add+0xd2/0x140 [obdclass]
[24373.118798] ll_statahead_interpret+0x51b/0xb90 [lustre]
In the statahead callback interpret, it generate new RPCs for striped dir: lmv_merge_attr() -> lmv_revalidate_slaves() -> mdc_intent_lock(). It may cause the problem using out the RPC slots.
There are two solution for this problem:
1. The origin solution: put the intermediate list, let the statahead thread to do revalidate slaves for striped dir. And here it can be improved to just put the striped dir to the intermediate list handling by the statahead thread.
2. The simplest solution: once found it is a striped dir, drop the result, let the scanning process do the stat() on the striped dir in synchronous way.
Which one should we used? Any suggestions?
|
|
I don't have a good idea on how complex each solution is. The first one sounds like it would provide better performance (not causing a stall in the statahead pipeline), but for now the more simple/robust solution is best so that you can move ahead with the other statahead patches.
|
|
After the patch:
LU-15121 llite: skip request slot for lmv_revalidate_slaves() https://review.whamcloud.com/#/c/45275/,
I think it solve the problem of using out the RPC slots.
The old patch should not cause the hang waiting for RPC slots.
|
|
"Yingjin Qian <qian@ddn.com>" uploaded a new patch: https://review.whamcloud.com/45648
Subject: LU-14139 llite: simplify callback handling for async getattr
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 4a891e844afdc8c2c18155efba5a1881fda92f0b
|
|
"Yingjin Qian <qian@ddn.com>" uploaded a new patch: https://review.whamcloud.com/46309
Subject: LU-14139 statahead: add total hit/miss count stats
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: c626be11590c894aa5167060e392b7b582b6b2e6
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/45648/
Subject: LU-14139 llite: simplify callback handling for async getattr
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 509d7305ce8a01351cb77c26aaad078edca0e09c
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/46309/
Subject: LU-14139 statahead: add total hit/miss count stats
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: b9167201a00e38ce8f63d3013ab89571c3492f52
|
|
I'm hitting freeze in replay-dual/26 quite often, bisection gives the following stats:
COMMIT TESTED PASSED FAILED COMMIT DESCRIPTION
76c3fa96dc 10 5 4 BAD LU-16082 ldiskfs: old-style EA inode handling fix
2447564e12 6 1 5 BAD LU-16011 lnet: use preallocate bulk for server
3f0bee2502 6 2 4 BAD LU-15959 kernel: new kernel [SLES15 SP4 5.14.21-150400.24.18.1]
cf35c54224 5 3 2 BAD LU-14745 tests: ensure sanity/51d has enough objects
bbe5e98180 3 0 3 BAD LU-15874 kernel: new kernel [RHEL 9.0 5.14.0-70.22.1.el9_0]
1ef1fa06b2 7 3 4 BAD LU-16078 o2iblnd: Salt comp_vector
0109cee261 10 4 6 BAD LU-13813 tests: fix stack_trap in conf-sanity test 110/111
b9167201a0 3 0 3 BAD LU-14139 statahead: add total hit/miss count stats
509d7305ce 6 4 1 BAD LU-14139 llite: simplify callback handling for async getattr
73ac8e35e5 10 10 0 GOOD LU-16061 osd-ldiskfs: clear EXTENT_FL for symlink agent inode
907dc0a2d3 10 10 0 GOOD LU-16060 osd-ldiskfs: copy nul byte terminator in writelink
33efefc496 10 10 0 GOOD LU-16037 build: remove quotes from %{mkconf_options}
|
|
Hi Alex,
What's your testing environment (how many MDTs and clients) ?
Is there any Maloo testing log available for the freeze in replay-dual/26?
Thanks,
Qian
|
|
just local testing:
FSTYPE=ldiskfs MDSCOUNT=2 MDSSIZE=500000 OSTSIZE=1000000 OSTCOUNT=2 REFORMAT=yes REFORMAT=yes bash replay-dual.sh
this is the unique stack traces:
schedule,osc_extent_wait,osc_cache_wait_range,osc_io_fsync_end,cl_io_end,lov_io_end_wrapper,lov_io_fsync_end,cl_io_end,cl_io_loop,cl_sync_file_range,ll_writepages,do_writepages,__writeback_single_inode,writeback_sb_inodes,wb_writeback,wb_workfn,process_one_work,worker_thread
PIDs(1): "kworker/u4:3":190
schedule,osc_extent_wait,osc_cache_wait_range,osc_io_fsync_end,cl_io_end,lov_io_end_wrapper,lov_io_fsync_end,cl_io_end,cl_io_loop,cl_sync_file_range,vvp_prune,cl_object_prune,lov_conf_set,cl_conf_set,cl_file_inode_init,ll_update_inode,ll_iget,ll_prep_inode,ll_statahead_interpret_common,ll_statahead_interpret,mdc_intent_getattr_async_interpret,ptlrpc_check_set,ptlrpcd
PIDs(2): "ptlrpcd_00_00":3041 "ptlrpcd_00_01":3042
schedule,obd_get_request_slot,ldlm_cli_enqueue,mdc_enqueue_base,mdc_intent_lock,lmv_intent_lock,ll_lookup_it.constprop.4,ll_lookup_nd,__lookup_slow,lookup_slow,walk_component,path_lookupat,filename_lookup,vfs_statx,__se_sys_newstat
PIDs(1): "dbench":31243
schedule,rwsem_down_read_slowpath,down_read,lov_io_init,cl_io_init0,cl_sync_file_range,ll_writepages,do_writepages,__writeback_single_inode,writeback_sb_inodes,__writeback_inodes_wb,wb_writeback,get_nr_inodes,wb_workfn,_raw_spin_unlock_irq,process_one_work,worker_thread
PIDs(1): "kworker/u4:4":31792
schedule,wait_for_common,osc_io_setattr_end,cl_io_end,lov_io_end_wrapper,lov_io_call,lov_io_end,cl_io_end,cl_io_loop,cl_setattr_ost,ll_setattr_raw,notify_change,utimes_common,do_utimes,__se_sys_utimensat
PIDs(1): "tar":33454
|
|
I did re-ran test "ls -l" (1M x 47001 byte file in single directory) with latest patch serices https://review.whamcloud.com/#/c/fs/lustre-release/+/49291/
master (commit:c74c630)
patched
I see elapse time downed from 33sec to 27sec with patch.
as far as I see batch_stats, more than 950K (64 * 12168 + 32 * 107 + 16 * 10736) of 1M requests can be batched with more than 16 request aggregations. Maybe, this is not so bad? However, we are still spending more than 27 sec here.
Here is additinal tests something like "drop cache; ls -l; ls -l"
In fact, we still spent 25sec even without drop cache. there were nothing requests from client to servers.
Because everything came from caches on local client.
So, somehow, "ls -l" for 1M files take 25sec even everything comes from caches.
Without patch, we needed another 8sec for round-trip between clients and servers, but it can downed to 2sec by batched statahead patch.
|
|
It looks like the client is still sending 125k x 8=1M glimpse RPCs to the OSTs to fetch the file size. I guess this is because the client is not caching all 1M of the OST DLM locks on the objects between "ls -l" calls? Did you check OSC LRU size? I suspect this would have a sudden jump in speed once the number of files is small enough that all the OST DLM locks are cached.
|
So, somehow, "ls -l" for 1M files take 25sec even everything comes from caches.
'ls -l' is doing other things after recived results. sorting, writing output, etc. sorting some impacts, but majority of time are still spent 1M times for statx() and getxattr() even all data in the cache.
Just in case, this is a test resutls with/without caches, but ls doesn't sort for result list.
still same 2 sec overheads for client and server roundtrips. So, batched statahead reduced that overheads to 2sec from 8 sec which means 4x speedup.
|
|
it might be not related to LU-14139 direclty, but still interested in why Lustre still takes 25sec for second 'ls -l'.
It looks like the client is still sending 125k x 8=1M glimpse RPCs to the OSTs to fetch the file size. I guess this is because the client is not caching all 1M of the OST DLM locks on the objects between "ls -l" calls? Did you check OSC LRU size? I suspect this would have a sudden jump in speed once the number of files is small enough that all the OST DLM locks are cached.
As far as I observed, all locks seems to be kept as well. nothing shrinks or re-granting locks between two 'ls -l'.
Here is same 1M files tests for ext4 on local disk of client.
I'm also attaching FG which captured at second 'ls -l' on Lustre.
|
|
there are no LNET messages go out in 2nd 'ls -l'.
I've opened a separate ticket for more investigations. https://jira.whamcloud.com/browse/LU-16365
|
|
From the attaching FG, lots of time costs are:
__ldlm_handle2lock () ->class_handle2object()
ldlm_resource_get() >cfs_hash_bd_lookup_intent()>ldlm_res_hop_keycmp()
Each of them costs 5% for data and metadata DLM lock matching on the client side. All takes about 20% of the total sample...
It seems that the hash for looking up the lock handle and resource take lots of time.
And ldlm_res_hop_keycmp() reaches 5%, it means there are lots of elements in the same bucket of the hash table. We should increase the hash table and use the resizable hash table.
For class_handle2object for locks, we should maintain the lock handle per target (osc/mdc) lock namespace, not shared a single global hash table for handle on the client or even the server.
|
|
Is there a patch that converts ldlm to use rhashtable?
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/40720/
Subject: LU-14139 statahead: batched statahead processing
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 4435d0121f72aac3ad01c98a33b265a496359890
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/40943/
Subject: LU-14139 statahead: add stats for batch RPC requests
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: a20f25d24b5f0ce7b5e77f7c596bffd0450cbdae
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/40945/
Subject: LU-14139 ptlrpc: grow reply buffer properly for batch request
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 5edb883b44ac707528ce2c0bc812d65b9ffb4a50
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/43707/
Subject: LU-14139 ptlrpc: grow PtlRPC properly when prepare sub request
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 5a2dfd36f9c2b6c10ab7ba44b0e9e86372623fde
|
|
"Oleg Drokin <green@whamcloud.com>" merged in patch https://review.whamcloud.com/c/fs/lustre-release/+/41220/
Subject: LU-14139 statahead: add test for batch statahead processing
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: cd1e7bdd903ada4467064eaf8613ec62a358fa1c
|
|
Landed for 2.16
|
Generated at Sat Feb 10 03:07:10 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
ls.svg