Slow upload to rPi SD after upgrade to 1.4.2

Get Help
21

THis is really weird. I just tried this on a fresh install on a Pi3+, definitely no waiting for the analysis. Then I transferred my testing library with 450MB of various files, folders and whatnot over, tried again, and now I seem to see a wait. It doesn't make any sense at all so far.

Case in point, fresh:

2021-03-12 14:42:20,508 - octoprint.filemanager.analysis - INFO - Starting analysis of local:trispinner_prusa.gcode
2021-03-12 14:42:20,510 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python3 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 /home/pi/.octoprint/uploads/trispinner_prusa.gcode
2021-03-12 14:42:20,537 - tornado.access - INFO - 201 POST /api/files/local (::ffff:192.168.1.3) 1526.08ms
2021-03-12 14:42:20,551 - tornado.access - INFO - 200 POST /api/files/local (::ffff:192.168.1.3) 1540.22ms
2021-03-12 14:42:20,641 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads',base='',force_refresh=False) took 29.56ms
2021-03-12 14:42:20,674 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('local',filter=False,recursive=True,allow_from_cache=True) took 63.53ms
2021-03-12 14:42:20,674 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('sdcard',) took 0.03ms
2021-03-12 14:42:20,741 - tornado.access - INFO - 200 GET /api/files?recursive=true (::ffff:192.168.1.3) 149.74ms
2021-03-12 14:42:31,361 - octoprint.filemanager.analysis - INFO - Analysis of entry local:trispinner_prusa.gcode finished, needed 10.85s
2021-03-12 14:42:31,397 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads',base='',force_refresh=False) took 4.85ms
2021-03-12 14:42:31,400 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('local',filter=False,recursive=True,allow_from_cache=True) took 8.85ms
2021-03-12 14:42:31,406 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('sdcard',) took 0.02ms
2021-03-12 14:42:31,415 - tornado.access - INFO - 200 GET /api/files?recursive=true (::ffff:192.168.1.3) 31.23ms

And with 450MB library:

