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.

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

Feature request: cache large directory listings #184

Open
conradneilands opened this issue Aug 24, 2016 · 18 comments
Open

Feature request: cache large directory listings #184

conradneilands opened this issue Aug 24, 2016 · 18 comments
Labels
Eng-Backlog feature request Feature request: request to add new features or functionality p1 P1

Comments

@conradneilands
Copy link

A simple 'ls' listing of a directory can take 30 seconds of more to complete.
Most programs are giving up before the directory list is available. Such as an FTP server listing a folder in the bucket.

I am currently using these mount options
--stat-cache-ttl 5m
--type-cache-ttl 5m
They seem to have zero effect.

ie An 'ls' of the same directory in quick succession results in the same 30 second wait time

All sub directories seem equally slow regardless of content.
Listing of empty folders is slightly quicker

gcsfuse installed from google yum repo

@jacobsa
Copy link
Contributor

jacobsa commented Aug 24, 2016

Could you give more details about how/where you're running this, where your bucket is, what type of bucket it is, and what you see if you run gcsfuse with --foreground --debug_gcs?

@conradneilands
Copy link
Author

Centos 7 Google image. All servers and bucket in asia-east1. I don't mind the first ls being slow but second ls no faster. In our system once a file is created it's not deleted for months.
gcsfuse -o rw -o allow_other --stat-cache-ttl 5m --foreground --debug_gcs --implicit-dirs --file-mode 777 sentinexdatabucket /sentinexdatabucket
Using mount point: /sentinexdatabucket
Opening GCS connection...

WARNING: gcsfuse invoked as root. This will cause all files to be owned by
root. If this is not what you intended, invoke gcsfuse as the user that will
be interacting with the file system.

