starred/s3fs-fuse
1
0
Fork 0
mirror of https://github.com/s3fs-fuse/s3fs-fuse.git synced 2026-04-25 05:16:00 +03:00
Code Issues 305 Projects Releases 5 Packages Wiki Activity

[GH-ISSUE #2735] Negative stat cache not hit #1282

New issue
Closed
opened 2026-03-04 01:52:47 +03:00 by kerem · 4 comments
kerem commented 2026-03-04 01:52:47 +03:00
Owner
Copy link

Originally created by @francoisfreitag on GitHub (Oct 3, 2025).
Original GitHub issue: https://github.com/s3fs-fuse/s3fs-fuse/issues/2735

Additional Information

Version of s3fs being used (s3fs --version)

Commit: 37e593aeb0

Version of fuse being used (pkg-config --modversion fuse, rpm -qi fuse or dpkg -s fuse)

2.9.9-13.amzn2023.0.2

Provider (AWS, OVH, Hetzner, iDrive E2, ...)

AWS

Kernel information (uname -r)

6.1.134-152.225.amzn2023.x86_64

GNU/Linux Distribution, if applicable (cat /etc/os-release)

NAME="Amazon Linux"
VERSION="2023"
ID="amzn"
ID_LIKE="fedora"
VERSION_ID="2023"
PLATFORM_ID="platform:al2023"
PRETTY_NAME="Amazon Linux 2023.7.20250512"
ANSI_COLOR="0;33"
CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2023"
HOME_URL="https://aws.amazon.com/linux/amazon-linux-2023/"
DOCUMENTATION_URL="https://docs.aws.amazon.com/linux/"
SUPPORT_URL="https://aws.amazon.com/premiumsupport/"
BUG_REPORT_URL="https://github.com/amazonlinux/amazon-linux-2023"
VENDOR_NAME="AWS"
VENDOR_URL="https://aws.amazon.com/"
SUPPORT_END="2029-06-30"

How to run s3fs, if applicable

[x] command line

s3fs -f -s mybucket /home/clients -o allow_other -o dbglevel=debug -o _netdev -o noexec -o mp_umask=0022 -o gid=1006 -o stat_cache_expire=60 -o del_cache

s3fs syslog messages (grep s3fs /var/log/syslog, journalctl | grep s3fs, or s3fs outputs)

2025-10-03T15:25:35.184Z [INF] s3fs.cpp:s3fs_getattr(907): [path=/user/.config][pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_parent_object_access(758): [path=/user/.config]
2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_object_access(651): [path=/user]
2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.184Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/user][hit count=146]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(651): [path=/]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.185Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/][hit count=148]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(651): [path=/user/.config]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user/.config, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.185Z [DBG] cache.cpp:GetStat(98): Hit negative stat cache [path=/user/.config][hit count=1]
2025-10-03T15:25:35.186Z [INF]       curl.cpp:CreateCurlHandle(1511): already has handle, so destroyed it or restored it to pool.
2025-10-03T15:25:35.187Z [INF]       s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config][pmeta=0x7fff77d0aa10]
2025-10-03T15:25:35.187Z [INF]       curl.cpp:HeadRequest(2783): [tpath=/user/.config]
2025-10-03T15:25:35.187Z [INF]       curl.cpp:PreHeadRequest(2745): [tpath=/user/.config][sseckeypos=18446744073709551615]
2025-10-03T15:25:35.187Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config
2025-10-03T15:25:35.187Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config
2025-10-03T15:25:35.187Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config
2025-10-03T15:25:35.187Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config] [] []
2025-10-03T15:25:35.187Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.210Z [INF]       curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT
2025-10-03T15:25:35.210Z [DBG] curl.cpp:RequestPerform(2038): Body Text:
2025-10-03T15:25:35.211Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2).
2025-10-03T15:25:35.211Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config]
2025-10-03T15:25:35.211Z [INF]       s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config/][pmeta=0x7fff77d0aa10]
2025-10-03T15:25:35.211Z [INF]       curl.cpp:HeadRequest(2783): [tpath=/user/.config/]
2025-10-03T15:25:35.211Z [INF]       curl.cpp:PreHeadRequest(2745): [tpath=/user/.config/][sseckeypos=18446744073709551615]
2025-10-03T15:25:35.211Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config/
2025-10-03T15:25:35.211Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/
2025-10-03T15:25:35.211Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/
2025-10-03T15:25:35.211Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config/] [] []
2025-10-03T15:25:35.211Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.236Z [INF]       curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT
2025-10-03T15:25:35.236Z [DBG] curl.cpp:RequestPerform(2038): Body Text:
2025-10-03T15:25:35.237Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2).
2025-10-03T15:25:35.237Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config/]
2025-10-03T15:25:35.237Z [INF]   s3fs.cpp:list_bucket(3539): [path=/user/.config]
2025-10-03T15:25:35.238Z [INF]       s3fs_threadreqs.cpp:list_bucket_req_threadworker(275): List Bucket Request [path=/user/.config][query=delimiter=/&max-keys=2&prefix=user/.config/]
2025-10-03T15:25:35.238Z [INF]       curl.cpp:ListBucketRequest(3226): [tpath=/user/.config]
2025-10-03T15:25:35.238Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.238Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.238Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.238Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [GET] [/] [delimiter=/&max-keys=2&prefix=user/.config/] []
2025-10-03T15:25:35.238Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.266Z [INF]       curl.cpp:RequestPerform(1985): HTTP response code 200
2025-10-03T15:25:35.266Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty.
2025-10-03T15:25:35.266Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty.
2025-10-03T15:25:35.266Z [DBG] cache.cpp:AddNegativeStat(217): There was no cache to truncate.
2025-10-03T15:25:35.266Z [INF]       cache.cpp:AddNegativeStat(219): add negative cache entry[path=/user/.config]




2025-10-03T15:25:35.348Z [INF] s3fs.cpp:s3fs_getattr(907): [path=/user/.config][pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_parent_object_access(758): [path=/user/.config]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/user]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.348Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/user][hit count=148]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.348Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/][hit count=150]
2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/user/.config]
2025-10-03T15:25:35.349Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007]
2025-10-03T15:25:35.349Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user/.config, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no]
2025-10-03T15:25:35.349Z [DBG] cache.cpp:GetStat(98): Hit negative stat cache [path=/user/.config][hit count=1]
2025-10-03T15:25:35.350Z [INF]       curl.cpp:CreateCurlHandle(1511): already has handle, so destroyed it or restored it to pool.
2025-10-03T15:25:35.350Z [INF]       s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config][pmeta=0x7fff77d0aa10]
2025-10-03T15:25:35.350Z [INF]       curl.cpp:HeadRequest(2783): [tpath=/user/.config]
2025-10-03T15:25:35.350Z [INF]       curl.cpp:PreHeadRequest(2745): [tpath=/user/.config][sseckeypos=18446744073709551615]
2025-10-03T15:25:35.350Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config
2025-10-03T15:25:35.350Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config
2025-10-03T15:25:35.350Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config
2025-10-03T15:25:35.350Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config] [] []
2025-10-03T15:25:35.350Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.383Z [INF]       curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT
2025-10-03T15:25:35.383Z [DBG] curl.cpp:RequestPerform(2038): Body Text:
2025-10-03T15:25:35.385Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2).
2025-10-03T15:25:35.385Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config]
2025-10-03T15:25:35.385Z [INF]       s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config/][pmeta=0x7fff77d0aa10]
2025-10-03T15:25:35.385Z [INF]       curl.cpp:HeadRequest(2783): [tpath=/user/.config/]
2025-10-03T15:25:35.385Z [INF]       curl.cpp:PreHeadRequest(2745): [tpath=/user/.config/][sseckeypos=18446744073709551615]
2025-10-03T15:25:35.385Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config/
2025-10-03T15:25:35.385Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/
2025-10-03T15:25:35.385Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/
2025-10-03T15:25:35.385Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config/] [] []
2025-10-03T15:25:35.385Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.409Z [INF]       curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT
2025-10-03T15:25:35.409Z [DBG] curl.cpp:RequestPerform(2038): Body Text:
2025-10-03T15:25:35.410Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2).
2025-10-03T15:25:35.410Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config/]
2025-10-03T15:25:35.410Z [INF]   s3fs.cpp:list_bucket(3539): [path=/user/.config]
2025-10-03T15:25:35.411Z [INF]       s3fs_threadreqs.cpp:list_bucket_req_threadworker(275): List Bucket Request [path=/user/.config][query=delimiter=/&max-keys=2&prefix=user/.config/]
2025-10-03T15:25:35.411Z [INF]       curl.cpp:ListBucketRequest(3226): [tpath=/user/.config]
2025-10-03T15:25:35.411Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.411Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.411Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/
2025-10-03T15:25:35.411Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [GET] [/] [delimiter=/&max-keys=2&prefix=user/.config/] []
2025-10-03T15:25:35.411Z [INF]       curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com
2025-10-03T15:25:35.441Z [INF]       curl.cpp:RequestPerform(1985): HTTP response code 200
2025-10-03T15:25:35.441Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty.
2025-10-03T15:25:35.441Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty.
2025-10-03T15:25:35.441Z [DBG] cache.cpp:AddNegativeStat(217): There was no cache to truncate.
2025-10-03T15:25:35.441Z [INF]       cache.cpp:AddNegativeStat(219): add negative cache entry[path=/user/.config]

