Large folder of many small files - initial scan stuck on 0%

Hello,

I have a very large folder (~70GB) with many smallish files, from around 1MB up through 30MB.

On my Linux box both initial scan and regular scanning completes very fast (at least relative to folder size), less than 20 minutes from start to finish.

On MacOS, however, the sync stalls at 0%; during the hashing process.

So here are the things I have tried to do in getting this folder to sync:

  • First I tried syncing to an empty folder on the MacOS machine. This worked fine because there was nothing to hash on the MacOS machine; but transfer was very slow, less than 50,000 files a day (there are around 2,000,000 in total).
  • Given this would be complete sometime next month, I decided instead to try rsyncing across the directory, and then syncing.
  • This is where we run into the current issue: hashing on the linux box is fast (compared to expectations) - around 13 minutes for total scan; hashing on the MacOS box stalls at 0%. I also had it always convinced that the files on MacOS were ‘out of sync,’ despite being the same files rsynced across. Note that rsync managed an average of 25MB/s transfer rate; this whole transfer took about 40 minutes.

In trying to fix this slow hashing, I have:

  • Tried disabling permissions etc.
  • Tried deleting the database on both devices.
  • Tried setting the Mac box to send only, and the Linux box to receive only.
  • Made sure the Low Priority checkbox was off.
  • Tried disabling the MacOS automatic setting of low background process priority with sudo sysctl debug.lowpri_throttle_enabled=0.
  • Tried disabling Spotlight indexing, as this was using a lot of CPU and I was wondering if it would interfere with file access times. I assume it was indexing all the new files, no telling how long that would take. Turning it off didn’t reduce the process’ CPU usage, though.

The hardware of both machines is new; CPU usage is higher on the Mac than on the Linux box, but this is expected as it is less beefy (it hangs around 2-10% on the Mac, 0.5-2.5% on the Linux box).

Here is a sample of debug output for the scanner - I am not sure what else I can show here:

2022-04-08 11:13:46 walker/ng6wn-5vg5q@0x1400147c000 to hash: User 1/collection.media/0x00122e40.wav.ogg File{Name:"User 1/collection.media/0x00122e40.wav.ogg", Sequence:0, Permissions:0700, ModTime:2021-12-08 09:49:02.843752233 +0000 GMT, Version:{[{OFN3KP7 1649412826}]}, VersionHash:, Length:50527, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2022-04-08 11:13:46 walker/ng6wn-5vg5q@0x1400147c000 to hash: User 1/collection.media/A_JojoS01_E05_1_0.06.37.980.jpg File{Name:"User 1/collection.media/A_JojoS01_E05_1_0.06.37.980.jpg", Sequence:0, Permissions:0700, ModTime:2021-12-08 09:56:08.993738134 +0000 GMT, Version:{[{OFN3KP7 1649412826}]}, VersionHash:, Length:15979, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2022-04-08 11:13:46 walker/ng6wn-5vg5q@0x1400147c000 to hash: User 1/collection.media/A_Assassination_classroom_E10_1_0.19.47.110.jpg File{Name:"User 1/collection.media/A_Assassination_classroom_E10_1_0.19.47.110.jpg", Sequence:0, Permissions:0700, ModTime:2021-12-08 09:50:42.887082262 +0000 GMT, Version:{[{OFN3KP7 1649412826}]}, VersionHash:, Length:18146, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}
2022-04-08 11:13:46 walker/ng6wn-5vg5q@0x1400147c000 to hash: User 1/collection.media/Dorohedoro_01_0.20.35.734-0.20.39.134.mp3 File{Name:"User 1/collection.media/Dorohedoro_01_0.20.35.734-0.20.39.134.mp3", Sequence:0, Permissions:0700, ModTime:2021-12-08 10:04:06.933722393 +0000 GMT, Version:{[{OFN3KP7 1649412826}]}, VersionHash:, Length:56509, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:}

Output of time ls -lR on the directory on the linux bos:

real    0m13.249s
user    0m8.612s
sys     0m4.075s

On the MacOS box:

real	5m18.654s
user	0m22.367s
sys	0m54.529s

Even accounting for the processing gap, a difference of ~13 minutes for initial hashing vs. 0% after sitting there for ~12 hours seems off to me! If the ls output is anything to go by, I would maybe exepect around 5-10 hours for initial hashing. Would I be right in thinking that this process is single threaded, as well? If that is the case, then the two processors are almost identical in SC performance on basically any benchmark I have thrown at them.

I am suspecting some weirdness with MacOS and file access at present.

Please let me know what other info I can provide/things I can try. I am aware this might be a somewhat absurd case; in the future this folder will be a lot smaller, but I want to be able to be doing the things necessary for that on both devices :slight_smile:

Is the folder on your Mac located on a HDD?

Try the steps in this post and check if it’s the same cause:

1 Like

Hello, thank you for the prompt reply!

The folder in question is on an SSD.

$ sudo fs_usage syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000080 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000100 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000095 W syncthing
12:12:02  getdirentries64                                                                          0.000354   syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000103 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000111 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000088 W syncthing
12:12:02  getdirentries64                                                                          0.000385   syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000099 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000103 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000089 W syncthing
12:12:02  getdirentries64                                                                          0.000374   syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000092 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000112 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000096 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000078 W syncthing
12:12:02  getdirentries64                                                                          0.000476   syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000100 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000080 W syncthing
12:12:02  getdirentries64                                                                          0.000258   syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000107 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000075 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000076 W syncthing
12:12:02    RdMeta[S]       /dev/disk3                                                             0.000075 W syncthing
...

I should note that other, less bonkers folders do hash fine; but still 0% after several hours seems odd.

I see some people in previous threads mentioning hashing speed explicitly in terms of MB/s, is there a way I can see that? Or are they just working it out via a benchmark or by dividing time taken by the amount?

I don’t know if this info is helpful, but I am beginning to doubt it when it says scanning 0% - if I am going by the database size alone, the complete database is around 356MB, whereas the one on MacOS seems to hit around 250MB and basically just sit there. This would usually seem like a permissions issue to me, but ignoring permissions didn’t resolve the issue, so… Maybe I will try changing the permissions temporarily for all files in any case.

Could be due to case sensitive filesystem checking. You should make sure you are on the latest version.

1 Like

I can confirm I am on the latest version on both machines.

I switched back to the former approach of syncing via Syncthing for the first sync, rather than using rsync and then syncing, which should avoid the long hashing stage.

I started by syncing the largest files first, so I could get a guestimate based on what was left as to how long it would take to sync the whole folder. Now, I know that Syncthing does a lot more than rsync per file, is a difference of 26mb/s vs. 220kb/s within the realm of expectations?

This is over a direct TCP connection - before the connection was using a relay, so I made sure to switch to rule that out.

Yes, Syncthing does do a lot a lot more per file than rsync, but unless these files are super tiny, it should be faster.

It does seem to me that the OS is throttling the application in one way or another, if neither io, not cpu nor network is bottlenecked. Sadly I don’t use a mac to advise. I suspect you would not see this between two linux machines.

I’d also make sure that syncthings database is on an ssd.

For clarity: I think that last sentence should end like this: “… faster than 220kb/s”.

1 Like

If you check the output of sudo fs_usage syncthing, do you see any THROTTLED entries? You mentioned running sudo sysctl debug.lowpri_throttle_enabled=0, just wondering because that e.g. requires to restart Syncthing to take effect and isn’t persisted on restart.

1 Like

Nope, I don’t see anything mentioning throttling, just a whole lot of getdirentries64 with the odd few other entries every few hundred lines.

Here is an example break in the pattern:

21:36:14  close                                                                                              0.000003   syncthing   
21:36:14  lstat64           /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000053   syncthing   
21:36:15  open              /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000019   syncthing   
21:36:15  fstat64                                                                                            0.000002   syncthing   
21:36:15  lstat64           t/Anki2/User 1/collection.media/A_GrandBlue_E12_1_0.10.34.051-0.10.36.970.mp3    0.000004   syncthing   
21:36:15  write                                                                                              0.002868   syncthing   
21:36:15  fcntl                                                                                              0.023295   syncthing   
21:36:15  close                                                                                              0.000003   syncthing   
21:36:15  write                                                                                              0.000011   syncthing   
21:36:15  write                                                                                              0.000004   syncthing   
21:36:15  read                                                                                               0.000002   syncthing   
21:36:15  write                                                                                              0.000024   syncthing   
21:36:15  read                                                                                               0.000001   syncthing   
21:36:15  write                                                                                              0.000055   syncthing   
21:36:15  write                                                                                              0.000819   syncthing   
21:36:15  write                                                                                              0.000005   syncthing   
21:36:15  write                                                                                              0.000004   syncthing   
21:36:15  write                                                                                              0.000002   syncthing   
21:36:15  read                                                                                               0.000001   syncthing   
21:36:15  statfs64          /Users/hearth/Library/Application Support/Anki2                                  0.000021   syncthing   
21:36:15  stat64            /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000004   syncthing   
21:36:15  pread                                                                                              0.000007   syncthing   
21:36:15  lstat64           ection.media/.syncthing.gang_ald_m_04_afam_20_q114_f_1f0d4419383c5004.mp3.tmp    0.000012   syncthing   
21:36:15  pread                                                                                              0.000006   syncthing   
21:36:15  lstat64           /Users/hearth/Library/Application Support/Anki2/User 1                           0.000003   syncthing   
21:36:15  open              ection.media/.syncthing.gang_ald_m_04_afam_20_q114_f_1f0d4419383c5004.mp3.tmp    0.000058   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15    WrData[A]       n.media/.syncthing.gang_mls_m_01_enus_30_maelstrom_f_1936964f91588004.mp3.tmp    0.000069 W syncthing   
21:36:15  lstat64           /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000002   syncthing   
21:36:15  lstat64           ection.media/.syncthing.gang_ald_m_04_afam_20_q114_f_1f0d4419383c5004.mp3.tmp    0.000002   syncthing   
21:36:15  open              /Users/hearth/Library/Application Support/Anki2                                  0.000010   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstatfs64                                                                                          0.000002   syncthing   
21:36:15  getdirentries64                                                                                    0.000017   syncthing   
21:36:15  close                                                                                              0.000001   syncthing   
21:36:15  close                                                                                              0.000001   syncthing   
21:36:15  open              /Users/hearth/Library/Application Support/Anki2/User 1                           0.000008   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstatfs64                                                                                          0.000001   syncthing   
21:36:15  getdirentries64                                                                                    0.000014   syncthing   
21:36:15  close                                                                                              0.000001   syncthing   
21:36:15  close                                                                                              0.000001   syncthing   
21:36:15  lstat64           /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000002   syncthing   
21:36:15  open              /Users/hearth/Library/Application Support/Anki2/User 1/collection.media          0.000009   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstat64                                                                                            0.000001   syncthing   
21:36:15  fcntl                                                                                              0.000001   syncthing   
21:36:15  fstatfs64                                                                                          0.000002   syncthing   
21:36:15  getdirentries64                                                                                    0.000040   syncthing   
21:36:15  getdirentries64                                                                                    0.000113   syncthing   
21:36:15  getdirentries64                                                                                    0.000097   syncthing   

@AudriusButkevicius Might see if I can test it a little with another linux machine, though I don’t own another one personally, I can probably loan one for a bit. For now, though, databases on both end are on SSDs.

Sounds like case sensitivity checks are slowing things down, but not sure what you can do about it.

I had the same problem on underpowered small machine, and enabling Case Sensitive FS, solved the problem.

The difference in performance was:

A) +1day
B) ~ 10 minutes (after enabling CSFS)

This is VERY COSTLY check :slight_smile:

Also, I noticed that this check is:

  • being executed on both scanning and syncing phases
  • its performance hit is strictly dependent on number of files in folder
  • I’m not sure why it is (IMO it shouldnt) be executed on scanning phase
  • Maybe there is also possibility/reason to do it once per folder, not per every file

@AudriusButkevicius: I can file a bug and help in testing if you consider it worthwhile to investigate further.

The check is done every time we Stat() a file, which is quite often, and requires a ReadDir() on the parent directories. There’s a cache, but it’s not very long lived.