Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Mount-s3 : Memory Usage Not Reduced After ReadFile Operation #1182

Open
Arasan-B opened this issue Dec 4, 2024 · 3 comments
Open

Mount-s3 : Memory Usage Not Reduced After ReadFile Operation #1182

Arasan-B opened this issue Dec 4, 2024 · 3 comments
Labels
bug Something isn't working

Comments

@Arasan-B
Copy link

Arasan-B commented Dec 4, 2024 •
edited
Loading

Mountpoint for Amazon S3 version

mount-s3 1.12.0

AWS Region

us-west-2

Describe the running environment

  • Instance type: c7a.large
  • Ubuntu 24.04 LTS
  • Arch: x86

Mountpoint options

/usr/bin/mount-s3 my-bucket /my-dir --debug

What happened?

We run a process that performs os.ReadFile() with the exact path of file against mount-s3. During this process, we observe mount-s3 to consume up-to 40 to 50% of available RAM and stays there even when there is no ReadFile operation.

Observed the utilization of mount-s3 not reducing from 40 to 50%, unless we manually perform a re-mount operation.

Bucket size is 8.3TB with ~2000 objects

Relevant log output

Dec 04 09:21:56 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(612912) ino 0x00000000000000f1 RELEASEDIR fh FileHandle(72678), flags 0x8000, flush false, lock owner None
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: fuse.op_latency_us[op=lookup]: n=2: min=15104 p10=15167 p50=15167 avg=22576.00 p90=30079 p99=30079 p99.9=30079 max=30079
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: fuse.op_latency_us[op=opendir]: n=35: min=6 p10=7 p50=10 avg=30.17 p90=135 p99=170 p99.9=170 max=170
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: fuse.op_latency_us[op=readdirplus]: n=75: min=5 p10=7 p50=73 avg=6234.84 p90=13695 p99=29951 p99.9=29951 max=29951
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: fuse.op_latency_us[op=releasedir]: n=35: min=4 p10=5 p50=7 avg=7.46 p90=9 p99=34 p99.9=34 max=34
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: fuse.readdirplus.entries: 347 (n=75)
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.forced_used: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.get_usage_latency_us: n=39: min=0 p10=0 p50=0 avg=1.51 p90=0 p99=58 p99.9=58 max=58
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.mem_limit: 2013265920
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_allocated: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_cutoff: 33554432
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_num_blocks: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_reserved: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_used: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.secondary_reserved: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.secondary_used: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.host_count[host=bucketname.s3.us-west-2.amazonaws.com]: 300
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_default_network_io: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_copy_network_io: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_get_network_io: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_put_network_io: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_being_prepared: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_being_processed: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_stream_queued_waiting: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_streaming_response: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_total_network_io: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.request_queue_size: 0
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.canceled[op=head_object]: 1
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.failures[op=head_object,status=404]: 1
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=head_object]: n=2: min=12544 p10=12607 p50=12607 avg=13792.00 p90=15039 p99=15039 p99.9=15039 max=15039
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=list_objects]: n=37: min=10624 p10=11135 p50=12415 avg=13375.14 p90=14399 p99=29823 p99.9=29823 max=29823
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=head_object]: n=2: min=12544 p10=12607 p50=12607 avg=13792.00 p90=15039 p99=15039 p99.9=15039 max=15039
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=list_objects]: n=37: min=10688 p10=11263 p50=12415 avg=13456.43 p90=14527 p99=29951 p99.9=29951 max=29951
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests[op=head_object]: 2 (n=2)
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests[op=list_objects]: 37 (n=37)
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.canceled[op=head_object,type=HeadObject]: 1
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.failures[op=head_object,type=HeadObject,status=404]: 1
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=head_object,type=HeadObject]: n=1: min=6912 p10=6943 p50=6943 avg=6928.00 p90=6943 p99=6943 p99.9=6943 max=6943
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=list_objects,type=Default]: n=37: min=9792 p10=10175 p50=11391 avg=12235.24 p90=12799 p99=28415 p99.9=28415 max=28415
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.total_latency_us[op=head_object,type=HeadObject]: n=2: min=12224 p10=12287 p50=12287 avg=13280.00 p90=14335 p99=14335 p99.9=14335 max=14335
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.total_latency_us[op=list_objects,type=Default]: n=37: min=10624 p10=11135 p50=12287 avg=13316.32 p90=14079 p99=29823 p99.9=29823 max=29823
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests[op=head_object,type=HeadObject]: 2 (n=2)
Dec 04 09:21:57 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests[op=list_objects,type=Default]: 37 (n=37)
@Arasan-B Arasan-B added the bug Something isn't working label Dec 4, 2024
@Arasan-B Arasan-B changed the title Memory Usage is not reduced Mount-s3 : Memory Usage Not Reduced After ReadFile Operation Dec 4, 2024
@unexge
Copy link
Contributor

unexge commented Dec 4, 2024

Hey @Arasan-B, thanks for the report. Could you please add --debug to your Mountpoint options and share the whole log? There are prefetch.* and process.memory_usage metrics which might be useful in this case. Also, one thing to note is that, even though Mountpoint does not use some portion of the previously allocated memory anymore, it might not be returned/reclaimed by Linux kernel until there is a need (e.g. system under memory pressure) to do so.

It's an ongoing effort to reduce memory usage of Mountpoint, and it's tracked with #987.

@Arasan-B
Copy link
Author

Arasan-B commented Dec 4, 2024

@unexge , Adding debug logs

Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091182) ino 0x0000000000000ae9 RELEASEDIR fh FileHandle(143495), flags 0x8000, flush false, lock owner None
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091184) ino 0x0000000000000aea OPENDIR flags 0x8000
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091186) ino 0x0000000000000aea READDIRPLUS fh FileHandle(143496), offset 0, size 4096
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] readdirplus{req=7091186 ino=2794 fh=143496 offset=0}:list_objects{id=267227 bucket=my-bucket continued=false delimiter=/ max_keys=1000 prefix=key1/key2>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] read{req=7090418 ino=5134 fh=143476 offset=10712252416 size=32768 name=file_name.mxf}:prefetch{range=10712252416..32936499544 >
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] open{req=7091178 ino=5134 pid=1087 name=file_name.mxf}:head_object{id=267225 bucket=my-bucket key=key2/135855>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] open{req=7091178 ino=5134 pid=1087 name=file_name.mxf}:head_object{id=267225 bucket=my-bucket key=key2/135855>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091188) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713305088, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091190) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713370624, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091192) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713501696, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] open{req=7091178 ino=5134 pid=1087 name=file_name.mxf}:list_objects{id=267226 bucket=my-bucket continued=false deli>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] open{req=7091178 ino=5134 pid=1087 name=file_name.mxf}:list_objects{id=267226 bucket=my-bucket continued=false deli>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] open{req=7091178 ino=5134 pid=1087 name=file_name.mxf}: mountpoint_s3::fs: new file handle created fh=143497 ino=5134
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091194) ino 0x000000000000140e READ fh FileHandle(143477), offset 10679681024, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091196) ino 0x000000000000140e READ fh FileHandle(143477), offset 10679746560, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091198) ino 0x000000000000140e READ fh FileHandle(143477), offset 10679877632, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091200) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680008704, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091202) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680139776, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091204) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680270848, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] read{req=7090926 ino=5134 fh=143488 offset=10745806848 size=32768 name=file_name.mxf}:prefetch{range=10745806848..32936499544 >
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] readdirplus{req=7091186 ino=2794 fh=143496 offset=0}:list_objects{id=267227 bucket=my-bucket continued=false delimiter=/ max_keys=1000 prefix=key1/key2>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091206) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747215872, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091208) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747084800, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] readdirplus{req=7091186 ino=2794 fh=143496 offset=0}:list_objects{id=267227 bucket=my-bucket continued=false delimiter=/ max_keys=1000 prefix=key1/key2>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091210) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680401920, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091224) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747150336, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091212) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680532992, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091214) ino 0x000000000000140e READ fh FileHandle(143481), offset 10721624064, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091216) ino 0x000000000000140e FLUSH fh FileHandle(143479), lock owner LockOwner(6705591401970432888)
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] read{req=7090768 ino=5134 fh=143487 offset=10737418240 size=32768 name=file_name.mxf}:prefetch{range=10737418240..32936499544 >
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091218) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713399296, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091226) ino 0x000000000000140e RELEASE fh FileHandle(143479), flags 0x8800, flush false, lock owner None
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091228) ino 0x000000000000089f LOOKUP name "file_name.mxf"
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] read{req=7090604 ino=5134 fh=143485 offset=10729029632 size=32768 name=file_name.mxf}:prefetch{range=10729029632..32936499544 >
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] lookup{req=7091228 ino=2207 name="file_name.mxf"}:head_object{id=267228 bucket=my-bucket key=key2/1358551_Muf>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] lookup{req=7091228 ino=2207 name="file_name.mxf"}:list_objects{id=267229 bucket=my-bucket continued=false delimiter>
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091230) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747346944, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091232) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747412480, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091220) ino 0x000000000000140e READ fh FileHandle(143487), offset 10737975296, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091222) ino 0x000000000000140e FLUSH fh FileHandle(143485), lock owner LockOwner(6705591401970432888)
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091234) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713464832, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091236) ino 0x000000000000140e READ fh FileHandle(143476), offset 10713595904, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091238) ino 0x000000000000140e READ fh FileHandle(143487), offset 10738040832, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091240) ino 0x000000000000140e READ fh FileHandle(143487), offset 10738171904, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091242) ino 0x000000000000140e READ fh FileHandle(143481), offset 10721689600, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091244) ino 0x000000000000140e READ fh FileHandle(143481), offset 10721820672, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091246) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680664064, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091248) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680795136, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091250) ino 0x000000000000140e READ fh FileHandle(143481), offset 10721951744, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091252) ino 0x000000000000140e READ fh FileHandle(143481), offset 10722082816, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091254) ino 0x000000000000140e READ fh FileHandle(143481), offset 10722213888, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091256) ino 0x000000000000140e READ fh FileHandle(143488), offset 10747215872, size 65536
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091258) ino 0x000000000000140e READ fh FileHandle(143493), offset 10754195456, size 32768
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091260) ino 0x000000000000140e READ fh FileHandle(143477), offset 10680926208, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091262) ino 0x000000000000140e READ fh FileHandle(143477), offset 10681057280, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091264) ino 0x000000000000140e READ fh FileHandle(143477), offset 10681188352, size 131072
Dec 04 13:49:02 hostname mount-s3[443613]: [DEBUG] fuser::request: FUSE(7091266) ino 0x000000000000140e RELEASE fh FileHandle(143485), flags 0x8800, flush false, lock owner None
......
......
.....
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: process.memory_usage: 1489829888
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.forced_used: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.get_usage_latency_us: n=304: min=0 p10=0 p50=0 avg=0.27 p90=0 p99=2 p99.9=51 max=51
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.mem_limit: 2013265920
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_allocated: 134217728
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_cutoff: 33554432
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_num_blocks: 1
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_reserved: 8388608
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.primary_used: 8388608
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.secondary_reserved: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.buffer_pool.secondary_used: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.host_count[host=my-bucket.s3.us-west-2.amazonaws.com]: 300
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_default_network_io: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_copy_network_io: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_get_network_io: 1
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_auto_ranged_put_network_io: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_being_prepared: 1
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_being_processed: 2
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_stream_queued_waiting: 292
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_requests_streaming_response: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.num_total_network_io: 1
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.read_window_excess_bytes: n=62: min=393216 p10=7766015 p50=7798783 avg=7500387.10 p90=8323071 p99=8388607 p99.9=8388607 max=8388607
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.request_queue_size: 0
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.client.total_bytes[type=read]: 597426176 (n=97)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.canceled[op=get_object]: 57 (n=57)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.canceled[op=head_object]: 6 (n=6)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.failures[op=head_object,status=404]: 30 (n=30)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=get_object]: n=60: min=21888 p10=28799 p50=86527 avg=100553.60 p90=205823 p99=344063 p99.9=344063 max=344063
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=head_object]: n=86: min=6304 p10=7583 p50=10687 avg=14671.81 p90=28671 p99=37887 p99.9=37887 max=37887
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.first_byte_latency_us[op=list_objects]: n=97: min=7520 p10=10495 p50=14207 avg=17751.26 p90=32767 p99=43007 p99.9=43007 max=43007
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.throughput_mibs[op=get_object,size=1-16MiB]: n=56: min=8 p10=14 p50=26 avg=26.38 p90=42 p99=50 p99.9=50 max=50
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.throughput_mibs[op=get_object,size=>16MiB]: n=4: min=57 p10=57 p50=58 avg=59.25 p90=62 p99=62 p99.9=62 max=62
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=get_object]: n=60: min=22016 p10=29055 p50=132095 avg=329387.73 p90=700415 p99=974847 p99.9=974847 max=974847
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=head_object]: n=86: min=6304 p10=7583 p50=10687 avg=14671.81 p90=28671 p99=37887 p99.9=37887 max=37887
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests.total_latency_us[op=list_objects]: n=97: min=7616 p10=10687 p50=14463 avg=21170.97 p90=33535 p99=331775 p99.9=331775 max=331775
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests[op=get_object]: 60 (n=60)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests[op=head_object]: 86 (n=86)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.meta_requests[op=list_objects]: 97 (n=97)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.canceled[op=get_object,type=GetObject]: 23 (n=23)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.canceled[op=head_object,type=HeadObject]: 6 (n=6)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.failures[op=head_object,type=HeadObject,status=404]: 30 (n=30)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=get_object,type=GetObject]: n=120: min=12416 p10=16127 p50=25855 avg=35352.00 p90=85503 p99=116735 p99.9=126463 max=126463
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=head_object,type=HeadObject]: n=80: min=5216 p10=6047 p50=8255 avg=11077.20 p90=22783 p99=25471 p99.9=25471 max=25471
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.first_byte_latency_us[op=list_objects,type=Default]: n=97: min=5632 p10=8095 p50=11391 avg=13896.58 p90=26239 p99=33791 p99.9=33791 max=33791
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.total_latency_us[op=get_object,type=GetObject]: n=123: min=20992 p10=39167 p50=94207 avg=114446.05 p90=189439 p99=368639 p99.9=374783 max=374783
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.total_latency_us[op=head_object,type=HeadObject]: n=86: min=6144 p10=7167 p50=9599 avg=13833.12 p90=27903 p99=37119 p99.9=37119 max=37119
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests.total_latency_us[op=list_objects,type=Default]: n=97: min=7296 p10=10239 p50=13503 avg=17190.43 p90=32511 p99=42751 p99.9=42751 max=42751
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests[op=get_object,type=GetObject]: 123 (n=123)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests[op=head_object,type=HeadObject]: 86 (n=86)
Dec 04 13:49:04 hostname mount-s3[443613]: [INFO] mountpoint_s3::metrics: s3.requests[op=list_objects,type=Defau

@pranathivemuri
Copy link

@Arasan-B Having a similar issue, wondering if you were able to resolve it?

passaro added a commit to passaro/mountpoint-s3 that referenced this issue Feb 5, 2025
@passaro
Update CRT submodules to latest releases
4936e9f 
Submodule mountpoint-s3-crt-sys/crt/aws-c-auth 5bc67797..b513db4b:
  > A bunch of CMake fixes (awslabs#258)
  > Add Account Id to Credentials (awslabs#260)
  > Skip Transfer-Encoding from signing (awslabs#261)
Submodule mountpoint-s3-crt-sys/crt/aws-c-cal fbbe2612..7299c6ab:
  > Fix Findcrypto.cmake (awslabs#205)
  > A bunch of CMake fixes (awslabs#203)
  > Switch CI to use roles (awslabs#202)
Submodule mountpoint-s3-crt-sys/crt/aws-c-common 7a6f5df2..0e7637fa:
  > A bunch of CMake fixes (awslabs#1178)
  > Fix heap overflow on uri parsing (awslabs#1185)
  > (take 2) Detect when AVX is disabled via OSXSAVE (awslabs#1184)
  > Fixup IPv6 validation logic (awslabs#1180)
  > Detect when AVX is disabled via OSXSAVE (awslabs#1182)
  > proof_ci.yaml must use latest upload-artifact (awslabs#1183)
  > change PR template to ask for clearer wording (awslabs#1177)
Submodule mountpoint-s3-crt-sys/crt/aws-c-compression c6c1191e..f951ab2b:
  > A bunch of CMake fixes (awslabs#72)
  > Switch CI to use roles (awslabs#71)
  > chore: Modified bug issue template to add checkbox to report potential regression. (awslabs#69)
Submodule mountpoint-s3-crt-sys/crt/aws-c-http fc3eded2..590c7b59:
  > A bunch of CMake fixes (awslabs#497)
  > Fix CI for GCC-13 on Ubuntu-18  (awslabs#496)
  > Switch CI to use roles (awslabs#494)
Submodule mountpoint-s3-crt-sys/crt/aws-c-io fcb38c80..3041dabf:
  > A bunch of CMake fixes (awslabs#701)
  > Event Loop & Socket Type Multi-Support (awslabs#692)
  > fix typo in log message (awslabs#702)
  > Fix CI for GCC-13 on Ubuntu-18 (awslabs#700)
  > Switch CI to use roles (awslabs#698)
Submodule mountpoint-s3-crt-sys/crt/aws-c-s3 a3b401bf..6eb8be53:
  > A bunch of CMake fixes (awslabs#480)
  > S3Express CreateSession Allowlist Headers (awslabs#492)
  > Auto - Update S3 Ruleset & Partition (awslabs#491)
Submodule mountpoint-s3-crt-sys/crt/aws-c-sdkutils 1ae8664f..ba6a28fa:
  > A bunch of CMake fixes (awslabs#50)
Submodule mountpoint-s3-crt-sys/crt/aws-checksums 3e4101b9..fb8bd0b8:
  > A bunch of CMake fixes (awslabs#101)
  > Switch CI to use roles (awslabs#100)
Submodule mountpoint-s3-crt-sys/crt/aws-lc ffd6fb71..138a6ad3:
  > Prepare AWS-LC v1.44.0 (#2153)
  > Fix issue with ML-DSA key parsing (#2152)
  > Add support for PKCS7_set/get_detached (#2134)
  > Prepare Docker image for CI integration jobs (#2126)
  > Delete OpenVPN mainline patch from our integration build (#2149)
  > SHA3/SHAKE Init Updates via FIPS202 API layer (#2101)
  > Support keypair calculation for PQDSA PKEY (#2145)
  > Optimize x86/aarch64 MD5 implementation (#2137)
  > Check for MIPSEB in target.h (#2143)
  > Ed25519ph and Ed25519ctx Support (#2120)
  > Support for ML-DSA public key generation from private key (#2142)
  > Avoid mixing SSE and AVX in XTS-mode AVX512 implementation (#2140)
  > Remove remaining support for Trusty and Fuchsia operating systems (#2136)
  > ACVP test harness for ML-DSA (#2127)
  > Minor symbols to work with Ruby's mainline (#2132)

Signed-off-by: Alessandro Passaro <[email protected]>
github-merge-queue bot pushed a commit that referenced this issue Feb 5, 2025
@passaro
Update CRT submodules to latest releases (#1255)
2bf0385 
Update the CRT libraries to the latest releases. In particular, include:
* S3Express CreateSession Allowlist Headers
([awslabs/aws-c-s3#492](awslabs/aws-c-s3#492))

<details>
  <summary>Full CRT changelog:</summary>
  
```
Submodule mountpoint-s3-crt-sys/crt/aws-c-auth 5bc67797..b513db4b:
  > A bunch of CMake fixes (#258)
  > Add Account Id to Credentials (#260)
  > Skip Transfer-Encoding from signing (#261)
Submodule mountpoint-s3-crt-sys/crt/aws-c-cal fbbe2612..7299c6ab:
  > Fix Findcrypto.cmake (#205)
  > A bunch of CMake fixes (#203)
  > Switch CI to use roles (#202)
Submodule mountpoint-s3-crt-sys/crt/aws-c-common 7a6f5df2..0e7637fa:
  > A bunch of CMake fixes (#1178)
  > Fix heap overflow on uri parsing (#1185)
  > (take 2) Detect when AVX is disabled via OSXSAVE (#1184)
  > Fixup IPv6 validation logic (#1180)
  > Detect when AVX is disabled via OSXSAVE (#1182)
  > proof_ci.yaml must use latest upload-artifact (#1183)
  > change PR template to ask for clearer wording (#1177)
Submodule mountpoint-s3-crt-sys/crt/aws-c-compression c6c1191e..f951ab2b:
  > A bunch of CMake fixes (#72)
  > Switch CI to use roles (#71)
  > chore: Modified bug issue template to add checkbox to report potential regression. (#69)
Submodule mountpoint-s3-crt-sys/crt/aws-c-http fc3eded2..590c7b59:
  > A bunch of CMake fixes (#497)
  > Fix CI for GCC-13 on Ubuntu-18  (#496)
  > Switch CI to use roles (#494)
Submodule mountpoint-s3-crt-sys/crt/aws-c-io fcb38c80..3041dabf:
  > A bunch of CMake fixes (#701)
  > Event Loop & Socket Type Multi-Support (#692)
  > fix typo in log message (#702)
  > Fix CI for GCC-13 on Ubuntu-18 (#700)
  > Switch CI to use roles (#698)
Submodule mountpoint-s3-crt-sys/crt/aws-c-s3 a3b401bf..6eb8be53:
  > A bunch of CMake fixes (#480)
  > S3Express CreateSession Allowlist Headers (#492)
  > Auto - Update S3 Ruleset & Partition (#491)
Submodule mountpoint-s3-crt-sys/crt/aws-c-sdkutils 1ae8664f..ba6a28fa:
  > A bunch of CMake fixes (#50)
Submodule mountpoint-s3-crt-sys/crt/aws-checksums 3e4101b9..fb8bd0b8:
  > A bunch of CMake fixes (#101)
  > Switch CI to use roles (#100)
Submodule mountpoint-s3-crt-sys/crt/aws-lc ffd6fb71..138a6ad3:
  > Prepare AWS-LC v1.44.0 (#2153)
  > Fix issue with ML-DSA key parsing (#2152)
  > Add support for PKCS7_set/get_detached (#2134)
  > Prepare Docker image for CI integration jobs (#2126)
  > Delete OpenVPN mainline patch from our integration build (#2149)
  > SHA3/SHAKE Init Updates via FIPS202 API layer (#2101)
  > Support keypair calculation for PQDSA PKEY (#2145)
  > Optimize x86/aarch64 MD5 implementation (#2137)
  > Check for MIPSEB in target.h (#2143)
  > Ed25519ph and Ed25519ctx Support (#2120)
  > Support for ML-DSA public key generation from private key (#2142)
  > Avoid mixing SSE and AVX in XTS-mode AVX512 implementation (#2140)
  > Remove remaining support for Trusty and Fuchsia operating systems (#2136)
  > ACVP test harness for ML-DSA (#2127)
  > Minor symbols to work with Ruby's mainline (#2132)
```
</details>


### Does this change impact existing behavior?

No.

### Does this change need a changelog entry? Does it require a version
change?

No.

---

By submitting this pull request, I confirm that my contribution is made
under the terms of the Apache 2.0 license and I agree to the terms of
the [Developer Certificate of Origin
(DCO)](https://developercertificate.org/).

Signed-off-by: Alessandro Passaro <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@pranathivemuri @unexge @Arasan-B