Details about issue

The negative cache entries are not reused on successive calls for a directory that does not exist.
I see the log “add negative cache entry” for my path (here /user/.config), however the line “Hit negative stat cache” for this path always says [hit count=1], despite the repeated calls happening within hundreds of milliseconds and the expiry being set to 60 seconds.

Not using this cache causes many extraneous HEAD requests (about 220 in my case), leading to significant performance loss (connecting to the chrooted SFTP environment takes about 20s, whereas it usually takes about 2s).

In case it helps, here’s the directory structure mounted from the S3FS-fuse we’re chrooting into:

$ tree -a /user/
/user/
├── .ssh
│   └── authorized_keys
├── studentlists
└── studentpics
Originally created by @francoisfreitag on GitHub (Oct 3, 2025). Original GitHub issue: https://github.com/s3fs-fuse/s3fs-fuse/issues/2735 <!-- -------------------------------------------------------------------------- The following information is very important in order to help us to help you. Omission of the following details may delay your support request or receive no attention at all. --------------------------------------------------------------------------- --> ### Additional Information #### Version of s3fs being used (`s3fs --version`) Commit: 37e593aeb0fd225dd05aa772a1263fad11dc079c #### Version of fuse being used (`pkg-config --modversion fuse`, `rpm -qi fuse` or `dpkg -s fuse`) 2.9.9-13.amzn2023.0.2 #### Provider (`AWS`, `OVH`, `Hetzner`, `iDrive E2`, ...) AWS #### Kernel information (`uname -r`) 6.1.134-152.225.amzn2023.x86_64 #### GNU/Linux Distribution, if applicable (`cat /etc/os-release`) ``` NAME="Amazon Linux" VERSION="2023" ID="amzn" ID_LIKE="fedora" VERSION_ID="2023" PLATFORM_ID="platform:al2023" PRETTY_NAME="Amazon Linux 2023.7.20250512" ANSI_COLOR="0;33" CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2023" HOME_URL="https://aws.amazon.com/linux/amazon-linux-2023/" DOCUMENTATION_URL="https://docs.aws.amazon.com/linux/" SUPPORT_URL="https://aws.amazon.com/premiumsupport/" BUG_REPORT_URL="https://github.com/amazonlinux/amazon-linux-2023" VENDOR_NAME="AWS" VENDOR_URL="https://aws.amazon.com/" SUPPORT_END="2029-06-30" ``` #### How to run s3fs, if applicable <!-- Describe the s3fs "command line" or "/etc/fstab" entry used. --> [x] command line ``` s3fs -f -s mybucket /home/clients -o allow_other -o dbglevel=debug -o _netdev -o noexec -o mp_umask=0022 -o gid=1006 -o stat_cache_expire=60 -o del_cache ``` #### s3fs syslog messages (`grep s3fs /var/log/syslog`, `journalctl | grep s3fs`, or `s3fs outputs`) ``` 2025-10-03T15:25:35.184Z [INF] s3fs.cpp:s3fs_getattr(907): [path=/user/.config][pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_parent_object_access(758): [path=/user/.config] 2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_object_access(651): [path=/user] 2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.184Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.184Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/user][hit count=146] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(651): [path=/] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.185Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/][hit count=148] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(651): [path=/user/.config] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.185Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user/.config, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.185Z [DBG] cache.cpp:GetStat(98): Hit negative stat cache [path=/user/.config][hit count=1] 2025-10-03T15:25:35.186Z [INF] curl.cpp:CreateCurlHandle(1511): already has handle, so destroyed it or restored it to pool. 2025-10-03T15:25:35.187Z [INF] s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config][pmeta=0x7fff77d0aa10] 2025-10-03T15:25:35.187Z [INF] curl.cpp:HeadRequest(2783): [tpath=/user/.config] 2025-10-03T15:25:35.187Z [INF] curl.cpp:PreHeadRequest(2745): [tpath=/user/.config][sseckeypos=18446744073709551615] 2025-10-03T15:25:35.187Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config 2025-10-03T15:25:35.187Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config 2025-10-03T15:25:35.187Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config 2025-10-03T15:25:35.187Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config] [] [] 2025-10-03T15:25:35.187Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.210Z [INF] curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT 2025-10-03T15:25:35.210Z [DBG] curl.cpp:RequestPerform(2038): Body Text: 2025-10-03T15:25:35.211Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2). 2025-10-03T15:25:35.211Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config] 2025-10-03T15:25:35.211Z [INF] s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config/][pmeta=0x7fff77d0aa10] 2025-10-03T15:25:35.211Z [INF] curl.cpp:HeadRequest(2783): [tpath=/user/.config/] 2025-10-03T15:25:35.211Z [INF] curl.cpp:PreHeadRequest(2745): [tpath=/user/.config/][sseckeypos=18446744073709551615] 2025-10-03T15:25:35.211Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config/ 2025-10-03T15:25:35.211Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/ 2025-10-03T15:25:35.211Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/ 2025-10-03T15:25:35.211Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config/] [] [] 2025-10-03T15:25:35.211Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.236Z [INF] curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT 2025-10-03T15:25:35.236Z [DBG] curl.cpp:RequestPerform(2038): Body Text: 2025-10-03T15:25:35.237Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2). 2025-10-03T15:25:35.237Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config/] 2025-10-03T15:25:35.237Z [INF] s3fs.cpp:list_bucket(3539): [path=/user/.config] 2025-10-03T15:25:35.238Z [INF] s3fs_threadreqs.cpp:list_bucket_req_threadworker(275): List Bucket Request [path=/user/.config][query=delimiter=/&max-keys=2&prefix=user/.config/] 2025-10-03T15:25:35.238Z [INF] curl.cpp:ListBucketRequest(3226): [tpath=/user/.config] 2025-10-03T15:25:35.238Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.238Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.238Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.238Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [GET] [/] [delimiter=/&max-keys=2&prefix=user/.config/] [] 2025-10-03T15:25:35.238Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.266Z [INF] curl.cpp:RequestPerform(1985): HTTP response code 200 2025-10-03T15:25:35.266Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty. 2025-10-03T15:25:35.266Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty. 2025-10-03T15:25:35.266Z [DBG] cache.cpp:AddNegativeStat(217): There was no cache to truncate. 2025-10-03T15:25:35.266Z [INF] cache.cpp:AddNegativeStat(219): add negative cache entry[path=/user/.config] 2025-10-03T15:25:35.348Z [INF] s3fs.cpp:s3fs_getattr(907): [path=/user/.config][pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_parent_object_access(758): [path=/user/.config] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/user] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.348Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/user][hit count=148] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.348Z [DBG] cache.cpp:GetStat(108): Hit stat cache [path=/][hit count=150] 2025-10-03T15:25:35.348Z [DBG] s3fs.cpp:check_object_access(651): [path=/user/.config] 2025-10-03T15:25:35.349Z [DBG] s3fs.cpp:check_object_access(656): [pid=127877,uid=1005,gid=1007] 2025-10-03T15:25:35.349Z [DBG] s3fs.cpp:get_object_attribute(310): [path=/user/.config, overcheck=yes, objtype=UNKNOWN(-1), notruncate=no] 2025-10-03T15:25:35.349Z [DBG] cache.cpp:GetStat(98): Hit negative stat cache [path=/user/.config][hit count=1] 2025-10-03T15:25:35.350Z [INF] curl.cpp:CreateCurlHandle(1511): already has handle, so destroyed it or restored it to pool. 2025-10-03T15:25:35.350Z [INF] s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config][pmeta=0x7fff77d0aa10] 2025-10-03T15:25:35.350Z [INF] curl.cpp:HeadRequest(2783): [tpath=/user/.config] 2025-10-03T15:25:35.350Z [INF] curl.cpp:PreHeadRequest(2745): [tpath=/user/.config][sseckeypos=18446744073709551615] 2025-10-03T15:25:35.350Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config 2025-10-03T15:25:35.350Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config 2025-10-03T15:25:35.350Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config 2025-10-03T15:25:35.350Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config] [] [] 2025-10-03T15:25:35.350Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.383Z [INF] curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT 2025-10-03T15:25:35.383Z [DBG] curl.cpp:RequestPerform(2038): Body Text: 2025-10-03T15:25:35.385Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2). 2025-10-03T15:25:35.385Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config] 2025-10-03T15:25:35.385Z [INF] s3fs_threadreqs.cpp:head_req_threadworker(46): Head Request [path=/user/.config/][pmeta=0x7fff77d0aa10] 2025-10-03T15:25:35.385Z [INF] curl.cpp:HeadRequest(2783): [tpath=/user/.config/] 2025-10-03T15:25:35.385Z [INF] curl.cpp:PreHeadRequest(2745): [tpath=/user/.config/][sseckeypos=18446744073709551615] 2025-10-03T15:25:35.385Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket/user/.config/ 2025-10-03T15:25:35.385Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/ 2025-10-03T15:25:35.385Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com/user/.config/ 2025-10-03T15:25:35.385Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [HEAD] [/user/.config/] [] [] 2025-10-03T15:25:35.385Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.409Z [INF] curl.cpp:RequestPerform(2037): HTTP response code 404 was returned, returning ENOENT 2025-10-03T15:25:35.409Z [DBG] curl.cpp:RequestPerform(2038): Body Text: 2025-10-03T15:25:35.410Z [WAN] threadpoolman.cpp:Worker(168): The instruction function returned with something error code(-2). 2025-10-03T15:25:35.410Z [DBG] s3fs_threadreqs.cpp:head_request(673): Await Head Request by error(-2) [path=/user/.config/] 2025-10-03T15:25:35.410Z [INF] s3fs.cpp:list_bucket(3539): [path=/user/.config] 2025-10-03T15:25:35.411Z [INF] s3fs_threadreqs.cpp:list_bucket_req_threadworker(275): List Bucket Request [path=/user/.config][query=delimiter=/&max-keys=2&prefix=user/.config/] 2025-10-03T15:25:35.411Z [INF] curl.cpp:ListBucketRequest(3226): [tpath=/user/.config] 2025-10-03T15:25:35.411Z [DBG] curl_util.cpp:prepare_url(213): URL is https://s3-ca-central-1.amazonaws.com/my-bucket?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.411Z [DBG] curl_util.cpp:prepare_url(246): URL changed is https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.411Z [DBG] curl.cpp:RequestPerform(1947): connecting to URL https://my-bucket.s3-ca-central-1.amazonaws.com?delimiter=/&max-keys=2&prefix=user/.config/ 2025-10-03T15:25:35.411Z [DBG] curl.cpp:insertV4Headers(2373): computing signature [GET] [/] [delimiter=/&max-keys=2&prefix=user/.config/] [] 2025-10-03T15:25:35.411Z [INF] curl_util.cpp:url_to_host(268): url is https://s3-ca-central-1.amazonaws.com 2025-10-03T15:25:35.441Z [INF] curl.cpp:RequestPerform(1985): HTTP response code 200 2025-10-03T15:25:35.441Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty. 2025-10-03T15:25:35.441Z [DBG] s3fs_xml.cpp:append_objects_from_xml_ex(332): contents_xp->nodesetval is empty. 2025-10-03T15:25:35.441Z [DBG] cache.cpp:AddNegativeStat(217): There was no cache to truncate. 2025-10-03T15:25:35.441Z [INF] cache.cpp:AddNegativeStat(219): add negative cache entry[path=/user/.config] ``` ### Details about issue The negative cache entries are not reused on successive calls for a directory that does not exist. I see the log “add negative cache entry” for my path (here `/user/.config`), however the line “Hit negative stat cache” for this path always says `[hit count=1]`, despite the repeated calls happening within hundreds of milliseconds and the expiry being set to 60 seconds. Not using this cache causes many extraneous HEAD requests (about 220 in my case), leading to significant performance loss (connecting to the chrooted SFTP environment takes about 20s, whereas it usually takes about 2s). In case it helps, here’s the directory structure mounted from the S3FS-fuse we’re chrooting into: ```bash $ tree -a /user/ /user/ ├── .ssh │   └── authorized_keys ├── studentlists └── studentpics ```
kerem closed this issue 2026-03-04 01:52:47 +03:00
kerem commented 2026-03-04 01:52:48 +03:00
Author
Owner
Copy link

