ENAMETOOLONG can cause performance issue

[jackwoods]

Version: tested both on 7.8 & 9.6

Description of problem:

When ENAMETOOLONG frequently happens, it can make the server slow, and the IO load is high. Sometimes the server can be very slow and even cannot respond.

When testing, at least I can see it's logging a lot (maybe that's one of the main reasons?).

It's easy to reproduce, just try to access files with very long name (> 300 characters) concurrently.

From iotop, I can see

Total DISK READ :	0.00 B/s | Total DISK WRITE :     469.18 K/s
Actual DISK READ:	0.00 B/s | Actual DISK WRITE:       0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
15352 be/4 root        0.00 B/s   65.92 K/s  0.00 %  0.00 % glusterfsd -s g2 --volfile-id ~sten-port=49152 [glfs_iotwr005]
15512 be/4 root        0.00 B/s   50.41 K/s  0.00 %  0.00 % glusterfsd -s g2 --volfile-id ~sten-port=49152 [glfs_iotwr001]
15513 be/4 root        0.00 B/s   50.41 K/s  0.00 %  0.00 % glusterfsd -s g2 --volfile-id ~sten-port=49152 [glfs_iotwr002]
15514 be/4 root        0.00 B/s   62.04 K/s  0.00 %  0.00 % glusterfsd -s g2 --volfile-id ~sten-port=49152 [glfs_iotwr003]
11549 be/4 root        0.00 B/s  127.96 K/s  0.00 %  0.00 % glusterfs --process-name fuse ~ /mnt/glusterfs [glfs_epoll000]
11550 be/4 root        0.00 B/s  112.45 K/s  0.00 %  0.00 % glusterfs --process-name fuse ~ /mnt/glusterfs [glfs_epoll001]
    1 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % systemd --switched-root --system --deserialize 21

For other errors, it doesn't perform like this, e.g., try to access a non-existing file. Is it designed to be like this?

The log content looks like this:

[2022-10-20 05:14:16.588901 +0000] W [MSGID: 114031] [client-rpc-fops_v2.c:2625:client4_0_lookup_cbk] 0-shareddata-client-0: remote operation failed. [{path=/e/uCy3zAbeqphatMCoK1YBchHFWTbVIMQJSidMHjNyAvICIk4XNUuHR63L3vaIAZGkZY9mSCB7IuOPvZY6Rapsu1j9PNLqLmpUp1f0ppLuBl0QhXqdjwH88yr3MWyMBWFAHtpF2UAMaOpc23TZ4OrshnlDMmEDZdJNRgtQ17IyN3203YSmgdLn5CJrYlcYjccbE8Y6c0fCHIgpgxUqqUsp2amW0m5xSf6wVWfb5XJIE0E9Vo62kyww6bKmxNBglrnzmkr3GcmexwXv1RSaDQe89d3f7UXcEeZNSc0A21nDNwmz}, {gfid=00000000-0000-0000-0000-000000000000}, {errno=36}, {error=File name too long}]
[2022-10-20 05:14:16.590708 +0000] W [MSGID: 114031] [client-rpc-fops_v2.c:2625:client4_0_lookup_cbk] 0-shareddata-client-1: remote operation failed. [{path=/e/uCy3zAbeqphatMCoK1YBchHFWTbVIMQJSidMHjNyAvICIk4XNUuHR63L3vaIAZGkZY9mSCB7IuOPvZY6Rapsu1j9PNLqLmpUp1f0ppLuBl0QhXqdjwH88yr3MWyMBWFAHtpF2UAMaOpc23TZ4OrshnlDMmEDZdJNRgtQ17IyN3203YSmgdLn5CJrYlcYjccbE8Y6c0fCHIgpgxUqqUsp2amW0m5xSf6wVWfb5XJIE0E9Vo62kyww6bKmxNBglrnzmkr3GcmexwXv1RSaDQe89d3f7UXcEeZNSc0A21nDNwmz}, {gfid=00000000-0000-0000-0000-000000000000}, {errno=36}, {error=File name too long}]
[2022-10-20 05:14:16.590757 +0000] W [fuse-bridge.c:1076:fuse_entry_cbk] 0-glusterfs-fuse: 605730: LOOKUP() /e/uCy3zAbeqphatMCoK1YBchHFWTbVIMQJSidMHjNyAvICIk4XNUuHR63L3vaIAZGkZY9mSCB7IuOPvZY6Rapsu1j9PNLqLmpUp1f0ppLuBl0QhXqdjwH88yr3MWyMBWFAHtpF2UAMaOpc23TZ4OrshnlDMmEDZdJNRgtQ17IyN3203YSmgdLn5CJrYlcYjccbE8Y6c0fCHIgpgxUqqUsp2amW0m5xSf6wVWfb5XJIE0E9Vo62kyww6bKmxNBglrnzmkr3GcmexwXv1RSaDQe89d3f7UXcEeZNSc0A21nDNwmz => -1 (File name too long)
The message "W [MSGID: 114031] [client-rpc-fops_v2.c:2625:client4_0_lookup_cbk] 0-shareddata-client-1: remote operation failed. [{path=/n/xbxWH39Y8UJWlh95ObbaXBlmubxYFNZmj45FE8f5wjgNpJnaA8wP6BpWwwvRBVgsLI5QAztwgS4CFe2ocxPTqclBkMURU2f7zjNyFd8HYUiUqnzUEe66V9mpU8xjFUtgG21KE5u6YDN2WL6Pbc0Nk9h8ESGXjb45s11XxdksCZHmoVC9SGpor9NmtoMj1S8DISBRhgX6OlgPiinQXr0BKFt1amjpFeuwugoOzMPh3oRycYH0tuDOF72tCUl5bdQ8Nt2OZBfY3hdSVZROrIec8FoQTWe1DI3PyE1d0s0yj0PE}, {gfid=00000000-0000-0000-0000-000000000000}, {errno=36}, {error=File name too long}]" repeated 4 times between [2022-10-20 05:12:23.763324 +0000] and [2022-10-20 05:12:23.769271 +0000]
The message "W [MSGID: 114031] [client-rpc-fops_v2.c:2625:client4_0_lookup_cbk] 0-shareddata-client-0: remote operation failed. [{path=/n/xbxWH39Y8UJWlh95ObbaXBlmubxYFNZmj45FE8f5wjgNpJnaA8wP6BpWwwvRBVgsLI5QAztwgS4CFe2ocxPTqclBkMURU2f7zjNyFd8HYUiUqnzUEe66V9mpU8xjFUtgG21KE5u6YDN2WL6Pbc0Nk9h8ESGXjb45s11XxdksCZHmoVC9SGpor9NmtoMj1S8DISBRhgX6OlgPiinQXr0BKFt1amjpFeuwugoOzMPh3oRycYH0tuDOF72tCUl5bdQ8Nt2OZBfY3hdSVZROrIec8FoQTWe1DI3PyE1d0s0yj0PE}, {gfid=00000000-0000-0000-0000-000000000000}, {errno=36}, {error=File name too long}]" repeated 4 times between [2022-10-20 05:12:23.763418 +0000] and [2022-10-20 05:12:23.769305 +0000]
The message "W [MSGID: 114031] [client-rpc-fops_v2.c:2625:client4_0_lookup_cbk] 0-shareddata-client-1: remote operation failed. [{path=/d/g8FIRgKeY1Y5ZAuMlLZvudDznsdLfzOqAKR6hwXr6fXHJrm1ebnNrseVF8tpo5av0G3TiUqDKBwgoVmRlwYJkVo57bfE44fbFhxrEwtOo3izNYIxKqFYXgOlYd5kRBZQMxIIbI5rybIGRI4ysJpI2ysJBPR4f77lGgnnN1XfDw7Ympmvxkprm1maM17SJtxR8om2Agqo5OvdAYZGfTSO6Eih3Vd71BeuYlhxMZYyPQk4cFHR3pyrvnueTeMu2o9L0EOKFu4ZWtQImRNo7agOHrOhI11YCArxgiQKWIl2G1iY}, {gfid=00000000-0000-0000-0000-000000000000}, {errno=36}, {error=File name too long}]" repeated 2 times between [2022-10-20 05:12:23.778157 +0000] and [2022-10-20 05:12:23.780852 +0000]
[2022-10-20 05:17:40.261762 +0000] I [MSGID: 108031] [afr-common.c:3203:afr_local_discovery_cbk] 0-shareddata-replicate-0: selecting local read_child shareddata-client-1

[rodericliu]

jackwoods is my colleague and he did this in a test environment.

We are using Glusterfs Replicated Volume as our production image storage. We mounted the gluster volume on the server runs nginx which will serve the image requests for our front image cache servers.

Recently we enabled secure token for our images and had a bug in generating the image url where the "?" is missed. So the expected url XXXX.jpg?token=XXXXXXX become XXXX.jpgtoken=XXXXXXX which caused the file name too long. After some days running, the glusterfs cluster started to have high iowait and the nginx response became very slow due to the high iowait on glusterfs servers.

After we fixed the bug, iowait became normal on the glusterfs servers when no more those LONG NAME requests.

[xhernandez]

@jackwoods, @rodericliu are you sure the issue is that the name is too long ?

An invalid name (either because it doesn't exist, or because the name is too long, or for any other reason) means that the lookup operation will fail. A failed lookup is not cached by default, so if the client insists in trying to access the same file again and again, a lot of lookups will be sent to the bricks.

Could this explain the problem ?

As a test, you can try enabling nl-cache:

# gluster volume set <volname> nl-cache on

This will cache lookup errors to avoid sending them again in a short period.

[xhernandez]

Additionally, if the log line is written many times, it could also contribute to stress the filesystem where logs are stored (/var/log/glusterfs).

[jackwoods]

Thanks, now we first avoid the error happens

[stale[bot]]

Thank you for your contributions. Noticed that this issue is not having any activity in last ~6 months! We are marking this issue as stale because it has not had recent activity. It will be closed in 2 weeks if no one responds with a comment here.