Opening bucket...
gcs: Req 0x0: <- ListObjects()
gcs: Req 0x0: -> ListObjects() (155.792653ms): OK
Mounting file system...
File system has been successfully mounted.
gcs: Req 0x1: <- ListObjects()
gcs: Req 0x1: -> ListObjects() (5.003393953s): OK
gcs: Req 0x2: <- StatObject("Reports/")
gcs: Req 0x3: <- ListObjects()
gcs: Req 0x2: -> StatObject("Reports/") (53.898089ms): OK
gcs: Req 0x3: -> ListObjects() (68.9914ms): OK
gcs: Req 0x4: <- StatObject("sentinex1/")
gcs: Req 0x5: <- ListObjects()
gcs: Req 0x4: -> StatObject("sentinex1/") (43.845606ms): OK
gcs: Req 0x5: -> ListObjects() (45.349048ms): OK
gcs: Req 0x6: <- StatObject("sentinex10/")
gcs: Req 0x7: <- ListObjects()
gcs: Req 0x6: -> StatObject("sentinex10/") (37.846514ms): OK
gcs: Req 0x7: -> ListObjects() (42.384263ms): OK
gcs: Req 0x8: <- StatObject("sentinex100/")
gcs: Req 0x9: <- ListObjects()
gcs: Req 0x8: -> StatObject("sentinex100/") (48.156809ms): OK
gcs: Req 0x9: -> ListObjects() (50.687767ms): OK
gcs: Req 0xa: <- StatObject("sentinex101/")
gcs: Req 0xb: <- ListObjects()
gcs: Req 0xa: -> StatObject("sentinex101/") (43.985288ms): OK
gcs: Req 0xb: -> ListObjects() (64.180036ms): OK
gcs: Req 0xc: <- StatObject("sentinex106/")
gcs: Req 0xd: <- ListObjects()
gcs: Req 0xd: -> ListObjects() (43.410729ms): OK
gcs: Req 0xc: -> StatObject("sentinex106/") (47.515189ms): OK
gcs: Req 0xe: <- StatObject("sentinex107/")
gcs: Req 0xf: <- ListObjects()
gcs: Req 0xf: -> ListObjects() (40.650126ms): OK
gcs: Req 0xe: -> StatObject("sentinex107/") (52.402358ms): OK
gcs: Req 0x10: <- StatObject("sentinex108/")
gcs: Req 0x11: <- ListObjects()
gcs: Req 0x10: -> StatObject("sentinex108/") (44.663651ms): OK
gcs: Req 0x11: -> ListObjects() (74.51609ms): OK
gcs: Req 0x12: <- StatObject("sentinex109/")
gcs: Req 0x13: <- ListObjects()
gcs: Req 0x13: -> ListObjects() (42.967777ms): OK
gcs: Req 0x12: -> StatObject("sentinex109/") (89.33812ms): OK
gcs: Req 0x14: <- StatObject("sentinex110/")
gcs: Req 0x15: <- ListObjects()
gcs: Req 0x15: -> ListObjects() (43.065877ms): OK
gcs: Req 0x14: -> StatObject("sentinex110/") (46.609291ms): OK
gcs: Req 0x16: <- StatObject("sentinex111/")
gcs: Req 0x17: <- ListObjects()
gcs: Req 0x16: -> StatObject("sentinex111/") (35.318019ms): OK
gcs: Req 0x17: -> ListObjects() (44.711369ms): OK
gcs: Req 0x18: <- StatObject("sentinex112/")
gcs: Req 0x19: <- ListObjects()
gcs: Req 0x18: -> StatObject("sentinex112/") (35.877254ms): OK
gcs: Req 0x19: -> ListObjects() (46.384772ms): OK
gcs: Req 0x1a: <- StatObject("sentinex115/")
gcs: Req 0x1b: <- ListObjects()
gcs: Req 0x1a: -> StatObject("sentinex115/") (36.815542ms): OK
gcs: Req 0x1b: -> ListObjects() (41.218852ms): OK
gcs: Req 0x1c: <- StatObject("sentinex116/")
gcs: Req 0x1d: <- ListObjects()
gcs: Req 0x1d: -> ListObjects() (46.290734ms): OK
gcs: Req 0x1c: -> StatObject("sentinex116/") (48.048645ms): OK
gcs: Req 0x1e: <- StatObject("sentinex117/")
gcs: Req 0x1f: <- ListObjects()
gcs: Req 0x1e: -> StatObject("sentinex117/") (39.420581ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x1f: -> ListObjects() (52.618647ms): OK
gcs: Req 0x20: <- StatObject("sentinex118/")
gcs: Req 0x21: <- ListObjects()
gcs: Req 0x20: -> StatObject("sentinex118/") (32.679879ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x21: -> ListObjects() (39.664716ms): OK
gcs: Req 0x22: <- StatObject("sentinex12/")
gcs: Req 0x23: <- ListObjects()
gcs: Req 0x22: -> StatObject("sentinex12/") (31.852015ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x23: -> ListObjects() (37.963244ms): OK
gcs: Req 0x24: <- StatObject("sentinex120/")
gcs: Req 0x25: <- ListObjects()
gcs: Req 0x25: -> ListObjects() (33.475926ms): OK
gcs: Req 0x24: -> StatObject("sentinex120/") (38.144389ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x26: <- StatObject("sentinex121/")
gcs: Req 0x27: <- ListObjects()
gcs: Req 0x26: -> StatObject("sentinex121/") (47.513895ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x27: -> ListObjects() (47.786959ms): OK
gcs: Req 0x28: <- StatObject("sentinex122/")
gcs: Req 0x29: <- ListObjects()
gcs: Req 0x28: -> StatObject("sentinex122/") (31.105264ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x29: -> ListObjects() (47.602951ms): OK
gcs: Req 0x2a: <- StatObject("sentinex123/")
gcs: Req 0x2b: <- ListObjects()
gcs: Req 0x2a: -> StatObject("sentinex123/") (34.500811ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2b: -> ListObjects() (44.792627ms): OK
gcs: Req 0x2c: <- StatObject("sentinex124/")
gcs: Req 0x2d: <- ListObjects()
gcs: Req 0x2c: -> StatObject("sentinex124/") (45.462164ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2d: -> ListObjects() (70.842823ms): OK
gcs: Req 0x2e: <- StatObject("sentinex125/")
gcs: Req 0x2f: <- ListObjects()
gcs: Req 0x2e: -> StatObject("sentinex125/") (44.987959ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2f: -> ListObjects() (56.549298ms): OK
gcs: Req 0x30: <- StatObject("sentinex13/")
gcs: Req 0x31: <- ListObjects()
gcs: Req 0x30: -> StatObject("sentinex13/") (42.526538ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x31: -> ListObjects() (51.753322ms): OK
gcs: Req 0x32: <- StatObject("sentinex130/")
gcs: Req 0x33: <- ListObjects()
gcs: Req 0x33: -> ListObjects() (40.05328ms): OK
gcs: Req 0x32: -> StatObject("sentinex130/") (45.417197ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x34: <- StatObject("sentinex140/")
gcs: Req 0x35: <- ListObjects()
gcs: Req 0x35: -> ListObjects() (56.177158ms): OK
gcs: Req 0x34: -> StatObject("sentinex140/") (64.221025ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x36: <- StatObject("sentinex141/")
gcs: Req 0x37: <- ListObjects()
gcs: Req 0x36: -> StatObject("sentinex141/") (32.571814ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x37: -> ListObjects() (81.248163ms): OK
gcs: Req 0x38: <- StatObject("sentinex142/")
gcs: Req 0x39: <- ListObjects()
gcs: Req 0x38: -> StatObject("sentinex142/") (37.073389ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x39: -> ListObjects() (40.439567ms): OK
gcs: Req 0x3a: <- StatObject("sentinex143/")
gcs: Req 0x3b: <- ListObjects()
gcs: Req 0x3a: -> StatObject("sentinex143/") (38.90738ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x3b: -> ListObjects() (62.409118ms): OK
gcs: Req 0x3c: <- StatObject("sentinex144/")
gcs: Req 0x3d: <- ListObjects()
gcs: Req 0x3d: -> ListObjects() (42.200557ms): OK
gcs: Req 0x3c: -> StatObject("sentinex144/") (46.740762ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x3e: <- StatObject("sentinex145/")
gcs: Req 0x3f: <- ListObjects()
gcs: Req 0x3e: -> StatObject("sentinex145/") (38.417503ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x3f: -> ListObjects() (51.114918ms): OK
gcs: Req 0x40: <- StatObject("sentinex146/")
gcs: Req 0x41: <- ListObjects()
gcs: Req 0x40: -> StatObject("sentinex146/") (35.750008ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x41: -> ListObjects() (48.585952ms): OK
gcs: Req 0x42: <- StatObject("sentinex147/")
gcs: Req 0x43: <- ListObjects()
gcs: Req 0x42: -> StatObject("sentinex147/") (37.788397ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x43: -> ListObjects() (52.063743ms): OK
gcs: Req 0x44: <- StatObject("sentinex15/")
gcs: Req 0x45: <- ListObjects()
gcs: Req 0x44: -> StatObject("sentinex15/") (30.088507ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x45: -> ListObjects() (42.429241ms): OK
gcs: Req 0x46: <- StatObject("sentinex150/")
gcs: Req 0x47: <- ListObjects()
gcs: Req 0x47: -> ListObjects() (32.576076ms): OK
gcs: Req 0x46: -> StatObject("sentinex150/") (38.6065ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x48: <- StatObject("sentinex151/")
gcs: Req 0x49: <- ListObjects()
gcs: Req 0x48: -> StatObject("sentinex151/") (44.096961ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x49: -> ListObjects() (54.811966ms): OK
gcs: Req 0x4a: <- StatObject("sentinex152/")
gcs: Req 0x4b: <- ListObjects()
gcs: Req 0x4b: -> ListObjects() (38.400458ms): OK
gcs: Req 0x4a: -> StatObject("sentinex152/") (42.485276ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x4c: <- StatObject("sentinex153/")
gcs: Req 0x4d: <- ListObjects()
gcs: Req 0x4c: -> StatObject("sentinex153/") (41.466869ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x4d: -> ListObjects() (60.381074ms): OK
gcs: Req 0x4e: <- StatObject("sentinex16/")
gcs: Req 0x4f: <- ListObjects()
gcs: Req 0x4e: -> StatObject("sentinex16/") (38.680269ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x4f: -> ListObjects() (41.890436ms): OK
gcs: Req 0x50: <- StatObject("sentinex160/")
gcs: Req 0x51: <- ListObjects()
gcs: Req 0x51: -> ListObjects() (43.808575ms): OK
gcs: Req 0x50: -> StatObject("sentinex160/") (50.888924ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x52: <- StatObject("sentinex17/")
gcs: Req 0x53: <- ListObjects()
gcs: Req 0x53: -> ListObjects() (44.823027ms): OK
gcs: Req 0x52: -> StatObject("sentinex17/") (45.979656ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x54: <- StatObject("sentinex18/")
gcs: Req 0x55: <- ListObjects()
gcs: Req 0x55: -> ListObjects() (36.201708ms): OK
gcs: Req 0x54: -> StatObject("sentinex18/") (60.741377ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x56: <- StatObject("sentinex2/")
gcs: Req 0x57: <- ListObjects()
gcs: Req 0x56: -> StatObject("sentinex2/") (50.602448ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x57: -> ListObjects() (50.842538ms): OK
gcs: Req 0x58: <- StatObject("sentinex2171/")
gcs: Req 0x59: <- ListObjects()
gcs: Req 0x59: -> ListObjects() (44.21784ms): OK
gcs: Req 0x58: -> StatObject("sentinex2171/") (48.789961ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x5a: <- StatObject("sentinex22/")
gcs: Req 0x5b: <- ListObjects()
gcs: Req 0x5a: -> StatObject("sentinex22/") (32.627822ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x5b: -> ListObjects() (40.418419ms): OK
gcs: Req 0x5c: <- StatObject("sentinex25/")
gcs: Req 0x5d: <- ListObjects()
gcs: Req 0x5c: -> StatObject("sentinex25/") (42.598117ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x5d: -> ListObjects() (71.972923ms): OK
gcs: Req 0x5e: <- StatObject("sentinex30/")
gcs: Req 0x5f: <- ListObjects()
gcs: Req 0x5e: -> StatObject("sentinex30/") (30.703638ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x5f: -> ListObjects() (53.307754ms): OK
gcs: Req 0x60: <- StatObject("sentinex31/")
gcs: Req 0x61: <- ListObjects()
gcs: Req 0x60: -> StatObject("sentinex31/") (49.547203ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x61: -> ListObjects() (60.228982ms): OK
gcs: Req 0x62: <- StatObject("sentinex32/")
gcs: Req 0x63: <- ListObjects()
gcs: Req 0x62: -> StatObject("sentinex32/") (41.427029ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x63: -> ListObjects() (46.237091ms): OK
gcs: Req 0x64: <- StatObject("sentinex33/")
gcs: Req 0x65: <- ListObjects()
gcs: Req 0x64: -> StatObject("sentinex33/") (35.614076ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x65: -> ListObjects() (54.181814ms): OK
gcs: Req 0x66: <- StatObject("sentinex34/")
gcs: Req 0x67: <- ListObjects()
gcs: Req 0x66: -> StatObject("sentinex34/") (38.401909ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x67: -> ListObjects() (41.065597ms): OK
gcs: Req 0x68: <- StatObject("sentinex35/")
gcs: Req 0x69: <- ListObjects()
gcs: Req 0x69: -> ListObjects() (49.199922ms): OK
gcs: Req 0x68: -> StatObject("sentinex35/") (66.16113ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x6a: <- StatObject("sentinex36/")
gcs: Req 0x6b: <- ListObjects()
gcs: Req 0x6a: -> StatObject("sentinex36/") (35.370274ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x6b: -> ListObjects() (46.462248ms): OK
gcs: Req 0x6c: <- StatObject("sentinex37/")
gcs: Req 0x6d: <- ListObjects()
gcs: Req 0x6d: -> ListObjects() (50.193057ms): OK
gcs: Req 0x6c: -> StatObject("sentinex37/") (61.765412ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x6e: <- StatObject("sentinex38/")
gcs: Req 0x6f: <- ListObjects()
gcs: Req 0x6e: -> StatObject("sentinex38/") (30.556062ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x6f: -> ListObjects() (50.562771ms): OK
gcs: Req 0x70: <- StatObject("sentinex39/")
gcs: Req 0x71: <- ListObjects()
gcs: Req 0x71: -> ListObjects() (35.971823ms): OK
gcs: Req 0x70: -> StatObject("sentinex39/") (61.394577ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x72: <- StatObject("sentinex4/")
gcs: Req 0x73: <- ListObjects()
gcs: Req 0x73: -> ListObjects() (43.13547ms): OK
gcs: Req 0x72: -> StatObject("sentinex4/") (51.211017ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x74: <- StatObject("sentinex40/")
gcs: Req 0x75: <- ListObjects()
gcs: Req 0x75: -> ListObjects() (45.969219ms): OK
gcs: Req 0x74: -> StatObject("sentinex40/") (67.421493ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x76: <- StatObject("sentinex41/")
gcs: Req 0x77: <- ListObjects()
gcs: Req 0x77: -> ListObjects() (37.627667ms): OK
gcs: Req 0x76: -> StatObject("sentinex41/") (64.926729ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x78: <- StatObject("sentinex45/")
gcs: Req 0x79: <- ListObjects()
gcs: Req 0x78: -> StatObject("sentinex45/") (34.165316ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x79: -> ListObjects() (45.184024ms): OK
gcs: Req 0x7a: <- StatObject("sentinex46/")
gcs: Req 0x7b: <- ListObjects()
gcs: Req 0x7a: -> StatObject("sentinex46/") (42.648032ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x7b: -> ListObjects() (46.354188ms): OK
gcs: Req 0x7c: <- StatObject("sentinex47/")
gcs: Req 0x7d: <- ListObjects()
gcs: Req 0x7c: -> StatObject("sentinex47/") (31.500763ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x7d: -> ListObjects() (52.054757ms): OK
gcs: Req 0x7e: <- StatObject("sentinex48/")
gcs: Req 0x7f: <- ListObjects()
gcs: Req 0x7e: -> StatObject("sentinex48/") (29.001451ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x7f: -> ListObjects() (43.862828ms): OK
gcs: Req 0x80: <- StatObject("sentinex5/")
gcs: Req 0x81: <- ListObjects()
gcs: Req 0x80: -> StatObject("sentinex5/") (41.560438ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x81: -> ListObjects() (44.951304ms): OK
gcs: Req 0x82: <- StatObject("sentinex50/")
gcs: Req 0x83: <- ListObjects()
gcs: Req 0x82: -> StatObject("sentinex50/") (38.179367ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x83: -> ListObjects() (40.874462ms): OK
gcs: Req 0x84: <- StatObject("sentinex500/")
gcs: Req 0x85: <- ListObjects()
gcs: Req 0x84: -> StatObject("sentinex500/") (37.140154ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x85: -> ListObjects() (42.949145ms): OK
gcs: Req 0x86: <- StatObject("sentinex51/")
gcs: Req 0x87: <- ListObjects()
gcs: Req 0x86: -> StatObject("sentinex51/") (49.046204ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x87: -> ListObjects() (62.004447ms): OK
gcs: Req 0x88: <- StatObject("sentinex56/")
gcs: Req 0x89: <- ListObjects()
gcs: Req 0x88: -> StatObject("sentinex56/") (30.420378ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x89: -> ListObjects() (39.718245ms): OK
gcs: Req 0x8a: <- StatObject("sentinex57/")
gcs: Req 0x8b: <- ListObjects()
gcs: Req 0x8a: -> StatObject("sentinex57/") (37.479199ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x8b: -> ListObjects() (44.832138ms): OK
gcs: Req 0x8c: <- StatObject("sentinex6/")
gcs: Req 0x8d: <- ListObjects()
gcs: Req 0x8d: -> ListObjects() (49.976125ms): OK
gcs: Req 0x8c: -> StatObject("sentinex6/") (60.636965ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x8e: <- StatObject("sentinex60/")
gcs: Req 0x8f: <- ListObjects()
gcs: Req 0x8e: -> StatObject("sentinex60/") (34.77718ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x8f: -> ListObjects() (56.728965ms): OK
gcs: Req 0x90: <- StatObject("sentinex62/")
gcs: Req 0x91: <- ListObjects()
gcs: Req 0x90: -> StatObject("sentinex62/") (26.954162ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x91: -> ListObjects() (42.459347ms): OK
gcs: Req 0x92: <- StatObject("sentinex63/")
gcs: Req 0x93: <- ListObjects()
gcs: Req 0x92: -> StatObject("sentinex63/") (28.445865ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x93: -> ListObjects() (47.64477ms): OK
gcs: Req 0x94: <- StatObject("sentinex64/")
gcs: Req 0x95: <- ListObjects()
gcs: Req 0x94: -> StatObject("sentinex64/") (39.021479ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x95: -> ListObjects() (49.952942ms): OK
gcs: Req 0x96: <- StatObject("sentinex65/")
gcs: Req 0x97: <- ListObjects()
gcs: Req 0x96: -> StatObject("sentinex65/") (37.576473ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x97: -> ListObjects() (44.180203ms): OK
gcs: Req 0x98: <- StatObject("sentinex66/")
gcs: Req 0x99: <- ListObjects()
gcs: Req 0x99: -> ListObjects() (33.587551ms): OK
gcs: Req 0x98: -> StatObject("sentinex66/") (34.281089ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x9a: <- StatObject("sentinex67/")
gcs: Req 0x9b: <- ListObjects()
gcs: Req 0x9a: -> StatObject("sentinex67/") (33.560811ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x9b: -> ListObjects() (42.120032ms): OK
gcs: Req 0x9c: <- StatObject("sentinex68/")
gcs: Req 0x9d: <- ListObjects()
gcs: Req 0x9c: -> StatObject("sentinex68/") (37.065212ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x9d: -> ListObjects() (41.631546ms): OK
gcs: Req 0x9e: <- StatObject("sentinex69/")
gcs: Req 0x9f: <- ListObjects()
gcs: Req 0x9e: -> StatObject("sentinex69/") (33.14995ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x9f: -> ListObjects() (52.765454ms): OK
gcs: Req 0xa0: <- StatObject("sentinex7/")
gcs: Req 0xa1: <- ListObjects()
gcs: Req 0xa1: -> ListObjects() (48.538188ms): OK
gcs: Req 0xa0: -> StatObject("sentinex7/") (50.309547ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xa2: <- StatObject("sentinex71/")
gcs: Req 0xa3: <- ListObjects()
gcs: Req 0xa2: -> StatObject("sentinex71/") (32.456555ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xa3: -> ListObjects() (41.326947ms): OK
gcs: Req 0xa4: <- StatObject("sentinex72/")
gcs: Req 0xa5: <- ListObjects()
gcs: Req 0xa4: -> StatObject("sentinex72/") (43.165314ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xa5: -> ListObjects() (50.918944ms): OK
gcs: Req 0xa6: <- StatObject("sentinex73/")
gcs: Req 0xa7: <- ListObjects()
gcs: Req 0xa6: -> StatObject("sentinex73/") (43.107182ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xa7: -> ListObjects() (49.475991ms): OK
gcs: Req 0xa8: <- StatObject("sentinex8/")
gcs: Req 0xa9: <- ListObjects()
gcs: Req 0xa8: -> StatObject("sentinex8/") (36.150929ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xa9: -> ListObjects() (45.972989ms): OK
gcs: Req 0xaa: <- StatObject("sentinex80/")
gcs: Req 0xab: <- ListObjects()
gcs: Req 0xab: -> ListObjects() (43.708714ms): OK
gcs: Req 0xaa: -> StatObject("sentinex80/") (45.443789ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xac: <- StatObject("sentinex81/")
gcs: Req 0xad: <- ListObjects()
gcs: Req 0xac: -> StatObject("sentinex81/") (35.351481ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xad: -> ListObjects() (39.51178ms): OK
gcs: Req 0xae: <- StatObject("sentinex82/")
gcs: Req 0xaf: <- ListObjects()
gcs: Req 0xaf: -> ListObjects() (47.84479ms): OK
gcs: Req 0xae: -> StatObject("sentinex82/") (51.100337ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb0: <- StatObject("sentinex83/")
gcs: Req 0xb1: <- ListObjects()
gcs: Req 0xb1: -> ListObjects() (33.536701ms): OK
gcs: Req 0xb0: -> StatObject("sentinex83/") (47.019769ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb2: <- StatObject("sentinex84/")
gcs: Req 0xb3: <- ListObjects()
gcs: Req 0xb2: -> StatObject("sentinex84/") (35.841169ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb3: -> ListObjects() (45.204672ms): OK
gcs: Req 0xb4: <- StatObject("sentinex85/")
gcs: Req 0xb5: <- ListObjects()
gcs: Req 0xb4: -> StatObject("sentinex85/") (32.80392ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb5: -> ListObjects() (49.229163ms): OK
gcs: Req 0xb6: <- StatObject("sentinex86/")
gcs: Req 0xb7: <- ListObjects()
gcs: Req 0xb6: -> StatObject("sentinex86/") (40.741543ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb7: -> ListObjects() (41.253875ms): OK
gcs: Req 0xb8: <- StatObject("sentinex87/")
gcs: Req 0xb9: <- ListObjects()
gcs: Req 0xb8: -> StatObject("sentinex87/") (46.079481ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xb9: -> ListObjects() (74.537514ms): OK
gcs: Req 0xba: <- StatObject("sentinex9/")
gcs: Req 0xbb: <- ListObjects()
gcs: Req 0xba: -> StatObject("sentinex9/") (45.295669ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xbb: -> ListObjects() (61.474663ms): OK
gcs: Req 0xbc: <- StatObject("sentinex90/")
gcs: Req 0xbd: <- ListObjects()
gcs: Req 0xbc: -> StatObject("sentinex90/") (21.992961ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xbd: -> ListObjects() (39.859075ms): OK
gcs: Req 0xbe: <- StatObject("sentinex91/")
gcs: Req 0xbf: <- ListObjects()
gcs: Req 0xbe: -> StatObject("sentinex91/") (33.244363ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xbf: -> ListObjects() (34.440722ms): OK
gcs: Req 0xc0: <- StatObject("sentinex94/")
gcs: Req 0xc1: <- ListObjects()
gcs: Req 0xc0: -> StatObject("sentinex94/") (45.8692ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xc1: -> ListObjects() (49.351701ms): OK
gcs: Req 0xc2: <- StatObject("sentinex95/")
gcs: Req 0xc3: <- ListObjects()
gcs: Req 0xc2: -> StatObject("sentinex95/") (40.372442ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xc3: -> ListObjects() (48.669036ms): OK
gcs: Req 0xc4: <- StatObject("sentinex96/")
gcs: Req 0xc5: <- ListObjects()
gcs: Req 0xc5: -> ListObjects() (38.968397ms): OK
gcs: Req 0xc4: -> StatObject("sentinex96/") (41.298838ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xc6: <- StatObject("sentinex97/")
gcs: Req 0xc7: <- ListObjects()
gcs: Req 0xc6: -> StatObject("sentinex97/") (33.630342ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xc7: -> ListObjects() (42.011028ms): OK
gcs: Req 0xc8: <- StatObject("sentinex98/")
gcs: Req 0xc9: <- ListObjects()
gcs: Req 0xc8: -> StatObject("sentinex98/") (38.864665ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xc9: -> ListObjects() (47.104745ms): OK
gcs: Req 0xca: <- StatObject("sentinex99/")
gcs: Req 0xcb: <- ListObjects()
gcs: Req 0xca: -> StatObject("sentinex99/") (30.041348ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0xcb: -> ListObjects() (32.873532ms): OK
gcs: Req 0xcc: <- ListObjects()
gcs: Req 0xcc: -> ListObjects() (3.473050079s): OK
gcs: Req 0xcd: <- ListObjects()
gcs: Req 0xcd: -> ListObjects() (43.31346ms): OK
gcs: Req 0xce: <- ListObjects()
gcs: Req 0xce: -> ListObjects() (52.399638ms): OK
gcs: Req 0xcf: <- ListObjects()
gcs: Req 0xcf: -> ListObjects() (40.846999ms): OK
gcs: Req 0xd0: <- ListObjects()
gcs: Req 0xd0: -> ListObjects() (36.816349ms): OK
gcs: Req 0xd1: <- ListObjects()
gcs: Req 0xd1: -> ListObjects() (41.74638ms): OK
gcs: Req 0xd2: <- ListObjects()
gcs: Req 0xd2: -> ListObjects() (39.274635ms): OK
gcs: Req 0xd3: <- ListObjects()
gcs: Req 0xd3: -> ListObjects() (35.722229ms): OK
gcs: Req 0xd4: <- ListObjects()
gcs: Req 0xd4: -> ListObjects() (47.554419ms): OK
gcs: Req 0xd5: <- ListObjects()
gcs: Req 0xd5: -> ListObjects() (52.831277ms): OK
gcs: Req 0xd6: <- ListObjects()
gcs: Req 0xd6: -> ListObjects() (41.983289ms): OK
gcs: Req 0xd7: <- ListObjects()
gcs: Req 0xd7: -> ListObjects() (60.957364ms): OK
gcs: Req 0xd8: <- ListObjects()
gcs: Req 0xd8: -> ListObjects() (46.223024ms): OK
gcs: Req 0xd9: <- ListObjects()
gcs: Req 0xd9: -> ListObjects() (43.996192ms): OK
gcs: Req 0xda: <- ListObjects()
gcs: Req 0xda: -> ListObjects() (25.018998ms): OK
gcs: Req 0xdb: <- ListObjects()
gcs: Req 0xdb: -> ListObjects() (28.254716ms): OK
gcs: Req 0xdc: <- ListObjects()
gcs: Req 0xdc: -> ListObjects() (47.282098ms): OK
gcs: Req 0xdd: <- ListObjects()
gcs: Req 0xdd: -> ListObjects() (41.655132ms): OK
gcs: Req 0xde: <- ListObjects()
gcs: Req 0xde: -> ListObjects() (47.301796ms): OK
gcs: Req 0xdf: <- ListObjects()
gcs: Req 0xdf: -> ListObjects() (53.395206ms): OK
gcs: Req 0xe0: <- ListObjects()
gcs: Req 0xe0: -> ListObjects() (43.039989ms): OK
gcs: Req 0xe1: <- ListObjects()
gcs: Req 0xe1: -> ListObjects() (49.397521ms): OK
gcs: Req 0xe2: <- ListObjects()
gcs: Req 0xe2: -> ListObjects() (45.643038ms): OK
gcs: Req 0xe3: <- ListObjects()
gcs: Req 0xe3: -> ListObjects() (42.432735ms): OK
gcs: Req 0xe4: <- ListObjects()
gcs: Req 0xe4: -> ListObjects() (39.732685ms): OK
gcs: Req 0xe5: <- ListObjects()
gcs: Req 0xe5: -> ListObjects() (46.80323ms): OK
gcs: Req 0xe6: <- ListObjects()
gcs: Req 0xe6: -> ListObjects() (39.221181ms): OK
gcs: Req 0xe7: <- ListObjects()
gcs: Req 0xe7: -> ListObjects() (43.671122ms): OK
gcs: Req 0xe8: <- ListObjects()
gcs: Req 0xe8: -> ListObjects() (47.620531ms): OK
gcs: Req 0xe9: <- ListObjects()
gcs: Req 0xe9: -> ListObjects() (44.649569ms): OK
gcs: Req 0xea: <- ListObjects()
gcs: Req 0xea: -> ListObjects() (46.150211ms): OK
gcs: Req 0xeb: <- ListObjects()
gcs: Req 0xeb: -> ListObjects() (59.79298ms): OK
gcs: Req 0xec: <- ListObjects()
gcs: Req 0xec: -> ListObjects() (38.512792ms): OK
gcs: Req 0xed: <- ListObjects()
gcs: Req 0xed: -> ListObjects() (43.022368ms): OK
gcs: Req 0xee: <- ListObjects()
gcs: Req 0xee: -> ListObjects() (98.18913ms): OK
gcs: Req 0xef: <- ListObjects()
gcs: Req 0xef: -> ListObjects() (37.389961ms): OK
gcs: Req 0xf0: <- ListObjects()
gcs: Req 0xf0: -> ListObjects() (32.058695ms): OK
gcs: Req 0xf1: <- ListObjects()
gcs: Req 0xf1: -> ListObjects() (75.802199ms): OK
gcs: Req 0xf2: <- ListObjects()
gcs: Req 0xf2: -> ListObjects() (37.111998ms): OK
gcs: Req 0xf3: <- ListObjects()
gcs: Req 0xf3: -> ListObjects() (33.743638ms): OK
gcs: Req 0xf4: <- ListObjects()
gcs: Req 0xf4: -> ListObjects() (27.960381ms): OK
gcs: Req 0xf5: <- ListObjects()
gcs: Req 0xf5: -> ListObjects() (45.696024ms): OK
gcs: Req 0xf6: <- ListObjects()
gcs: Req 0xf6: -> ListObjects() (34.854637ms): OK
gcs: Req 0xf7: <- ListObjects()
gcs: Req 0xf7: -> ListObjects() (41.028998ms): OK
gcs: Req 0xf8: <- ListObjects()
gcs: Req 0xf8: -> ListObjects() (42.361034ms): OK
gcs: Req 0xf9: <- ListObjects()
gcs: Req 0xf9: -> ListObjects() (41.445124ms): OK
gcs: Req 0xfa: <- ListObjects()
gcs: Req 0xfa: -> ListObjects() (36.421642ms): OK
gcs: Req 0xfb: <- ListObjects()
gcs: Req 0xfb: -> ListObjects() (39.609782ms): OK
gcs: Req 0xfc: <- ListObjects()
gcs: Req 0xfc: -> ListObjects() (50.055691ms): OK
gcs: Req 0xfd: <- ListObjects()
gcs: Req 0xfd: -> ListObjects() (29.038046ms): OK
gcs: Req 0xfe: <- ListObjects()
gcs: Req 0xfe: -> ListObjects() (28.995126ms): OK
gcs: Req 0xff: <- ListObjects()
gcs: Req 0xff: -> ListObjects() (54.427769ms): OK
gcs: Req 0x100: <- ListObjects()
gcs: Req 0x100: -> ListObjects() (50.323892ms): OK
gcs: Req 0x101: <- ListObjects()
gcs: Req 0x101: -> ListObjects() (38.000092ms): OK
gcs: Req 0x102: <- ListObjects()
gcs: Req 0x102: -> ListObjects() (37.394012ms): OK
gcs: Req 0x103: <- ListObjects()
gcs: Req 0x103: -> ListObjects() (43.666757ms): OK
gcs: Req 0x104: <- ListObjects()
gcs: Req 0x104: -> ListObjects() (26.819512ms): OK
gcs: Req 0x105: <- ListObjects()
gcs: Req 0x105: -> ListObjects() (37.75703ms): OK
gcs: Req 0x106: <- ListObjects()
gcs: Req 0x106: -> ListObjects() (55.422546ms): OK
gcs: Req 0x107: <- ListObjects()
gcs: Req 0x107: -> ListObjects() (34.942861ms): OK
gcs: Req 0x108: <- ListObjects()
gcs: Req 0x108: -> ListObjects() (30.766434ms): OK
gcs: Req 0x109: <- ListObjects()
gcs: Req 0x109: -> ListObjects() (36.672641ms): OK
gcs: Req 0x10a: <- ListObjects()
gcs: Req 0x10a: -> ListObjects() (47.191122ms): OK
gcs: Req 0x10b: <- ListObjects()
gcs: Req 0x10b: -> ListObjects() (105.422241ms): OK
gcs: Req 0x10c: <- ListObjects()
gcs: Req 0x10c: -> ListObjects() (46.945048ms): OK
gcs: Req 0x10d: <- ListObjects()
gcs: Req 0x10d: -> ListObjects() (48.540369ms): OK
gcs: Req 0x10e: <- ListObjects()
gcs: Req 0x10e: -> ListObjects() (31.705883ms): OK
gcs: Req 0x10f: <- ListObjects()
gcs: Req 0x10f: -> ListObjects() (43.437547ms): OK
gcs: Req 0x110: <- ListObjects()
gcs: Req 0x110: -> ListObjects() (37.592952ms): OK
gcs: Req 0x111: <- ListObjects()
gcs: Req 0x111: -> ListObjects() (44.351681ms): OK
gcs: Req 0x112: <- ListObjects()
gcs: Req 0x112: -> ListObjects() (46.7187ms): OK
gcs: Req 0x113: <- ListObjects()
gcs: Req 0x113: -> ListObjects() (42.689448ms): OK
gcs: Req 0x114: <- ListObjects()
gcs: Req 0x114: -> ListObjects() (43.128524ms): OK
gcs: Req 0x115: <- ListObjects()
gcs: Req 0x115: -> ListObjects() (41.927245ms): OK
gcs: Req 0x116: <- ListObjects()
gcs: Req 0x116: -> ListObjects() (36.604167ms): OK
gcs: Req 0x117: <- ListObjects()
gcs: Req 0x117: -> ListObjects() (45.010404ms): OK
gcs: Req 0x118: <- ListObjects()
gcs: Req 0x118: -> ListObjects() (51.023755ms): OK
gcs: Req 0x119: <- ListObjects()
gcs: Req 0x119: -> ListObjects() (45.116977ms): OK
gcs: Req 0x11a: <- ListObjects()
gcs: Req 0x11a: -> ListObjects() (35.721394ms): OK
gcs: Req 0x11b: <- ListObjects()
gcs: Req 0x11b: -> ListObjects() (40.770896ms): OK
gcs: Req 0x11c: <- ListObjects()
gcs: Req 0x11c: -> ListObjects() (36.919168ms): OK
gcs: Req 0x11d: <- ListObjects()
gcs: Req 0x11d: -> ListObjects() (46.22502ms): OK
gcs: Req 0x11e: <- ListObjects()
gcs: Req 0x11e: -> ListObjects() (33.323272ms): OK
gcs: Req 0x11f: <- ListObjects()
gcs: Req 0x11f: -> ListObjects() (41.277303ms): OK
gcs: Req 0x120: <- ListObjects()
gcs: Req 0x120: -> ListObjects() (38.461593ms): OK
gcs: Req 0x121: <- ListObjects()
gcs: Req 0x121: -> ListObjects() (37.788463ms): OK
gcs: Req 0x122: <- ListObjects()
gcs: Req 0x122: -> ListObjects() (42.482407ms): OK
gcs: Req 0x123: <- ListObjects()
gcs: Req 0x123: -> ListObjects() (27.942438ms): OK
gcs: Req 0x124: <- ListObjects()
gcs: Req 0x124: -> ListObjects() (42.585676ms): OK
gcs: Req 0x125: <- ListObjects()
gcs: Req 0x125: -> ListObjects() (51.155035ms): OK
gcs: Req 0x126: <- ListObjects()
gcs: Req 0x126: -> ListObjects() (57.465279ms): OK
gcs: Req 0x127: <- ListObjects()
gcs: Req 0x127: -> ListObjects() (53.224345ms): OK
gcs: Req 0x128: <- ListObjects()
gcs: Req 0x128: -> ListObjects() (31.759814ms): OK
gcs: Req 0x129: <- ListObjects()
gcs: Req 0x129: -> ListObjects() (47.4189ms): OK
gcs: Req 0x12a: <- ListObjects()
gcs: Req 0x12a: -> ListObjects() (47.811568ms): OK
gcs: Req 0x12b: <- ListObjects()
gcs: Req 0x12b: -> ListObjects() (36.702393ms): OK
gcs: Req 0x12c: <- ListObjects()
gcs: Req 0x12c: -> ListObjects() (35.364831ms): OK
gcs: Req 0x12d: <- ListObjects()
gcs: Req 0x12d: -> ListObjects() (62.056628ms): OK
gcs: Req 0x12e: <- ListObjects()
gcs: Req 0x12e: -> ListObjects() (42.692949ms): OK
gcs: Req 0x12f: <- ListObjects()
gcs: Req 0x12f: -> ListObjects() (36.351445ms): OK
gcs: Req 0x130: <- ListObjects()
gcs: Req 0x130: -> ListObjects() (29.53479ms): OK
gcs: Req 0x131: <- ListObjects()
gcs: Req 0x131: -> ListObjects() (39.526747ms): OK
gcs: Req 0x132: <- ListObjects()
gcs: Req 0x132: -> ListObjects() (4.495917449s): OK
gcs: Req 0x133: <- ListObjects()
gcs: Req 0x133: -> ListObjects() (42.590016ms): OK
gcs: Req 0x134: <- ListObjects()
gcs: Req 0x134: -> ListObjects() (46.379202ms): OK
gcs: Req 0x135: <- ListObjects()
gcs: Req 0x135: -> ListObjects() (36.327762ms): OK
gcs: Req 0x136: <- ListObjects()
gcs: Req 0x136: -> ListObjects() (36.75603ms): OK
gcs: Req 0x137: <- ListObjects()
gcs: Req 0x137: -> ListObjects() (49.094132ms): OK
gcs: Req 0x138: <- ListObjects()
gcs: Req 0x138: -> ListObjects() (60.304365ms): OK
gcs: Req 0x139: <- ListObjects()
gcs: Req 0x139: -> ListObjects() (39.895904ms): OK
gcs: Req 0x13a: <- ListObjects()
gcs: Req 0x13a: -> ListObjects() (38.213844ms): OK
gcs: Req 0x13b: <- ListObjects()
gcs: Req 0x13b: -> ListObjects() (46.673783ms): OK
gcs: Req 0x13c: <- ListObjects()
gcs: Req 0x13c: -> ListObjects() (41.488626ms): OK
gcs: Req 0x13d: <- ListObjects()
gcs: Req 0x13d: -> ListObjects() (43.768364ms): OK
gcs: Req 0x13e: <- ListObjects()
gcs: Req 0x13e: -> ListObjects() (38.88732ms): OK
gcs: Req 0x13f: <- ListObjects()
gcs: Req 0x13f: -> ListObjects() (46.236119ms): OK
gcs: Req 0x140: <- ListObjects()
gcs: Req 0x140: -> ListObjects() (35.609796ms): OK
gcs: Req 0x141: <- ListObjects()
gcs: Req 0x141: -> ListObjects() (45.116172ms): OK
gcs: Req 0x142: <- ListObjects()
gcs: Req 0x142: -> ListObjects() (44.922825ms): OK
gcs: Req 0x143: <- ListObjects()
gcs: Req 0x143: -> ListObjects() (37.927246ms): OK
gcs: Req 0x144: <- ListObjects()
gcs: Req 0x144: -> ListObjects() (36.333426ms): OK
gcs: Req 0x145: <- ListObjects()
gcs: Req 0x145: -> ListObjects() (39.487936ms): OK
gcs: Req 0x146: <- ListObjects()
gcs: Req 0x146: -> ListObjects() (38.587461ms): OK
gcs: Req 0x147: <- ListObjects()
gcs: Req 0x147: -> ListObjects() (36.811684ms): OK
gcs: Req 0x148: <- ListObjects()
gcs: Req 0x148: -> ListObjects() (46.938656ms): OK
gcs: Req 0x149: <- ListObjects()
gcs: Req 0x149: -> ListObjects() (38.188396ms): OK
gcs: Req 0x14a: <- ListObjects()
gcs: Req 0x14a: -> ListObjects() (47.365515ms): OK
gcs: Req 0x14b: <- ListObjects()
gcs: Req 0x14b: -> ListObjects() (38.206001ms): OK
gcs: Req 0x14c: <- ListObjects()
gcs: Req 0x14c: -> ListObjects() (37.806315ms): OK
gcs: Req 0x14d: <- ListObjects()
gcs: Req 0x14d: -> ListObjects() (51.56823ms): OK
gcs: Req 0x14e: <- ListObjects()
gcs: Req 0x14e: -> ListObjects() (41.666832ms): OK
gcs: Req 0x14f: <- ListObjects()
gcs: Req 0x14f: -> ListObjects() (72.989142ms): OK
gcs: Req 0x150: <- ListObjects()
gcs: Req 0x150: -> ListObjects() (43.038325ms): OK
gcs: Req 0x151: <- ListObjects()
gcs: Req 0x151: -> ListObjects() (42.921693ms): OK
gcs: Req 0x152: <- ListObjects()
gcs: Req 0x152: -> ListObjects() (65.470437ms): OK
gcs: Req 0x153: <- ListObjects()
gcs: Req 0x153: -> ListObjects() (34.941416ms): OK
gcs: Req 0x154: <- ListObjects()
gcs: Req 0x154: -> ListObjects() (39.153914ms): OK
gcs: Req 0x155: <- ListObjects()
gcs: Req 0x155: -> ListObjects() (47.863593ms): OK
gcs: Req 0x156: <- ListObjects()
gcs: Req 0x156: -> ListObjects() (41.698212ms): OK
gcs: Req 0x157: <- ListObjects()
gcs: Req 0x157: -> ListObjects() (38.732364ms): OK
gcs: Req 0x158: <- ListObjects()
gcs: Req 0x158: -> ListObjects() (46.389626ms): OK
gcs: Req 0x159: <- ListObjects()
gcs: Req 0x159: -> ListObjects() (40.399589ms): OK
gcs: Req 0x15a: <- ListObjects()
gcs: Req 0x15a: -> ListObjects() (61.148686ms): OK
gcs: Req 0x15b: <- ListObjects()
gcs: Req 0x15b: -> ListObjects() (42.231977ms): OK
gcs: Req 0x15c: <- ListObjects()
gcs: Req 0x15c: -> ListObjects() (40.267539ms): OK
gcs: Req 0x15d: <- ListObjects()
gcs: Req 0x15d: -> ListObjects() (41.703679ms): OK
gcs: Req 0x15e: <- ListObjects()
gcs: Req 0x15e: -> ListObjects() (37.597763ms): OK
gcs: Req 0x15f: <- ListObjects()
gcs: Req 0x15f: -> ListObjects() (40.521418ms): OK
gcs: Req 0x160: <- ListObjects()
gcs: Req 0x160: -> ListObjects() (33.578307ms): OK
gcs: Req 0x161: <- ListObjects()
gcs: Req 0x161: -> ListObjects() (62.70406ms): OK
gcs: Req 0x162: <- ListObjects()
gcs: Req 0x162: -> ListObjects() (48.508079ms): OK
gcs: Req 0x163: <- ListObjects()
gcs: Req 0x163: -> ListObjects() (39.281655ms): OK
gcs: Req 0x164: <- ListObjects()
gcs: Req 0x164: -> ListObjects() (57.183159ms): OK
gcs: Req 0x165: <- ListObjects()
gcs: Req 0x165: -> ListObjects() (40.205732ms): OK
gcs: Req 0x166: <- ListObjects()
gcs: Req 0x166: -> ListObjects() (36.973274ms): OK
gcs: Req 0x167: <- ListObjects()
gcs: Req 0x167: -> ListObjects() (48.849895ms): OK
gcs: Req 0x168: <- ListObjects()
gcs: Req 0x168: -> ListObjects() (53.959004ms): OK
gcs: Req 0x169: <- ListObjects()
gcs: Req 0x169: -> ListObjects() (35.977472ms): OK
gcs: Req 0x16a: <- ListObjects()
gcs: Req 0x16a: -> ListObjects() (38.288199ms): OK
gcs: Req 0x16b: <- ListObjects()
gcs: Req 0x16b: -> ListObjects() (36.218579ms): OK
gcs: Req 0x16c: <- ListObjects()
gcs: Req 0x16c: -> ListObjects() (44.323184ms): OK
gcs: Req 0x16d: <- ListObjects()
gcs: Req 0x16d: -> ListObjects() (50.580511ms): OK
gcs: Req 0x16e: <- ListObjects()
gcs: Req 0x16e: -> ListObjects() (41.509764ms): OK
gcs: Req 0x16f: <- ListObjects()
gcs: Req 0x16f: -> ListObjects() (42.012387ms): OK
gcs: Req 0x170: <- ListObjects()
gcs: Req 0x170: -> ListObjects() (41.220127ms): OK
gcs: Req 0x171: <- ListObjects()
gcs: Req 0x171: -> ListObjects() (41.373152ms): OK
gcs: Req 0x172: <- ListObjects()
gcs: Req 0x172: -> ListObjects() (49.699976ms): OK
gcs: Req 0x173: <- ListObjects()
gcs: Req 0x173: -> ListObjects() (36.008736ms): OK
gcs: Req 0x174: <- ListObjects()
gcs: Req 0x174: -> ListObjects() (41.571402ms): OK
gcs: Req 0x175: <- ListObjects()
gcs: Req 0x175: -> ListObjects() (37.330063ms): OK
gcs: Req 0x176: <- ListObjects()
gcs: Req 0x176: -> ListObjects() (51.990291ms): OK
gcs: Req 0x177: <- ListObjects()
gcs: Req 0x177: -> ListObjects() (44.697594ms): OK
gcs: Req 0x178: <- ListObjects()
gcs: Req 0x178: -> ListObjects() (32.726326ms): OK
gcs: Req 0x179: <- ListObjects()
gcs: Req 0x179: -> ListObjects() (41.262825ms): OK
gcs: Req 0x17a: <- ListObjects()
gcs: Req 0x17a: -> ListObjects() (38.108937ms): OK
gcs: Req 0x17b: <- ListObjects()
gcs: Req 0x17b: -> ListObjects() (42.301105ms): OK
gcs: Req 0x17c: <- ListObjects()
gcs: Req 0x17c: -> ListObjects() (33.054493ms): OK
gcs: Req 0x17d: <- ListObjects()
gcs: Req 0x17d: -> ListObjects() (43.49302ms): OK
gcs: Req 0x17e: <- ListObjects()
gcs: Req 0x17e: -> ListObjects() (41.117425ms): OK
gcs: Req 0x17f: <- ListObjects()
gcs: Req 0x17f: -> ListObjects() (48.759339ms): OK
gcs: Req 0x180: <- ListObjects()
gcs: Req 0x180: -> ListObjects() (39.310099ms): OK
gcs: Req 0x181: <- ListObjects()
gcs: Req 0x181: -> ListObjects() (41.497549ms): OK
gcs: Req 0x182: <- ListObjects()
gcs: Req 0x182: -> ListObjects() (38.684986ms): OK
gcs: Req 0x183: <- ListObjects()
gcs: Req 0x183: -> ListObjects() (33.49102ms): OK
gcs: Req 0x184: <- ListObjects()
gcs: Req 0x184: -> ListObjects() (29.09546ms): OK
gcs: Req 0x185: <- ListObjects()
gcs: Req 0x185: -> ListObjects() (43.858579ms): OK
gcs: Req 0x186: <- ListObjects()
gcs: Req 0x186: -> ListObjects() (42.048466ms): OK
gcs: Req 0x187: <- ListObjects()
gcs: Req 0x187: -> ListObjects() (47.502089ms): OK
gcs: Req 0x188: <- ListObjects()
gcs: Req 0x188: -> ListObjects() (39.849289ms): OK
gcs: Req 0x189: <- ListObjects()
gcs: Req 0x189: -> ListObjects() (47.127495ms): OK
gcs: Req 0x18a: <- ListObjects()
gcs: Req 0x18a: -> ListObjects() (54.153966ms): OK
gcs: Req 0x18b: <- ListObjects()
gcs: Req 0x18b: -> ListObjects() (41.743481ms): OK
gcs: Req 0x18c: <- ListObjects()
gcs: Req 0x18c: -> ListObjects() (42.081946ms): OK
gcs: Req 0x18d: <- ListObjects()
gcs: Req 0x18d: -> ListObjects() (42.802554ms): OK
gcs: Req 0x18e: <- ListObjects()
gcs: Req 0x18e: -> ListObjects() (64.215458ms): OK
gcs: Req 0x18f: <- ListObjects()
gcs: Req 0x18f: -> ListObjects() (38.119893ms): OK
gcs: Req 0x190: <- ListObjects()
gcs: Req 0x190: -> ListObjects() (39.873987ms): OK
gcs: Req 0x191: <- ListObjects()
gcs: Req 0x191: -> ListObjects() (36.332196ms): OK
gcs: Req 0x192: <- ListObjects()
gcs: Req 0x192: -> ListObjects() (43.926957ms): OK
gcs: Req 0x193: <- ListObjects()
gcs: Req 0x193: -> ListObjects() (40.591457ms): OK
gcs: Req 0x194: <- ListObjects()
gcs: Req 0x194: -> ListObjects() (49.122798ms): OK
gcs: Req 0x195: <- ListObjects()
gcs: Req 0x195: -> ListObjects() (38.837936ms): OK
gcs: Req 0x196: <- ListObjects()
gcs: Req 0x196: -> ListObjects() (34.474165ms): OK
gcs: Req 0x197: <- ListObjects()
gcs: Req 0x197: -> ListObjects() (38.730803ms): OK

@jacobsa
Copy link
Contributor

jacobsa commented Aug 24, 2016

I assume you're doing ls -l (so that you need all the inode attributes) and not just ls (so that you only need the name)? Could you also post the resulting listing?

@conradneilands
Copy link
Author

Just repeated 'ls' on the root of the bucket.

Interestingly most slowness occurs in directories with no files, just sub directories. This particular root directory has about 200 sub directories

I cannot be sure what other programs will execute. I would assume a proftpd may do an ls -l behind the scenes for a directory listing

@conradneilands
Copy link
Author

From what i can tell proftpd is doing an equivalent ls -l on each file individually in a directory one by one. Resulting in very bad performance. I will attempt to work around that one if i can

Regardless, It still seems as though nothing ever gets cached, It's like it has totally ignored the stat cache setting

@jacobsa
Copy link
Contributor

jacobsa commented Aug 24, 2016

Assuming the debug output above covers more than one ls -l invocation, you can see that the stat cache is indeed working. For the first listing there's a StatObject call for each top-level inode, but then for subsequent listings there is no such call. The stat cache maps from individual objects to their stat results; it doesn't cover listings.

What evidence makes you think that proftpd is at fault here? An alternate explanation: the number of ListObjects requests required for listing a directory is proportional to the size of the contents of that directory and all its descendants in GCS. So it's likely that listing the top-level directory just takes a ton of requests.

@conradneilands
Copy link
Author

I really shouldn't have mentioned proftpd, I use it for reference on how unusable the non existent caching makes it.

I'm fine with the first ls being slow, it's to be expected.
I am not fine with the second and third etc 'ls' being exactly as slow.

The debug output is a simple 'ls' repeated on the same directory

Yes i can see that the cache is being recorded by the program. But whats the point in the cached 'ls' being just as slow on every single hit and no faster that an uncached 'ls'

@conradneilands
Copy link
Author

Here we can see that the access times are exactly the same for the non cached and cached ls

############NON CACHED ls (first go)################################################################
2016/08/24 15:36:39.766212 Starting a garbage collection run.
gcs: Req 0x28a2: <- ListObjects()
gcs: Req 0x28a2: -> ListObjects() (36.354529ms): OK
2016/08/24 15:36:39.803013 Garbage collection succeeded after deleted 0 objects in 36.753716ms.
2016/08/24 15:46:39.766522 Starting a garbage collection run.
gcs: Req 0x28a3: <- ListObjects()
gcs: Req 0x28a3: -> ListObjects() (104.179643ms): OK
2016/08/24 15:46:39.871290 Garbage collection succeeded after deleted 0 objects in 104.700995ms.
2016/08/24 15:56:39.766251 Starting a garbage collection run.
gcs: Req 0x28a4: <- ListObjects()
gcs: Req 0x28a4: -> ListObjects() (55.571415ms): OK
2016/08/24 15:56:39.822328 Garbage collection succeeded after deleted 0 objects in 56.009826ms.
2016/08/24 16:06:39.766380 Starting a garbage collection run.
gcs: Req 0x28a5: <- ListObjects()
gcs: Req 0x28a5: -> ListObjects() (71.502793ms): OK
2016/08/24 16:06:39.838478 Garbage collection succeeded after deleted 0 objects in 72.027978ms.
2016/08/24 16:16:39.766238 Starting a garbage collection run.
gcs: Req 0x28a6: <- ListObjects()
gcs: Req 0x28a6: -> ListObjects() (56.024003ms): OK
2016/08/24 16:16:39.822699 Garbage collection succeeded after deleted 0 objects in 56.406384ms.
gcs: Req 0x28a7: <- ListObjects()
gcs: Req 0x28a7: -> ListObjects() (4.706915303s): OK
gcs: Req 0x28a8: <- StatObject("Reports/")
gcs: Req 0x28a9: <- ListObjects()
gcs: Req 0x28a9: -> ListObjects() (59.992851ms): OK
gcs: Req 0x28a8: -> StatObject("Reports/") (64.406839ms): OK
gcs: Req 0x28aa: <- StatObject("sentinex1/")
gcs: Req 0x28ab: <- ListObjects()
gcs: Req 0x28aa: -> StatObject("sentinex1/") (37.602321ms): OK
gcs: Req 0x28ab: -> ListObjects() (50.841419ms): OK
gcs: Req 0x28ac: <- StatObject("sentinex10/")
gcs: Req 0x28ad: <- ListObjects()
gcs: Req 0x28ac: -> StatObject("sentinex10/") (43.772444ms): OK
gcs: Req 0x28ad: -> ListObjects() (53.642933ms): OK
gcs: Req 0x28ae: <- StatObject("sentinex100/")
gcs: Req 0x28af: <- ListObjects()
gcs: Req 0x28ae: -> StatObject("sentinex100/") (43.411317ms): OK
gcs: Req 0x28af: -> ListObjects() (45.226427ms): OK
gcs: Req 0x28b0: <- StatObject("sentinex101/")
gcs: Req 0x28b1: <- ListObjects()
gcs: Req 0x28b0: -> StatObject("sentinex101/") (39.56299ms): OK
gcs: Req 0x28b1: -> ListObjects() (48.662734ms): OK
gcs: Req 0x28b2: <- StatObject("sentinex106/")
gcs: Req 0x28b3: <- ListObjects()
gcs: Req 0x28b3: -> ListObjects() (52.850342ms): OK
gcs: Req 0x28b2: -> StatObject("sentinex106/") (105.037435ms): OK
gcs: Req 0x28b4: <- StatObject("sentinex107/")
gcs: Req 0x28b5: <- ListObjects()
gcs: Req 0x28b5: -> ListObjects() (39.212203ms): OK
gcs: Req 0x28b4: -> StatObject("sentinex107/") (90.753661ms): OK
gcs: Req 0x28b6: <- StatObject("sentinex108/")
gcs: Req 0x28b7: <- ListObjects()
gcs: Req 0x28b7: -> ListObjects() (34.707015ms): OK
gcs: Req 0x28b6: -> StatObject("sentinex108/") (43.746886ms): OK
gcs: Req 0x28b8: <- StatObject("sentinex109/")
gcs: Req 0x28b9: <- ListObjects()
gcs: Req 0x28b8: -> StatObject("sentinex109/") (47.95109ms): OK
gcs: Req 0x28b9: -> ListObjects() (58.052293ms): OK
gcs: Req 0x28ba: <- StatObject("sentinex110/")
gcs: Req 0x28bb: <- ListObjects()
gcs: Req 0x28ba: -> StatObject("sentinex110/") (42.627815ms): OK
gcs: Req 0x28bb: -> ListObjects() (66.008176ms): OK
gcs: Req 0x28bc: <- StatObject("sentinex111/")
gcs: Req 0x28bd: <- ListObjects()
gcs: Req 0x28bc: -> StatObject("sentinex111/") (41.774487ms): OK
gcs: Req 0x28bd: -> ListObjects() (42.702443ms): OK
gcs: Req 0x28be: <- StatObject("sentinex112/")
gcs: Req 0x28bf: <- ListObjects()
gcs: Req 0x28bf: -> ListObjects() (45.156842ms): OK
gcs: Req 0x28be: -> StatObject("sentinex112/") (57.26011ms): OK
gcs: Req 0x28c0: <- StatObject("sentinex115/")
gcs: Req 0x28c1: <- ListObjects()
gcs: Req 0x28c1: -> ListObjects() (58.091653ms): OK
gcs: Req 0x28c0: -> StatObject("sentinex115/") (67.141824ms): OK
gcs: Req 0x28c2: <- StatObject("sentinex116/")
gcs: Req 0x28c3: <- ListObjects()
gcs: Req 0x28c2: -> StatObject("sentinex116/") (39.549523ms): OK
gcs: Req 0x28c3: -> ListObjects() (47.553426ms): OK
gcs: Req 0x28c4: <- StatObject("sentinex117/")
gcs: Req 0x28c5: <- ListObjects()
gcs: Req 0x28c5: -> ListObjects() (44.448249ms): OK
gcs: Req 0x28c4: -> StatObject("sentinex117/") (56.775976ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28c6: <- StatObject("sentinex118/")
gcs: Req 0x28c7: <- ListObjects()
gcs: Req 0x28c6: -> StatObject("sentinex118/") (42.153599ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28c7: -> ListObjects() (43.445676ms): OK
gcs: Req 0x28c8: <- StatObject("sentinex12/")
gcs: Req 0x28c9: <- ListObjects()
gcs: Req 0x28c8: -> StatObject("sentinex12/") (43.698316ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28c9: -> ListObjects() (43.967251ms): OK
gcs: Req 0x28ca: <- StatObject("sentinex120/")
gcs: Req 0x28cb: <- ListObjects()
gcs: Req 0x28ca: -> StatObject("sentinex120/") (62.554117ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28cb: -> ListObjects() (103.67104ms): OK
gcs: Req 0x28cc: <- StatObject("sentinex121/")
gcs: Req 0x28cd: <- ListObjects()
gcs: Req 0x28cc: -> StatObject("sentinex121/") (43.134772ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28cd: -> ListObjects() (98.694059ms): OK
gcs: Req 0x28ce: <- StatObject("sentinex122/")
gcs: Req 0x28cf: <- ListObjects()
gcs: Req 0x28ce: -> StatObject("sentinex122/") (42.73236ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28cf: -> ListObjects() (48.333368ms): OK
gcs: Req 0x28d0: <- StatObject("sentinex123/")
gcs: Req 0x28d1: <- ListObjects()
gcs: Req 0x28d0: -> StatObject("sentinex123/") (39.993224ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28d1: -> ListObjects() (51.436583ms): OK
gcs: Req 0x28d2: <- StatObject("sentinex124/")
gcs: Req 0x28d3: <- ListObjects()
gcs: Req 0x28d2: -> StatObject("sentinex124/") (41.484966ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28d3: -> ListObjects() (43.929547ms): OK
gcs: Req 0x28d4: <- StatObject("sentinex125/")
gcs: Req 0x28d5: <- ListObjects()
gcs: Req 0x28d4: -> StatObject("sentinex125/") (35.36405ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28d5: -> ListObjects() (49.599045ms): OK
gcs: Req 0x28d6: <- StatObject("sentinex13/")
gcs: Req 0x28d7: <- ListObjects()
gcs: Req 0x28d6: -> StatObject("sentinex13/") (39.407495ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28d7: -> ListObjects() (40.631473ms): OK
gcs: Req 0x28d8: <- StatObject("sentinex130/")
gcs: Req 0x28d9: <- ListObjects()
gcs: Req 0x28d8: -> StatObject("sentinex130/") (44.597358ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28d9: -> ListObjects() (46.731558ms): OK
gcs: Req 0x28da: <- StatObject("sentinex140/")
gcs: Req 0x28db: <- ListObjects()
gcs: Req 0x28da: -> StatObject("sentinex140/") (36.259007ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28db: -> ListObjects() (42.059523ms): OK
gcs: Req 0x28dc: <- StatObject("sentinex141/")
gcs: Req 0x28dd: <- ListObjects()
gcs: Req 0x28dd: -> ListObjects() (36.362014ms): OK
gcs: Req 0x28dc: -> StatObject("sentinex141/") (46.459718ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28de: <- StatObject("sentinex142/")
gcs: Req 0x28df: <- ListObjects()
gcs: Req 0x28de: -> StatObject("sentinex142/") (31.857875ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28df: -> ListObjects() (61.400807ms): OK
gcs: Req 0x28e0: <- StatObject("sentinex143/")
gcs: Req 0x28e1: <- ListObjects()
gcs: Req 0x28e1: -> ListObjects() (35.091712ms): OK
gcs: Req 0x28e0: -> StatObject("sentinex143/") (41.267412ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28e2: <- StatObject("sentinex144/")
gcs: Req 0x28e3: <- ListObjects()
gcs: Req 0x28e2: -> StatObject("sentinex144/") (34.949279ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28e3: -> ListObjects() (35.886901ms): OK
gcs: Req 0x28e4: <- StatObject("sentinex145/")
gcs: Req 0x28e5: <- ListObjects()
gcs: Req 0x28e5: -> ListObjects() (35.686947ms): OK
gcs: Req 0x28e4: -> StatObject("sentinex145/") (46.671373ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28e6: <- StatObject("sentinex146/")
gcs: Req 0x28e7: <- ListObjects()
gcs: Req 0x28e6: -> StatObject("sentinex146/") (42.635665ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28e7: -> ListObjects() (79.8083ms): OK
gcs: Req 0x28e8: <- StatObject("sentinex147/")
gcs: Req 0x28e9: <- ListObjects()
gcs: Req 0x28e8: -> StatObject("sentinex147/") (31.11276ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28e9: -> ListObjects() (42.306905ms): OK
gcs: Req 0x28ea: <- StatObject("sentinex15/")
gcs: Req 0x28eb: <- ListObjects()
gcs: Req 0x28ea: -> StatObject("sentinex15/") (49.172667ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28eb: -> ListObjects() (51.909559ms): OK
gcs: Req 0x28ec: <- StatObject("sentinex150/")
gcs: Req 0x28ed: <- ListObjects()
gcs: Req 0x28ec: -> StatObject("sentinex150/") (36.957256ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28ed: -> ListObjects() (47.819729ms): OK
gcs: Req 0x28ee: <- StatObject("sentinex151/")
gcs: Req 0x28ef: <- ListObjects()
gcs: Req 0x28ef: -> ListObjects() (41.369993ms): OK
gcs: Req 0x28ee: -> StatObject("sentinex151/") (49.180693ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f0: <- StatObject("sentinex152/")
gcs: Req 0x28f1: <- ListObjects()
gcs: Req 0x28f0: -> StatObject("sentinex152/") (29.449768ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f1: -> ListObjects() (32.278004ms): OK
gcs: Req 0x28f2: <- StatObject("sentinex153/")
gcs: Req 0x28f3: <- ListObjects()
gcs: Req 0x28f3: -> ListObjects() (44.409154ms): OK
gcs: Req 0x28f2: -> StatObject("sentinex153/") (45.399761ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f4: <- StatObject("sentinex16/")
gcs: Req 0x28f5: <- ListObjects()
gcs: Req 0x28f4: -> StatObject("sentinex16/") (39.564582ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f5: -> ListObjects() (47.557364ms): OK
gcs: Req 0x28f6: <- StatObject("sentinex160/")
gcs: Req 0x28f7: <- ListObjects()
gcs: Req 0x28f6: -> StatObject("sentinex160/") (36.490645ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f7: -> ListObjects() (45.124872ms): OK
gcs: Req 0x28f8: <- StatObject("sentinex17/")
gcs: Req 0x28f9: <- ListObjects()
gcs: Req 0x28f8: -> StatObject("sentinex17/") (39.471549ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28f9: -> ListObjects() (40.790096ms): OK
gcs: Req 0x28fa: <- StatObject("sentinex18/")
gcs: Req 0x28fb: <- ListObjects()
gcs: Req 0x28fa: -> StatObject("sentinex18/") (33.711709ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28fb: -> ListObjects() (36.014211ms): OK
gcs: Req 0x28fc: <- StatObject("sentinex2/")
gcs: Req 0x28fd: <- ListObjects()
gcs: Req 0x28fc: -> StatObject("sentinex2/") (35.488278ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28fd: -> ListObjects() (41.163581ms): OK
gcs: Req 0x28fe: <- StatObject("sentinex2171/")
gcs: Req 0x28ff: <- ListObjects()
gcs: Req 0x28fe: -> StatObject("sentinex2171/") (38.090304ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x28ff: -> ListObjects() (69.299093ms): OK
gcs: Req 0x2900: <- StatObject("sentinex22/")
gcs: Req 0x2901: <- ListObjects()
gcs: Req 0x2900: -> StatObject("sentinex22/") (46.985426ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2901: -> ListObjects() (51.239355ms): OK
gcs: Req 0x2902: <- StatObject("sentinex25/")
gcs: Req 0x2903: <- ListObjects()
gcs: Req 0x2903: -> ListObjects() (35.42834ms): OK
gcs: Req 0x2902: -> StatObject("sentinex25/") (54.801143ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2904: <- StatObject("sentinex30/")
gcs: Req 0x2905: <- ListObjects()
gcs: Req 0x2905: -> ListObjects() (41.539132ms): OK
gcs: Req 0x2904: -> StatObject("sentinex30/") (41.936594ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2906: <- StatObject("sentinex31/")
gcs: Req 0x2907: <- ListObjects()
gcs: Req 0x2906: -> StatObject("sentinex31/") (41.98944ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2907: -> ListObjects() (42.869906ms): OK
gcs: Req 0x2908: <- StatObject("sentinex32/")
gcs: Req 0x2909: <- ListObjects()
gcs: Req 0x2908: -> StatObject("sentinex32/") (34.152081ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2909: -> ListObjects() (37.509301ms): OK
gcs: Req 0x290a: <- StatObject("sentinex33/")
gcs: Req 0x290b: <- ListObjects()
gcs: Req 0x290a: -> StatObject("sentinex33/") (36.97841ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x290b: -> ListObjects() (42.740754ms): OK
gcs: Req 0x290c: <- StatObject("sentinex34/")
gcs: Req 0x290d: <- ListObjects()
gcs: Req 0x290c: -> StatObject("sentinex34/") (36.291153ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x290d: -> ListObjects() (61.602845ms): OK
gcs: Req 0x290e: <- StatObject("sentinex35/")
gcs: Req 0x290f: <- ListObjects()
gcs: Req 0x290e: -> StatObject("sentinex35/") (35.06548ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x290f: -> ListObjects() (40.229561ms): OK
gcs: Req 0x2910: <- StatObject("sentinex36/")
gcs: Req 0x2911: <- ListObjects()
gcs: Req 0x2911: -> ListObjects() (35.828368ms): OK
gcs: Req 0x2910: -> StatObject("sentinex36/") (38.397783ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2912: <- StatObject("sentinex37/")
gcs: Req 0x2913: <- ListObjects()
gcs: Req 0x2913: -> ListObjects() (39.917227ms): OK
gcs: Req 0x2912: -> StatObject("sentinex37/") (56.828253ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2914: <- StatObject("sentinex38/")
gcs: Req 0x2915: <- ListObjects()
gcs: Req 0x2914: -> StatObject("sentinex38/") (37.232494ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2915: -> ListObjects() (47.292448ms): OK
gcs: Req 0x2916: <- StatObject("sentinex39/")
gcs: Req 0x2917: <- ListObjects()
gcs: Req 0x2917: -> ListObjects() (32.095035ms): OK
gcs: Req 0x2916: -> StatObject("sentinex39/") (33.394805ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2918: <- StatObject("sentinex4/")
gcs: Req 0x2919: <- ListObjects()
gcs: Req 0x2918: -> StatObject("sentinex4/") (33.354551ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2919: -> ListObjects() (46.829762ms): OK
gcs: Req 0x291a: <- StatObject("sentinex40/")
gcs: Req 0x291b: <- ListObjects()
gcs: Req 0x291a: -> StatObject("sentinex40/") (37.051747ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x291b: -> ListObjects() (53.958696ms): OK
gcs: Req 0x291c: <- StatObject("sentinex41/")
gcs: Req 0x291d: <- ListObjects()
gcs: Req 0x291c: -> StatObject("sentinex41/") (28.34402ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x291d: -> ListObjects() (38.741279ms): OK
gcs: Req 0x291e: <- StatObject("sentinex45/")
gcs: Req 0x291f: <- ListObjects()
gcs: Req 0x291f: -> ListObjects() (35.064227ms): OK
gcs: Req 0x291e: -> StatObject("sentinex45/") (36.816069ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2920: <- StatObject("sentinex46/")
gcs: Req 0x2921: <- ListObjects()
gcs: Req 0x2921: -> ListObjects() (38.850067ms): OK
gcs: Req 0x2920: -> StatObject("sentinex46/") (71.214506ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2922: <- StatObject("sentinex47/")
gcs: Req 0x2923: <- ListObjects()
gcs: Req 0x2923: -> ListObjects() (34.734734ms): OK
gcs: Req 0x2922: -> StatObject("sentinex47/") (36.557299ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2924: <- StatObject("sentinex48/")
gcs: Req 0x2925: <- ListObjects()
gcs: Req 0x2924: -> StatObject("sentinex48/") (35.075569ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2925: -> ListObjects() (42.7771ms): OK
gcs: Req 0x2926: <- StatObject("sentinex5/")
gcs: Req 0x2927: <- ListObjects()
gcs: Req 0x2927: -> ListObjects() (34.225469ms): OK
gcs: Req 0x2926: -> StatObject("sentinex5/") (53.711473ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2928: <- StatObject("sentinex50/")
gcs: Req 0x2929: <- ListObjects()
gcs: Req 0x2928: -> StatObject("sentinex50/") (40.600498ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2929: -> ListObjects() (41.540033ms): OK
gcs: Req 0x292a: <- StatObject("sentinex500/")
gcs: Req 0x292b: <- ListObjects()
gcs: Req 0x292a: -> StatObject("sentinex500/") (34.928675ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x292b: -> ListObjects() (46.291321ms): OK
gcs: Req 0x292c: <- StatObject("sentinex51/")
gcs: Req 0x292d: <- ListObjects()
gcs: Req 0x292d: -> ListObjects() (36.773375ms): OK
gcs: Req 0x292c: -> StatObject("sentinex51/") (45.802489ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x292e: <- StatObject("sentinex56/")
gcs: Req 0x292f: <- ListObjects()
gcs: Req 0x292f: -> ListObjects() (59.620332ms): OK
gcs: Req 0x292e: -> StatObject("sentinex56/") (64.991702ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2930: <- StatObject("sentinex57/")
gcs: Req 0x2931: <- ListObjects()
gcs: Req 0x2930: -> StatObject("sentinex57/") (39.964744ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2931: -> ListObjects() (43.615989ms): OK
gcs: Req 0x2932: <- StatObject("sentinex6/")
gcs: Req 0x2933: <- ListObjects()
gcs: Req 0x2932: -> StatObject("sentinex6/") (34.619967ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2933: -> ListObjects() (36.172076ms): OK
gcs: Req 0x2934: <- StatObject("sentinex60/")
gcs: Req 0x2935: <- ListObjects()
gcs: Req 0x2934: -> StatObject("sentinex60/") (44.700529ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2935: -> ListObjects() (64.799271ms): OK
gcs: Req 0x2936: <- StatObject("sentinex62/")
gcs: Req 0x2937: <- ListObjects()
gcs: Req 0x2936: -> StatObject("sentinex62/") (38.237698ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2937: -> ListObjects() (68.39583ms): OK
gcs: Req 0x2938: <- StatObject("sentinex63/")
gcs: Req 0x2939: <- ListObjects()
gcs: Req 0x2939: -> ListObjects() (37.965907ms): OK
gcs: Req 0x2938: -> StatObject("sentinex63/") (60.661499ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x293a: <- StatObject("sentinex64/")
gcs: Req 0x293b: <- ListObjects()
gcs: Req 0x293b: -> ListObjects() (35.373632ms): OK
gcs: Req 0x293a: -> StatObject("sentinex64/") (40.464157ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x293c: <- StatObject("sentinex65/")
gcs: Req 0x293d: <- ListObjects()
gcs: Req 0x293c: -> StatObject("sentinex65/") (37.701551ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x293d: -> ListObjects() (53.320122ms): OK
gcs: Req 0x293e: <- StatObject("sentinex66/")
gcs: Req 0x293f: <- ListObjects()
gcs: Req 0x293e: -> StatObject("sentinex66/") (60.121176ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x293f: -> ListObjects() (75.457316ms): OK
gcs: Req 0x2940: <- StatObject("sentinex67/")
gcs: Req 0x2941: <- ListObjects()
gcs: Req 0x2940: -> StatObject("sentinex67/") (41.19903ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2941: -> ListObjects() (49.066988ms): OK
gcs: Req 0x2942: <- StatObject("sentinex68/")
gcs: Req 0x2943: <- ListObjects()
gcs: Req 0x2942: -> StatObject("sentinex68/") (41.541447ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2943: -> ListObjects() (45.565255ms): OK
gcs: Req 0x2944: <- StatObject("sentinex69/")
gcs: Req 0x2945: <- ListObjects()
gcs: Req 0x2944: -> StatObject("sentinex69/") (38.864425ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2945: -> ListObjects() (42.643161ms): OK
gcs: Req 0x2946: <- StatObject("sentinex7/")
gcs: Req 0x2947: <- ListObjects()
gcs: Req 0x2946: -> StatObject("sentinex7/") (37.103631ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2947: -> ListObjects() (45.078741ms): OK
gcs: Req 0x2948: <- StatObject("sentinex71/")
gcs: Req 0x2949: <- ListObjects()
gcs: Req 0x2948: -> StatObject("sentinex71/") (34.170213ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2949: -> ListObjects() (48.753391ms): OK
gcs: Req 0x294a: <- StatObject("sentinex72/")
gcs: Req 0x294b: <- ListObjects()
gcs: Req 0x294a: -> StatObject("sentinex72/") (31.822801ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x294b: -> ListObjects() (38.486831ms): OK
gcs: Req 0x294c: <- StatObject("sentinex73/")
gcs: Req 0x294d: <- ListObjects()
gcs: Req 0x294c: -> StatObject("sentinex73/") (33.646805ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x294d: -> ListObjects() (37.369785ms): OK
gcs: Req 0x294e: <- StatObject("sentinex8/")
gcs: Req 0x294f: <- ListObjects()
gcs: Req 0x294e: -> StatObject("sentinex8/") (36.195092ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x294f: -> ListObjects() (40.480779ms): OK
gcs: Req 0x2950: <- StatObject("sentinex80/")
gcs: Req 0x2951: <- ListObjects()
gcs: Req 0x2950: -> StatObject("sentinex80/") (26.872438ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2951: -> ListObjects() (41.029433ms): OK
gcs: Req 0x2952: <- StatObject("sentinex81/")
gcs: Req 0x2953: <- ListObjects()
gcs: Req 0x2952: -> StatObject("sentinex81/") (30.982587ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2953: -> ListObjects() (44.958945ms): OK
gcs: Req 0x2954: <- StatObject("sentinex82/")
gcs: Req 0x2955: <- ListObjects()
gcs: Req 0x2955: -> ListObjects() (35.129476ms): OK
gcs: Req 0x2954: -> StatObject("sentinex82/") (39.137459ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2956: <- StatObject("sentinex83/")
gcs: Req 0x2957: <- ListObjects()
gcs: Req 0x2956: -> StatObject("sentinex83/") (30.327155ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2957: -> ListObjects() (48.34995ms): OK
gcs: Req 0x2958: <- StatObject("sentinex84/")
gcs: Req 0x2959: <- ListObjects()
gcs: Req 0x2958: -> StatObject("sentinex84/") (32.636352ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2959: -> ListObjects() (80.222725ms): OK
gcs: Req 0x295a: <- StatObject("sentinex85/")
gcs: Req 0x295b: <- ListObjects()
gcs: Req 0x295a: -> StatObject("sentinex85/") (32.936609ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x295b: -> ListObjects() (52.656034ms): OK
gcs: Req 0x295c: <- StatObject("sentinex86/")
gcs: Req 0x295d: <- ListObjects()
gcs: Req 0x295c: -> StatObject("sentinex86/") (36.073455ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x295d: -> ListObjects() (48.649144ms): OK
gcs: Req 0x295e: <- StatObject("sentinex87/")
gcs: Req 0x295f: <- ListObjects()
gcs: Req 0x295e: -> StatObject("sentinex87/") (41.257992ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x295f: -> ListObjects() (47.898325ms): OK
gcs: Req 0x2960: <- StatObject("sentinex9/")
gcs: Req 0x2961: <- ListObjects()
gcs: Req 0x2961: -> ListObjects() (34.411408ms): OK
gcs: Req 0x2960: -> StatObject("sentinex9/") (35.190409ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2962: <- StatObject("sentinex90/")
gcs: Req 0x2963: <- ListObjects()
gcs: Req 0x2962: -> StatObject("sentinex90/") (33.335622ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2963: -> ListObjects() (48.678322ms): OK
gcs: Req 0x2964: <- StatObject("sentinex91/")
gcs: Req 0x2965: <- ListObjects()
gcs: Req 0x2965: -> ListObjects() (36.370272ms): OK
gcs: Req 0x2964: -> StatObject("sentinex91/") (44.374733ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2966: <- StatObject("sentinex94/")
gcs: Req 0x2967: <- ListObjects()
gcs: Req 0x2967: -> ListObjects() (31.822439ms): OK
gcs: Req 0x2966: -> StatObject("sentinex94/") (66.699435ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2968: <- StatObject("sentinex95/")
gcs: Req 0x2969: <- ListObjects()
gcs: Req 0x2968: -> StatObject("sentinex95/") (42.628801ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x2969: -> ListObjects() (48.214342ms): OK
gcs: Req 0x296a: <- StatObject("sentinex96/")
gcs: Req 0x296b: <- ListObjects()
gcs: Req 0x296a: -> StatObject("sentinex96/") (34.193435ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x296b: -> ListObjects() (49.027661ms): OK
gcs: Req 0x296c: <- StatObject("sentinex97/")
gcs: Req 0x296d: <- ListObjects()
gcs: Req 0x296c: -> StatObject("sentinex97/") (38.819693ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x296d: -> ListObjects() (45.655402ms): OK
gcs: Req 0x296e: <- StatObject("sentinex98/")
gcs: Req 0x296f: <- ListObjects()
gcs: Req 0x296e: -> StatObject("sentinex98/") (45.153316ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound
gcs: Req 0x296f: -> ListObjects() (48.420466ms): OK
gcs: Req 0x2970: <- StatObject("sentinex99/")
gcs: Req 0x2971: <- ListObjects()
gcs: Req 0x2970: -> StatObject("sentinex99/") (39.764603ms): gcs.NotFoundError: googleapi: Error 404: Not Found, notFound

###################CACHED ls one second after first ls############################################################################
gcs: Req 0x2971: -> ListObjects() (41.78773ms): OK
gcs: Req 0x2972: <- ListObjects()
gcs: Req 0x2972: -> ListObjects() (4.693871363s): OK
gcs: Req 0x2973: <- ListObjects()
gcs: Req 0x2973: -> ListObjects() (51.231895ms): OK
gcs: Req 0x2974: <- ListObjects()
gcs: Req 0x2974: -> ListObjects() (35.704218ms): OK
gcs: Req 0x2975: <- ListObjects()
gcs: Req 0x2975: -> ListObjects() (35.953026ms): OK
gcs: Req 0x2976: <- ListObjects()
gcs: Req 0x2976: -> ListObjects() (42.61748ms): OK
gcs: Req 0x2977: <- ListObjects()
gcs: Req 0x2977: -> ListObjects() (39.171019ms): OK
gcs: Req 0x2978: <- ListObjects()
gcs: Req 0x2978: -> ListObjects() (34.28617ms): OK
gcs: Req 0x2979: <- ListObjects()
gcs: Req 0x2979: -> ListObjects() (33.011924ms): OK
gcs: Req 0x297a: <- ListObjects()
gcs: Req 0x297a: -> ListObjects() (35.217218ms): OK
gcs: Req 0x297b: <- ListObjects()
gcs: Req 0x297b: -> ListObjects() (64.388192ms): OK
gcs: Req 0x297c: <- ListObjects()
gcs: Req 0x297c: -> ListObjects() (37.359582ms): OK
gcs: Req 0x297d: <- ListObjects()
gcs: Req 0x297d: -> ListObjects() (37.382852ms): OK
gcs: Req 0x297e: <- ListObjects()
gcs: Req 0x297e: -> ListObjects() (41.286502ms): OK
gcs: Req 0x297f: <- ListObjects()
gcs: Req 0x297f: -> ListObjects() (36.954473ms): OK
gcs: Req 0x2980: <- ListObjects()
gcs: Req 0x2980: -> ListObjects() (49.00951ms): OK
gcs: Req 0x2981: <- ListObjects()
gcs: Req 0x2981: -> ListObjects() (71.322802ms): OK
gcs: Req 0x2982: <- ListObjects()
gcs: Req 0x2982: -> ListObjects() (52.044272ms): OK
gcs: Req 0x2983: <- ListObjects()
gcs: Req 0x2983: -> ListObjects() (40.607039ms): OK
gcs: Req 0x2984: <- ListObjects()
gcs: Req 0x2984: -> ListObjects() (61.195279ms): OK
gcs: Req 0x2985: <- ListObjects()
gcs: Req 0x2985: -> ListObjects() (34.593267ms): OK
gcs: Req 0x2986: <- ListObjects()
gcs: Req 0x2986: -> ListObjects() (34.002863ms): OK
gcs: Req 0x2987: <- ListObjects()
gcs: Req 0x2987: -> ListObjects() (33.862426ms): OK
gcs: Req 0x2988: <- ListObjects()
gcs: Req 0x2988: -> ListObjects() (44.835745ms): OK
gcs: Req 0x2989: <- ListObjects()
gcs: Req 0x2989: -> ListObjects() (48.380727ms): OK
gcs: Req 0x298a: <- ListObjects()
gcs: Req 0x298a: -> ListObjects() (51.932726ms): OK
gcs: Req 0x298b: <- ListObjects()
gcs: Req 0x298b: -> ListObjects() (40.277724ms): OK
gcs: Req 0x298c: <- ListObjects()
gcs: Req 0x298c: -> ListObjects() (39.631286ms): OK
gcs: Req 0x298d: <- ListObjects()
gcs: Req 0x298d: -> ListObjects() (41.659744ms): OK
gcs: Req 0x298e: <- ListObjects()
gcs: Req 0x298e: -> ListObjects() (62.428874ms): OK
gcs: Req 0x298f: <- ListObjects()
gcs: Req 0x298f: -> ListObjects() (55.955499ms): OK
gcs: Req 0x2990: <- ListObjects()
gcs: Req 0x2990: -> ListObjects() (45.451371ms): OK
gcs: Req 0x2991: <- ListObjects()
gcs: Req 0x2991: -> ListObjects() (63.683477ms): OK
gcs: Req 0x2992: <- ListObjects()
gcs: Req 0x2992: -> ListObjects() (37.577807ms): OK
gcs: Req 0x2993: <- ListObjects()
gcs: Req 0x2993: -> ListObjects() (48.17949ms): OK
gcs: Req 0x2994: <- ListObjects()
gcs: Req 0x2994: -> ListObjects() (42.155634ms): OK
gcs: Req 0x2995: <- ListObjects()
gcs: Req 0x2995: -> ListObjects() (40.635657ms): OK
gcs: Req 0x2996: <- ListObjects()
gcs: Req 0x2996: -> ListObjects() (30.706096ms): OK
gcs: Req 0x2997: <- ListObjects()
gcs: Req 0x2997: -> ListObjects() (42.952396ms): OK
gcs: Req 0x2998: <- ListObjects()
gcs: Req 0x2998: -> ListObjects() (44.004212ms): OK
gcs: Req 0x2999: <- ListObjects()
gcs: Req 0x2999: -> ListObjects() (41.187845ms): OK
gcs: Req 0x299a: <- ListObjects()
gcs: Req 0x299a: -> ListObjects() (27.217496ms): OK
gcs: Req 0x299b: <- ListObjects()
gcs: Req 0x299b: -> ListObjects() (39.825995ms): OK
gcs: Req 0x299c: <- ListObjects()
gcs: Req 0x299c: -> ListObjects() (30.230263ms): OK
gcs: Req 0x299d: <- ListObjects()
gcs: Req 0x299d: -> ListObjects() (55.441112ms): OK
gcs: Req 0x299e: <- ListObjects()
gcs: Req 0x299e: -> ListObjects() (52.35953ms): OK
gcs: Req 0x299f: <- ListObjects()
gcs: Req 0x299f: -> ListObjects() (47.031055ms): OK
gcs: Req 0x29a0: <- ListObjects()
gcs: Req 0x29a0: -> ListObjects() (34.568742ms): OK
gcs: Req 0x29a1: <- ListObjects()
gcs: Req 0x29a1: -> ListObjects() (45.774289ms): OK
gcs: Req 0x29a2: <- ListObjects()
gcs: Req 0x29a2: -> ListObjects() (37.483606ms): OK
gcs: Req 0x29a3: <- ListObjects()
gcs: Req 0x29a3: -> ListObjects() (34.646773ms): OK
gcs: Req 0x29a4: <- ListObjects()
gcs: Req 0x29a4: -> ListObjects() (128.598576ms): OK
gcs: Req 0x29a5: <- ListObjects()
gcs: Req 0x29a5: -> ListObjects() (53.247834ms): OK
gcs: Req 0x29a6: <- ListObjects()
gcs: Req 0x29a6: -> ListObjects() (48.346916ms): OK
gcs: Req 0x29a7: <- ListObjects()
gcs: Req 0x29a7: -> ListObjects() (65.154179ms): OK
gcs: Req 0x29a8: <- ListObjects()
gcs: Req 0x29a8: -> ListObjects() (88.942783ms): OK
gcs: Req 0x29a9: <- ListObjects()
gcs: Req 0x29a9: -> ListObjects() (85.873305ms): OK
gcs: Req 0x29aa: <- ListObjects()
gcs: Req 0x29aa: -> ListObjects() (53.131612ms): OK
gcs: Req 0x29ab: <- ListObjects()
gcs: Req 0x29ab: -> ListObjects() (57.779759ms): OK
gcs: Req 0x29ac: <- ListObjects()
gcs: Req 0x29ac: -> ListObjects() (66.318339ms): OK
gcs: Req 0x29ad: <- ListObjects()
gcs: Req 0x29ad: -> ListObjects() (63.675915ms): OK
gcs: Req 0x29ae: <- ListObjects()
gcs: Req 0x29ae: -> ListObjects() (62.314175ms): OK
gcs: Req 0x29af: <- ListObjects()
gcs: Req 0x29af: -> ListObjects() (71.733439ms): OK
gcs: Req 0x29b0: <- ListObjects()
gcs: Req 0x29b0: -> ListObjects() (37.426682ms): OK
gcs: Req 0x29b1: <- ListObjects()
gcs: Req 0x29b1: -> ListObjects() (55.298518ms): OK
gcs: Req 0x29b2: <- ListObjects()
gcs: Req 0x29b2: -> ListObjects() (40.916871ms): OK
gcs: Req 0x29b3: <- ListObjects()
gcs: Req 0x29b3: -> ListObjects() (42.176601ms): OK
gcs: Req 0x29b4: <- ListObjects()
gcs: Req 0x29b4: -> ListObjects() (28.654289ms): OK
gcs: Req 0x29b5: <- ListObjects()
gcs: Req 0x29b5: -> ListObjects() (44.320406ms): OK
gcs: Req 0x29b6: <- ListObjects()
gcs: Req 0x29b6: -> ListObjects() (53.136362ms): OK
gcs: Req 0x29b7: <- ListObjects()
gcs: Req 0x29b7: -> ListObjects() (64.041401ms): OK
gcs: Req 0x29b8: <- ListObjects()
gcs: Req 0x29b8: -> ListObjects() (33.333698ms): OK
gcs: Req 0x29b9: <- ListObjects()
gcs: Req 0x29b9: -> ListObjects() (38.876045ms): OK
gcs: Req 0x29ba: <- ListObjects()
gcs: Req 0x29ba: -> ListObjects() (36.826077ms): OK
gcs: Req 0x29bb: <- ListObjects()
gcs: Req 0x29bb: -> ListObjects() (46.91826ms): OK
gcs: Req 0x29bc: <- ListObjects()
gcs: Req 0x29bc: -> ListObjects() (40.604428ms): OK
gcs: Req 0x29bd: <- ListObjects()
gcs: Req 0x29bd: -> ListObjects() (45.046665ms): OK
gcs: Req 0x29be: <- ListObjects()
gcs: Req 0x29be: -> ListObjects() (45.582192ms): OK
gcs: Req 0x29bf: <- ListObjects()
gcs: Req 0x29bf: -> ListObjects() (36.965705ms): OK
gcs: Req 0x29c0: <- ListObjects()
gcs: Req 0x29c0: -> ListObjects() (51.617851ms): OK
gcs: Req 0x29c1: <- ListObjects()
gcs: Req 0x29c1: -> ListObjects() (48.921086ms): OK
gcs: Req 0x29c2: <- ListObjects()
gcs: Req 0x29c2: -> ListObjects() (55.138331ms): OK
gcs: Req 0x29c3: <- ListObjects()
gcs: Req 0x29c3: -> ListObjects() (38.534302ms): OK
gcs: Req 0x29c4: <- ListObjects()
gcs: Req 0x29c4: -> ListObjects() (39.743498ms): OK
gcs: Req 0x29c5: <- ListObjects()
gcs: Req 0x29c5: -> ListObjects() (37.440974ms): OK
gcs: Req 0x29c6: <- ListObjects()
gcs: Req 0x29c6: -> ListObjects() (114.944359ms): OK
gcs: Req 0x29c7: <- ListObjects()
gcs: Req 0x29c7: -> ListObjects() (44.478053ms): OK
gcs: Req 0x29c8: <- ListObjects()
gcs: Req 0x29c8: -> ListObjects() (43.813968ms): OK
gcs: Req 0x29c9: <- ListObjects()
gcs: Req 0x29c9: -> ListObjects() (37.7359ms): OK
gcs: Req 0x29ca: <- ListObjects()
gcs: Req 0x29ca: -> ListObjects() (56.92245ms): OK
gcs: Req 0x29cb: <- ListObjects()
gcs: Req 0x29cb: -> ListObjects() (42.043475ms): OK
gcs: Req 0x29cc: <- ListObjects()
gcs: Req 0x29cc: -> ListObjects() (50.385027ms): OK
gcs: Req 0x29cd: <- ListObjects()
gcs: Req 0x29cd: -> ListObjects() (37.356855ms): OK
gcs: Req 0x29ce: <- ListObjects()
gcs: Req 0x29ce: -> ListObjects() (40.891519ms): OK
gcs: Req 0x29cf: <- ListObjects()
gcs: Req 0x29cf: -> ListObjects() (45.610107ms): OK
gcs: Req 0x29d0: <- ListObjects()
gcs: Req 0x29d0: -> ListObjects() (42.054391ms): OK
gcs: Req 0x29d1: <- ListObjects()
gcs: Req 0x29d1: -> ListObjects() (41.683692ms): OK
gcs: Req 0x29d2: <- ListObjects()
gcs: Req 0x29d2: -> ListObjects() (50.516826ms): OK
gcs: Req 0x29d3: <- ListObjects()
gcs: Req 0x29d3: -> ListObjects() (36.368762ms): OK
gcs: Req 0x29d4: <- ListObjects()
gcs: Req 0x29d4: -> ListObjects() (48.072046ms): OK
gcs: Req 0x29d5: <- ListObjects()
gcs: Req 0x29d5: -> ListObjects() (43.304369ms): OK
gcs: Req 0x29d6: <- ListObjects()
gcs: Req 0x29d6: -> ListObjects() (30.316902ms): OK
gcs: Req 0x29d7: <- ListObjects()

@jacobsa
Copy link
Contributor

jacobsa commented Aug 24, 2016

Again, you can see that fewer requests are made in the second case. The wall clock time is the same only because your listing is so huge: the stat calls are performed in parallel with follow-up list requests, and because you've got so many follow-up requests to make the stat calls complete long before you're done listing. In other cases (such as a small listing, or opening a file) the stat cache makes a big wall time difference.

Unfortunately I can't help you with large listings being slow in GCS; that's just how the API works (and the backend implementation too I suspect). The best that could be done here is caching the listing itself, but that is problematic:

  1. Unlike stat results, listing results are of an unbounded size. Pinning that memory is a bit nasty.
  2. Unlike stat results, the presence of a listing cache entry affects the fate of many objects. If you cache a listing for 5 minutes, it will be at least five minutes until you ever discover by listing that a new object has been created or an old one has been deleted.
  3. This exacerbates the existing problem of listings not being consistent. If you cache a listing and then delete an object yourself, it would still show up in the listing unless you do tricky cache invalidation dances.

So at the very least I think such a cache would need to be optional and off by default. I haven't heard any other complaints about this, so I'm not sure it's worth the effort (and the rarely-used feature that's likely to rot).

@conradneilands
Copy link
Author

Jacobsa,
I have tired of this, I will work around somehow. Clearly it's not worth your time and effort, which is to be expected for an unsupported access method. My current thoughts are that I will use the s3fuse driver instead. I guess this will at least allow me to quickly move off the google platform.

A key few points I have issue with.

100 to 200 folders is not really that big a directory.

  1. Even 1 minute of directory caching would be better than the current situation.
  2. Not really worried about consistency here. Wasn't that the point of the bucket storage? eventual consistency?

Options are great when given

And no most people will not complain, they will just give up and move on

Thanks for your help

@jacobsa
Copy link
Contributor

jacobsa commented Aug 25, 2016

I didn't intend to say this will never happen; just that it's not a clear win. Thank you for your report, which is a data point in its favor.

  1. How many total objects do you have in the bucket? I understand there are 100 to 200 folders in the top level, but how many total objects as descendants of those folders? That's the relevant number here unlike a traditional file system, unfortunately.
  2. gcsfuse makes many promises about consistency (see here). This is something that I must be very careful about.

@conradneilands
Copy link
Author

Currently at 204059 would hope to go to at least 500000

@conradneilands
Copy link
Author

Problem solved the s3fs seems to operate in the manor I require. i.e. directories are cached enough so as not to cause timeouts in programs using the directories
https://github.com/s3fs-fuse/s3fs-fuse/wiki/Google-Cloud-Storage
Thanks for your time and please let me know If a gcsfuse solution becomes available

@jacobsa jacobsa changed the title Directory listings are unusably slow Feature request: cache large directory listings Aug 26, 2016
@tobsch
Copy link

tobsch commented Jan 14, 2018

+1

@tobsch
Copy link

tobsch commented Jan 14, 2018

Some more words:

One of the most used pieces of web software called Wordpress does mkdir -p everywhere.
If you now want to host this with kubernetes on gcloud it is essential that you have gcsfuse or something similar for it's shared files (uploads).
Using gcsfuse slows down wordpress as hell as it does mkdir -p with almost every page request. In the case I have seen it slows down every page request by 2 seconds which is simply unacceptable.
All of that are stupid stat requests that are being repeated.

Any alternatives you see or things I have missed?

@tobsch
Copy link

tobsch commented Apr 17, 2018

Any plans on touching this, @jacobsa?

@jacobsa
Copy link
Contributor

jacobsa commented Apr 18, 2018

No, I still think that this is not a particularly obvious win due to the issues I mentioned earlier.

@vadlakondaswetha
Copy link
Collaborator

There are two issues which needs to addressed here.

  1. Improve the latency of directory listing when ls is invoked for the first time. Filed a seperate ticket for this (Request large listing with lesser supplemental info from GCS #652)
  2. Cache the response from the 1st call, so when ls is performed again, it will be much faster.

@sethiay sethiay added the p1 P1 label Jun 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Eng-Backlog feature request Feature request: request to add new features or functionality p1 P1
Projects
None yet
Development

No branches or pull requests

6 participants