Hello:
Ok - I’m still debugging the system I described in Files Transferred Multiple Times? - here’s a copy of the system summary for reference:
I’m running Syncthing on two locally-network Synology NAS units in order to reconcile a large data set (~4.6 million files at ~37TB) between the units, prior to moving one of the NAS units off-site. Both units have nearly the same data set (unfortunately not quite the same - probably 99% identical), and the data is not being touched, to allow the sync to complete. Only these two units are signed into the cluster, and they each only have one Shared Folder.
I’m aware that the NAS units won’t give very high performance, and that I’m using a large data set - so have set my expectations accordingly. However, I’m getting much slower sync than I would expect; the rate of transfer seems to vary considerably, but I’m typically getting ~100GB reconciled per day - and it’s been going on for months now!
I’m digging around in the log files, and have found a lot of ‘too many open files’ entries in the log for the NAS units. The sync appears to start off normally - but after >24hrs we get the ‘too many open files’ errors appearing, sometimes interrupted by Puller/finisher versions of the same file.
When the log entries are really going for it, we’re seeing about 45k entries per second of the form:
WARNING: Accepting connection (BEP/tcp): accept tcp [::]:22000: accept4: too many open files
Due to the massive log size, here are some extracts showing NAS02:
- (13:45:35) Syncthing being started, and starting a scan of the shared folder;
- (10:26:10) Receiving an index update from NAS01;
- (10:46:18) File syncing happening;
- (01:22:12) Syncing continuing to happen - then the first ‘too many open files’ error;
- (01:22:31) The ‘normal’ too many open files error interrupted by a Puller/finisher version of the same message;
- (22:01:55) The errors finishing in a panic, and syncthing restarting itself.
[OVPYX] 13:45:35 INFO: My ID: OVPYXBH-******-******-******-******-******-******-******
[OVPYX] 13:45:36 INFO: Single thread SHA256 performance is 92 MB/s using minio/sha256-simd (66 MB/s using crypto/sha256).
[OVPYX] 13:45:36 VERBOSE: Starting up (/usr/local/syncthing/var)
[OVPYX] 13:45:38 INFO: Hashing performance with weak hash is 80.84 MB/s
[OVPYX] 13:45:39 INFO: Hashing performance without weak hash is 91.25 MB/s
[OVPYX] 13:45:39 INFO: Weak hash enabled, as it has an acceptable performance impact.
[OVPYX] 14:16:56 INFO: Ready to synchronize "NAS" (bvkmk-wxrz3) (readwrite)
[OVPYX] 14:16:56 INFO: Send rate is unlimited, receive rate is unlimited
[OVPYX] 14:16:56 INFO: Rate limits do not apply to LAN connections
[OVPYX] 14:16:56 INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 14:16:56 INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 14:16:56 INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 14:16:56 INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[OVPYX] 14:16:56 INFO: TCP listener ([::]:22000) starting
[OVPYX] 14:16:56 INFO: KCP listener ([::]:22020) starting
[OVPYX] 14:16:56 VERBOSE: Folder "bvkmk-*****" is now scanning
[OVPYX] 14:16:58 INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[OVPYX] 14:16:58 INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[OVPYX] 14:16:58 INFO: Device GSXHK4J-******-******-******-******-******-******-****** is "NAS1" at [dynamic]
[OVPYX] 14:16:58 INFO: Device OVPYXBH-******-******-******-******-******-******-****** is "NAS02" at [dynamic]
[OVPYX] 14:16:58 VERBOSE: Startup complete
[OVPYX] 14:16:58 INFO: GUI and API listening on [::]:7070
[OVPYX] 14:16:58 INFO: Access the GUI via the following URL: http://127.0.0.1:7070/
[OVPYX] 14:17:01 VERBOSE: Local change detected in folder "bvkmk-*****": added dir subfolder/path1/here
...
[OVPYX] 10:26:10 VERBOSE: Device GSXHK4J-******-******-******-******-******-******-****** sent an index update for "bvkmk-*****" with 131 items
[OVPYX] 10:37:12 INFO: Completed initial scan of readwrite folder "NAS" (bvkmk-*****)
[OVPYX] 10:37:12 VERBOSE: Folder "bvkmk-*****" is now idle
[OVPYX] 10:37:12 VERBOSE: Folder "bvkmk-*****" is now syncing
[OVPYX] 10:39:26 VERBOSE: Device GSXHK4J-******-******-******-******-******-******-****** sent an index update for "bvkmk-*****" with 178 items
...
[OVPYX] 10:46:18 VERBOSE: Started syncing "bvkmk-*****" / "subfolder/path2/here" (update dir)
[OVPYX] 10:46:18 VERBOSE: Finished syncing "bvkmk-*****" / "subfolder/path2/here" (update dir): Success
[OVPYX] 10:46:18 VERBOSE: Started syncing "bvkmk-*****" / "subfolder/path3/here" (update dir)
[OVPYX] 10:46:18 VERBOSE: Finished syncing "bvkmk-*****" / "subfolder/path3/here" (update dir): Success
[OVPYX] 10:46:18 VERBOSE: Started syncing "bvkmk-*****" / "subfolder/path4/here" (update dir)
[OVPYX] 10:46:18 VERBOSE: Finished syncing "bvkmk-*****" / "subfolder/path5/here" (update dir): Success
...
[OVPYX] 01:22:12 VERBOSE: Started syncing "bvkmk-*****" / "file/path1/here" (update file)
[OVPYX] 01:22:14 VERBOSE: Started syncing "bvkmk-*****" / "file/path2/here" (update file)
[OVPYX] 01:22:16 WARNING: Accepting connection (BEP/tcp): accept tcp [::]:22000: accept4: too many open files
...
[OVPYX] 01:22:31 WARNING: Accepting connection (BEP/tcp): accept tcp [::]:22000: accept4: too many open files
[OVPYX] 01:22:31 INFO: Puller (folder "\"NAS\" (bvkmk-*****)", file "file/path3/here"): finisher: dst create: open /volume1/NAS/file/path4/here: too many open files
[OVPYX] 01:22:31 WARNING: Accepting connection (BEP/tcp): accept tcp [::]:22000: accept4: too many open files
...
[OVPYX] 22:01:55 WARNING: Accepting connection (BEP/tcp): accept tcp [::]:22000: accept4: too many open files
panic: open /usr/local/syncthing/var/index-v0.14.0.db/10492564.ldb: too many open files
[OVPYX] 22:01:57 INFO: syncthing v0.14.40 "Dysprosium Dragonfly" (go1.9.2 linux-amd64) teamcity@build.syncthing.net 2017-10-28 19:15:32 UTC
[OVPYX] 22:01:57 INFO: My ID: OVPYXBH-******-******-******-******-******-******-******
[OVPYX] 22:01:58 INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[OVPYX] 22:01:58 VERBOSE: Starting up (/usr/local/syncthing/var)
...
I’ve attached a redacted copy of the NAS02 panic log referenced here, plus screenshots of Syncthing from both NAS01 and NAS02.
I hope this is all of some use - please let me know if I can provide any further information to help diagnose this.
Many thanks,
Pants.
panic-20171126-220155_redacted.log (55.1 KB)
