Mac Desktop Client: Slow Change Detection

Summary
The Mac Desktop client seemingly doesn’t detect changes. It seems to run recurring refresh of the entire folder/file directory, and it’s very slow. It evaluates every single file and folder at a rate of approximately 1 file or folder per second. Once it’s finished and the green checkmark appears, it waits for about 10 seconds, and then starts over from the top.

What I’ve done

  • Research: I’ve read a few help community conversations that talk about slow performance, but none of the solutions presented helped my situation.
  • Per one suggestion, I updated PHP and everything else I can think of: PHP to 7.2, Redis to 4.0.9, Nextcloud to 13.0.1, Mac client to 2.3.3, etc. No performance change.
  • Per another suggestion, I added the line innodb_flush_log_at_trx_commit = 2 to the my.cnf file. No performance change.

Can you tell us a bit more about the synced files, how many and which size in total? Open the logging terminal with F12 in your client, do you see any errors? Server logs?

First off, thanks for telling me how to get to the log. Had to modify my keyboard settings to turn off the Dashboard for F12, but this is a far more useful function.

Files: 1.67 GB distributed amongst 514 items (from Finder, which presumably skips hidden files, but there’s nothing significant there).

I let it run for a while, and then copied the log into a text editor for analysis. It never produced a single error/warning/caution or other problem. What I learned is that it starts off fast. Nanosecond fast. It evaluates the entire directory and notes INSTRUCTION_NONE for each file, but every folder is noted as INSTRUCTION_UPDATE_METADATA. The fact that I haven’t interacted with any of these folders in any client doesn’t seem to matter.

Here is the point at which the process slows down to seconds. It confirms the speed of the prior evaluation(s), and then moves into something else:

04-08 09:23:52:070 0x7fa98bd139a8 csync_update: Update detection for local replica took 0.07 seconds walking 532 files.
04-08 09:23:52:070 329624 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x6080000ddff0)  Calling into main thread...
04-08 09:23:52:515 11934 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "my.domain" + "/nextcloud" "OCC::DiscoverySingleDirectoryJob"
04-08 09:23:56:662 11934 OCC::DiscoveryMainThread::singleDirectoryJobFirstDirectoryPermissionsSlot: Permissions for root dir: "RMGDNVCK"
04-08 09:23:56:663 11934 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer> &) Have 8 results for  "/nextcloud"
04-08 09:23:56:663 329624 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x6080000ddff0)  ...Returned from main thread

After this, it It generated thousands of lines, most of which look like the following:

04-08 09:24:02:407 329624 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x6080000ddff0) path/to/folder Calling into main thread...
04-08 09:24:02:409 11934 OCC::AbstractNetworkJob::start: !!! OCC::LsColJob created for "my.domain" + "/cloud/path/to/folder" "OCC::DiscoverySingleDirectoryJob"
04-08 09:24:08:689 11934 OCC::DiscoveryMainThread::singleDirectoryJobResultSlot: void OCC::DiscoveryMainThread::singleDirectoryJobResultSlot(const QList<OCC::FileStatPointer> &) Have 4 results for  "/cloud/path/to/folder"
04-08 09:24:08:690 329624 OCC::DiscoveryJob::remote_vio_opendir_hook: OCC::DiscoveryJob(0x6080000ddff0) path/to/folder ...Returned from main thread
04-08 09:24:08:690 0x7fa98bd139a8 csync_walker: file: path/to/file1.docx [file_id=00005129oc1ba375tic7 size=104]
04-08 09:24:08:690 0x7fa98bd139a8 sqlite_profile: _SQL_ SELECT phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId FROM metadata WHERE phash=?1: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: Database entry found, compare: 1439403475 <-> 1439403475, etag: 5ab8be143a423 <-> 5ab8be143a423, inode: 0 <-> 8593176093, size: 104 <-> 104, perms: RmGDNVW <-> RmGDNVW, ignore: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: file: path/to/file1.docx, instruction: INSTRUCTION_NONE <<=
04-08 09:24:08:690 0x7fa98bd139a8 csync_walker: file: path/to/file2.docx [file_id=00005130oc1ba375tic7 size=114684]
04-08 09:24:08:690 0x7fa98bd139a8 sqlite_profile: _SQL_ SELECT phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId FROM metadata WHERE phash=?1: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: Database entry found, compare: 1506429870 <-> 1506429870, etag: 5ab8be146a7eb <-> 5ab8be146a7eb, inode: 0 <-> 8593176094, size: 114684 <-> 114684, perms: RmGDNVW <-> RmGDNVW, ignore: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: file: path/to/file2.docx, instruction: INSTRUCTION_NONE <<=
04-08 09:24:08:690 0x7fa98bd139a8 csync_walker: file: path/to/file3.docx [file_id=00005131oc1ba375tic7 size=110158]
04-08 09:24:08:690 0x7fa98bd139a8 sqlite_profile: _SQL_ SELECT phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId FROM metadata WHERE phash=?1: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: Database entry found, compare: 1400515736 <-> 1400515736, etag: 5ab8be148ccb2 <-> 5ab8be148ccb2, inode: 0 <-> 8593176095, size: 110158 <-> 110158, perms: RmGDNVW <-> RmGDNVW, ignore: 0
04-08 09:24:08:690 0x7fa98bd139a8 _csync_detect_update: file: path/to/file3.docx, instruction: INSTRUCTION_NONE <<=
04-08 09:24:08:691 0x7fa98bd139a8 csync_walker: directory: path/to/subfolder1 [file_id=00005128oc1ba375tic7]
04-08 09:24:08:691 0x7fa98bd139a8 sqlite_profile: _SQL_ SELECT phash, pathlen, path, inode, uid, gid, mode, modtime, type, md5, fileid, remotePerm, filesize, ignoredChildrenRemote, contentChecksum, contentChecksumTypeId FROM metadata WHERE phash=?1: 0
04-08 09:24:08:691 0x7fa98bd139a8 _csync_detect_update: Database entry found, compare: 1523187448 <-> 1523186779, etag: 5aca26088a669 <-> 5aca236b48a15, inode: 0 <-> 8592980173, size: 0 <-> 0, perms: RmGDNVCK <-> RmGDNVCK, ignore: 0
04-08 09:24:08:691 0x7fa98bd139a8 _csync_detect_update: file: path/to/subfolder1, instruction: INSTRUCTION_EVAL <<=

Then it moves in to do the same thing in that subfolder. As you can see in the timestamps, the second line where it starts the DiscoverySingleDirectoryJob is where speed takes a hit. I don’t know what this is doing, and Googling it didn’t turn up anything that helps me understand it.

Status: Still not resolved.

I doubt it’s related, but just in case, I have a second topic open right now for what seems like an unrelated issue. But if anyone sees a common theme between them, I’m all-ears.

During this discovery process, is there a high load on the database server (on the server)? Could be that this verification process takes too long due to a slow database response (perhaps use slow-query to catch a few, then you can check the database cache settings). The size of the synced folder and the number of files still has a reasonable size.

I had some pretty core issues going on. Sys-admin friend of mine helped me blow away the original installation and reinstall fresh using the snap package. It won’t be possible to finish diagnosing this, nor relevant to my installation to do so.

On a related note, it seems like the documentation is either wrong or highly misleading in the sense that there’s no direction for a snap installation to NOT proceed with all of the next steps on the installation page, which aren’t necessary if using the snap installation.