@francoisfreitag commented on GitHub (Oct 3, 2025):

It might be related to 60fb557f14.

The following patch fixes the issue for me:

diff --git a/src/s3fs.cpp b/src/s3fs.cpp
index 2461b73..c4b0f5a 100644
--- a/src/s3fs.cpp
+++ b/src/s3fs.cpp
@@ -352,30 +352,16 @@ static int get_object_attribute(const char* path, struct stat* pstbuf, headers_t
     // [NOTE]
     // For mount points("/"), the Stat cache key name is "/".
     //
-    if(!need_meta){
+    if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, pmeta, pObjType)){
+        return 0;
+    }else{
         // [NOTE]
-        // Normally, if the object's stat cache exists but has only stat
-        // structure(no meta header), a HEAD request will be sent for
-        // loading meta header.
-        // But if this function is called with pmeta as nullptr, we can
-        // suppress the HEAD request by setting the meta header pointer
-        // to nullptr and making  GetStat() call.
+        // In the case of a Negative Cache, GetStat() returns false and
+        // objtype_t::NEGATIVE is set.
         //
-        if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, nullptr, parm_pObjType)){
-            return 0;
-        }
-    }else{
-        if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, pmeta, pObjType)){
-            return 0;
-        }else{
-            // [NOTE]
-            // In the case of a Negative Cache, GetStat() returns false and
-            // objtype_t::NEGATIVE is set.
-            //
-            if(objtype_t::NEGATIVE == *pObjType){
-                // When not hit cache and the reason is negative cache.
-                return -ENOENT;
-            }
+        if(objtype_t::NEGATIVE == *pObjType){
+            // When not hit cache and the reason is negative cache.
+            return -ENOENT;
         }
     }