2021-03-12 15:00:19,293 - tornado.access - INFO - 201 POST /api/files/local (::ffff:192.168.1.3) 3297.66ms
2021-03-12 15:00:19,313 - tornado.access - INFO - 200 POST /api/files/local (::ffff:192.168.1.3) 3318.07ms
2021-03-12 15:00:30,723 - octoprint.filemanager.analysis - INFO - Analysis of entry local:pia/trispinner_prusa.gcode finished, needed 11.49s
2021-03-12 15:00:31,373 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/pia',base='pia/',force_refresh=False) took 1.89ms
2021-03-12 15:00:31,376 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/biqu_bx',base='biqu_bx/',force_refresh=False) took 2.06ms
2021-03-12 15:00:31,381 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_2773',base='test/issue_2773/',force_refresh=False) took 0.24ms
2021-03-12 15:00:31,384 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_2629',base='test/issue_2629/',force_refresh=False) took 1.87ms
2021-03-12 15:00:31,387 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/gcodeviewer_lag',base='test/gcodeviewer_lag/',force_refresh=False) took 1.94ms
2021-03-12 15:00:31,389 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3930',base='test/issue_3930/',force_refresh=False) took 1.95ms
2021-03-12 15:00:31,392 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3387',base='test/issue_3387/',force_refresh=False) took 1.92ms
2021-03-12 15:00:31,394 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3437',base='test/issue_3437/',force_refresh=False) took 1.94ms
2021-03-12 15:00:31,397 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/foo',base='test/foo/',force_refresh=False) took 1.90ms
2021-03-12 15:00:31,401 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3541/Folder_1/Sub_Folder_1',base='test/issue_3541/Folder_1/Sub_Folder_1/',force_refresh=False) took 0.20ms
2021-03-12 15:00:31,403 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3541/Folder_1/Sub_Folder_2',base='test/issue_3541/Folder_1/Sub_Folder_2/',force_refresh=False) took 1.87ms
2021-03-12 15:00:31,404 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3541/Folder_1',base='test/issue_3541/Folder_1/',force_refresh=False) took 3.84ms
2021-03-12 15:00:31,404 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3541',base='test/issue_3541/',force_refresh=False) took 6.73ms
2021-03-12 15:00:31,409 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test/issue_3057',base='test/issue_3057/',force_refresh=False) took 4.46ms
2021-03-12 15:00:31,409 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/test',base='test/',force_refresh=False) took 32.71ms
2021-03-12 15:00:31,412 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/h2',base='h2/',force_refresh=False) took 1.99ms
2021-03-12 15:00:31,414 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/foo',base='foo/',force_refresh=False) took 1.74ms
2021-03-12 15:00:31,418 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/blurb',base='haussge/blurb/',force_refresh=False) took 0.18ms
2021-03-12 15:00:31,422 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/wolf_face',base='haussge/test/wolf_face/',force_refresh=False) took 0.18ms
2021-03-12 15:00:31,424 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/blorb',base='haussge/test/blorb/',force_refresh=False) took 1.83ms
2021-03-12 15:00:31,426 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/bloorb',base='haussge/test/bloorb/',force_refresh=False) took 1.77ms
2021-03-12 15:00:31,429 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/dog_face',base='haussge/test/dog_face/',force_refresh=False) took 1.63ms
2021-03-12 15:00:31,431 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/test',base='haussge/test/test/',force_refresh=False) took 1.68ms
2021-03-12 15:00:31,433 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test/blarb',base='haussge/test/blarb/',force_refresh=False) took 1.79ms
2021-03-12 15:00:31,434 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge/test',base='haussge/test/',force_refresh=False) took 15.03ms
2021-03-12 15:00:31,434 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/haussge',base='haussge/',force_refresh=False) took 19.28ms
2021-03-12 15:00:31,439 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads/another_test',base='another_test/',force_refresh=False) took 4.14ms
2021-03-12 15:00:31,443 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x726fe030>,'/home/pi/.octoprint/uploads',base='',force_refresh=False) took 10403.85ms
2021-03-12 15:00:31,505 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('local',filter=False,recursive=True,allow_from_cache=True) took 11162.68ms
2021-03-12 15:00:31,506 - octoprint.server.api.files.timings - DEBUG - octoprint.server.api.files._getFileList('sdcard',) took 0.03ms
2021-03-12 15:00:31,535 - tornado.access - INFO - 200 GET /api/files?recursive=true (::ffff:192.168.1.3) 12196.06ms
22

Interesting. Where you get:

/home/pi/.octoprint/uploads',base='',force_refresh=False) took 10403.85ms

On a folder refresh, mine shows:

force_refresh=True) took 1816.68ms

and on a reboot:

force_refresh=False) took 14236.09ms

and I just spotted this earlier in the scan:

2021-03-12 17:41:12,694 - octoprint.filemanager.storage.timings - DEBUG - octoprint.filemanager.storage._list_folder(<octoprint.filemanager.storage.LocalFileStorage object at 0x728a4650>,'/home/pi/.octoprint/uploads/FDG',base='FDG/',force_refresh=False) took 14033.18ms

FDG is my largest folder (contents are around 5.5 Gigs), it is in the root, and it's got a ton of sub-folders and files. Probably 80% of my storage is this folder. Understandable to take a long time to scan when asked for, but should not be included in the scan when I upload a file.

So, happy to see it's reproducible for you at least.

23

The problem at its core is probably that right now OctoPrint doesn't just refresh the folder you uploaded to, it always refreshes the whole tree. I use some heavy internal caching here to make sure it only actually has to crawl all the files from the changed subtree again, but that still means it'll have to walk the full tree.

We might simply see the limitations of that, though I'm not entirely sure yet.

I'll try to continue to dig, but it might just need a change in the refresh approach altogether after all.

24

Danke, Gina. I'll consider it a known issue then, and continue to live with the delay for now.

I suppose it's a good thing I don't have it pointed at my NAS folder where I save all my .gcodes to before uploading to each Pi. :see_no_evil: :hear_no_evil: