Ask a Question

Can someone read these logs and tell me why file upload so slow?

0 votes
by (150 points)

Hello guys, first post. Running BuruSFTP on Windows 10 Pro. I use a folder syncing app that I use to upload files to a drive connected to BSFTP. Almost all folders sync fine, but this "com.whatsapp media Ahmad" is CRAWLING! It started out very fast, but something now is not letting me finish the sync (20 gigs and 1000s of files). I contacted the folder sync dev, he says not much is showing in the logs for his app, but to look at server logs. I downloaded it and I don't see much obvious in there. Can you guys take a look and tell me if I could configure something differently in BSFTP to get past these ridiculously slow processing of files? None of the individual files are especially big and I have a gig wired connection for the BSFTP server machine.

Here's the log link, appreciate your help!

https://drive.google.com/file/d/1Amg9UStGWhFPhKEe67XIpTSDGVEx0zHt/view?usp=drivesdk

1 Answer

+1 vote
by (15.2k points)

Hello,

thank you for the log. It shows that the client does some intensive work when synchronizing your folders. There are some delays before next folder is processed. See some delays below after a packet is send back to a client when a folder is closed (this is a confirmation packet that a close folder operation was completed) and when next packet is received from a client to do some other work (opening new folder to process)

small delay about 6 seconds:

2021-08-13 23:04:54.652 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (26 bytes).
2021-08-13 23:04:54.652 -05:00 [Debug] Closing directory '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WallPaper': success (2 items enumerated).
2021-08-13 23:04:54.652 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:05:00.536 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (128 bytes).
2021-08-13 23:05:00.537 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Animated Gifs/

large delay about 106 seconds:

2021-08-13 23:05:03.098 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (26 bytes).
2021-08-13 23:05:03.098 -05:00 [Debug] Closing directory '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Documents': success (45 items enumerated).
2021-08-13 23:05:03.098 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:06:49.108 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (121 bytes).
2021-08-13 23:06:49.109 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/

Also there is one major issue with the client process. During the synchronization of your folders, the client lists one folder many times. Since it is a folder with more than 10000 files, listing that folder takes about 20 seconds. Your client lists your big folder 149 times in one session! So it takes almost 50 minutes to list it so many times. Listing of a folder happens after each file that is uploaded to the server side.

2021-08-13 23:07:08.567 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (26 bytes).
2021-08-13 23:07:08.567 -05:00 [Debug] Closing directory '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images': success (10263 items enumerated).
2021-08-13 23:07:08.567 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:08:05.926 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (154 bytes).
2021-08-13 23:08:05.926 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart
2021-08-13 23:08:05.926 -05:00 [Information] Session 7: Attempting GetItemInfo FSO Read "/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart"
2021-08-13 23:08:05.932 -05:00 [Debug] Getting item info on '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart': not found.
2021-08-13 23:08:05.932 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (45 bytes).
2021-08-13 23:08:05.939 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (154 bytes).
2021-08-13 23:08:05.939 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart
2021-08-13 23:08:05.939 -05:00 [Information] Session 7: Attempting GetItemInfo FSO Read "/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart"
2021-08-13 23:08:05.945 -05:00 [Debug] Getting item info on '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart': not found.
2021-08-13 23:08:05.945 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (45 bytes).
2021-08-13 23:08:05.962 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (162 bytes).
2021-08-13 23:08:05.962 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart
2021-08-13 23:08:05.962 -05:00 [Information] Session 7: Attempting OpenFile FSO Write, Create "/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart"
2021-08-13 23:08:05.987 -05:00 [Debug] Opening file '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart' (Create, Write): success.
2021-08-13 23:08:05.987 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (26 bytes).
2021-08-13 23:08:06.016 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (65545 bytes).
2021-08-13 23:08:06.019 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:08:06.020 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (65545 bytes).
2021-08-13 23:08:06.022 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (26411 bytes).
2021-08-13 23:08:06.023 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:08:06.024 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:08:06.066 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (26 bytes).
2021-08-13 23:08:06.074 -05:00 [Debug] Closing file '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/IMG-20200907-WA0001.jpg.tacitpart': success.
2021-08-13 23:08:06.074 -05:00 [Debug] Session 7: Sent packet SSH_MSG_CHANNEL_DATA (32 bytes).
2021-08-13 23:08:06.078 -05:00 [Debug] Session 7: Received packet SSH_MSG_CHANNEL_DATA (121 bytes).
2021-08-13 23:08:06.078 -05:00 [Debug] Resolving path: /AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images/
2021-08-13 23:08:06.078 -05:00 [Information] Session 7: Attempting OpenDirectory FSO List "/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images"
2021-08-13 23:08:06.079 -05:00 [Debug] Opening directory '/AhmadBadal1/Faraz Stuff/FolderSyncFiles/Android/media/com.whatsapp/WhatsApp/Media/WhatsApp Images': success.

Changing the client behavior to not list a folder after each upload to a server should speed up the process rapidly.

by (150 points)
Hello Pavel,

I really, really appreciate your response and the time you put into studying and explaining the logs to me. You are in fact correct. I submitted the same log to the client (FolderSync) app developer. He seems to agree that there is indeed a lack of optimization on how the directories are being processed. He sent me a beta build of the app and I did see the that the process did in fact finish this time, albeit with different errors. If you'd like to study and confirm a positive change, here's the new log I collected today:

https://drive.google.com/file/d/1DmAfQEbdxqVfHMekHRN14f03jtzy3Dei/view?usp=drivesdk

Thank you again!
by (15.2k points)
Hello,

I did not see any error in your previous server log (I looked into last communication handled by "Session 7"). I will look into your new log file and let you know what I find.
by (15.2k points)
Hello,

I can confirm that the listing after each uploaded file is no longer in the log. This issue seems to be resloved then. There are some "strange" sequences though. I am fine with uploading a file to a temporary file and then renaming it to correcte name. But before each uploade there is a double check whether that temporoary file exists and after succesful renaming there is a check whether the renamed file (the correct one) actually exists. This adds about 100 miliseconds to each file uploaded. Given that it transfers more than 10000 files, it adds up to about 15 to 20 minutes. If all files are transferred because they do not exists on the server side, there is not much that can be done to speed up the process unless you try to split the bulk to some small number of parallel transfers.
...