cc @ggtakec, as you recently changed these files.

<!-- gh-comment-id:3367033922 --> @francoisfreitag commented on GitHub (Oct 3, 2025): It might be related to 60fb557f14151f0e5a935b9c9dfcac5265ac8c10. The following patch fixes the issue for me: ```diff diff --git a/src/s3fs.cpp b/src/s3fs.cpp index 2461b73..c4b0f5a 100644 --- a/src/s3fs.cpp +++ b/src/s3fs.cpp @@ -352,30 +352,16 @@ static int get_object_attribute(const char* path, struct stat* pstbuf, headers_t // [NOTE] // For mount points("/"), the Stat cache key name is "/". // - if(!need_meta){ + if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, pmeta, pObjType)){ + return 0; + }else{ // [NOTE] - // Normally, if the object's stat cache exists but has only stat - // structure(no meta header), a HEAD request will be sent for - // loading meta header. - // But if this function is called with pmeta as nullptr, we can - // suppress the HEAD request by setting the meta header pointer - // to nullptr and making GetStat() call. + // In the case of a Negative Cache, GetStat() returns false and + // objtype_t::NEGATIVE is set. // - if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, nullptr, parm_pObjType)){ - return 0; - } - }else{ - if(StatCache::getStatCacheData()->GetStat(strpath, pstbuf, pmeta, pObjType)){ - return 0; - }else{ - // [NOTE] - // In the case of a Negative Cache, GetStat() returns false and - // objtype_t::NEGATIVE is set. - // - if(objtype_t::NEGATIVE == *pObjType){ - // When not hit cache and the reason is negative cache. - return -ENOENT; - } + if(objtype_t::NEGATIVE == *pObjType){ + // When not hit cache and the reason is negative cache. + return -ENOENT; } } ``` cc @ggtakec, as you recently changed these files.
kerem commented 2026-03-04 01:52:48 +03:00
Author
Owner
Copy link

@ggtakec commented on GitHub (Oct 4, 2025):

@francoisfreitag Thanks for reporting it, I'll check what the problem is and how to fix it.

<!-- gh-comment-id:3367849632 --> @ggtakec commented on GitHub (Oct 4, 2025): @francoisfreitag Thanks for reporting it, I'll check what the problem is and how to fix it.
kerem commented 2026-03-04 01:52:48 +03:00
Author
Owner
Copy link

@ggtakec commented on GitHub (Oct 4, 2025):

@francoisfreitag
I've confirmed this bug, and your fixed code.
Your fix is ​​mostly fine(although you need to slightly change how you pass the pmeta parameter).
I've created a PR #2736, so I'd appreciate it if you could take a look.

<!-- gh-comment-id:3368118077 --> @ggtakec commented on GitHub (Oct 4, 2025): @francoisfreitag I've confirmed this bug, and your fixed code. Your fix is ​​mostly fine(although you need to slightly change how you pass the pmeta parameter). I've created a PR #2736, so I'd appreciate it if you could take a look.
kerem commented 2026-03-04 01:52:48 +03:00
Author
Owner
Copy link

@francoisfreitag commented on GitHub (Oct 4, 2025):

I checked out your branch and confirm we’re back to the usual number of HEAD requests and performance. Thank you for fixing so quickly! 🌟

<!-- gh-comment-id:3368529619 --> @francoisfreitag commented on GitHub (Oct 4, 2025): I checked out your branch and confirm we’re back to the usual number of HEAD requests and performance. Thank you for fixing so quickly! 🌟
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
master
v1.97
v1.96
v1.95
v1.94
v1.93
v1.92
v1.91
v1.90
v1.89
v1.88
v1.87
v1.86
v1.85
v1.84
v1.83
v1.82
v1.81
v1.80
v1.79
v1.78
Pre-v1.78
v1.77
v1.76
v1.75
v1.74
Labels
Clear labels   
bug

   
bug

   
dataloss

   
duplicate

   
enhancement

   
feature request

   
help wanted

   
invalid

   
need info

   
performance

   
pull-request

Mirrored from GitHub Pull Request

  
question

   
question

   
testing
No labels
bug
bug
dataloss
duplicate
enhancement
feature request
help wanted
invalid
need info
performance
pull-request
question
question
testing
Milestone
Clear milestone
No items
No milestone
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/s3fs-fuse#1282
No description provided.