Exceptionally long sync time

I hove Joplin 2.2.7 running on 4 different devices: An Intel Mac mini, A ThinkPad T450 running Manjaro Linux, an iPhone 10R, and an iPad Pro. All these devices are on the latest operating system available for them.

I am using NextCloud to sync all 4 devices.

My average sync time is about 10 minutes over home Wi-Fi or Gigabit Ethernet.

Is this exceptionally long for the number of notes I have?

Hi

Installed on an SD, HDD, SDD ... ?

apples, seconds, houres, minutes?

How many notes, resources, tags, ...

My Joplin needs ~6-10 second (With no changed items) for 35897 items on a Synology WebDav syntarget.

Installed on an SD, HDD, SDD ... ?

SSDs and internal storage on iPhone and iPad.

apples, seconds, houres, minutes?

It takes, on average 10 minutes for Joplin to sync

How many notes, resources, tags, ...

30 notes. 24 tags. Where do I get resource information?

You can find the infos in the Sync stats: Help > Syncronisation Status > Sync status (synced items / total items)
But for so few items is 10 minutes long.

Could you please enable the debug log and post the log after a sync.

https://joplinapp.org/debugging/

Sync status (synced items / total items)
Note: 47/47
Folder: 5/5
Resource: 91/91
Tag: 59/59
NoteTag: 78/78
MasterKey: 0/0
Revision: 30/30
Total: 310/310

And here is what's in the logs:

2021-08-17 15:33:10: "Running background sync on timer..."
2021-08-17 15:33:10: "Scheduling sync operation...", "0"
2021-08-17 15:33:10: "Preparing scheduled sync"
2021-08-17 15:33:10: "Starting scheduled sync"
2021-08-17 15:33:10: "Synchronisation is already in progress. State: in_progress"
2021-08-17 15:33:10: "Setting up recurrent sync with interval 300"
2021-08-17 15:33:18: FileApi: "list "
2021-08-17 15:33:18: FileApi: "list "
2021-08-17 15:33:52: "Saving settings..."
2021-08-17 15:33:52: "Settings have been saved."
2021-08-17 15:34:55: FileApi: "put locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json", "null"
2021-08-17 15:35:51: FileApi: "delta "
2021-08-17 15:36:49: Synchronizer: "BasicDelta: Report: {"timestamp":1628915384000,"older":330,"newer":2,"equal":1}"
2021-08-17 15:36:49: Synchronizer: "Sync: fetchingTotal: Fetching delta items from sync target"
2021-08-17 15:36:49: FileApi: "get 6ef1d7834ca04cf0acbfe215623a6d19.md"
2021-08-17 15:36:49: FileApi: "get 32aa55721efd4b6e9142caac4aef6ed3.md"
2021-08-17 15:36:49: Synchronizer: "Sync: fetchingProcessed: Processing fetched item"
2021-08-17 15:36:51: FileApi: "list "
2021-08-17 15:37:52: Synchronizer: "Sync: updateLocal: remote is more recent than local: Note: (Local 6ef1d7834ca04cf0acbfe215623a6d19): (Remote 6ef1d7834ca04cf0acbfe215623a6d19.md)"
2021-08-17 15:37:52: Synchronizer: "Sync: fetchingProcessed: Processing fetched item"
2021-08-17 15:38:02: "SearchEngine: Updating FTS table..."
2021-08-17 15:38:02: "Saving settings..."
2021-08-17 15:38:02: "Settings have been saved."
2021-08-17 15:38:02: "SearchEngine: Updated FTS table in 33ms. Inserted: 1. Deleted: 0"
2021-08-17 15:38:10: "Running background sync on timer..."
2021-08-17 15:38:10: "Scheduling sync operation...", "0"
2021-08-17 15:38:10: "Preparing scheduled sync"
2021-08-17 15:38:10: "Starting scheduled sync"
2021-08-17 15:38:10: "Synchronisation is already in progress. State: in_progress"
2021-08-17 15:38:10: "Setting up recurrent sync with interval 300"
2021-08-17 15:38:10: RevisionService: "RevisionService::maintenance: Starting..."
2021-08-17 15:38:10: RevisionService: "RevisionService::maintenance: Service is enabled"
2021-08-17 15:38:11: RevisionService: "RevisionService::collectRevisions: Created revisions for 0 notes"
2021-08-17 15:38:11: RevisionService: "RevisionService::maintenance: Done in 107ms"
2021-08-17 15:38:54: Synchronizer: "Sync: createLocal: remote exists but local does not: (Remote 32aa55721efd4b6e9142caac4aef6ed3.md)"
2021-08-17 15:38:54: FileApi: "delete locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json"
2021-08-17 15:38:55: "Saving settings..."
2021-08-17 15:38:55: "Settings have been saved."
2021-08-17 15:40:41: Synchronizer: "Sync: finished: Synchronisation finished [1629228492256]"
2021-08-17 15:40:41: Synchronizer: "Operations completed: "
2021-08-17 15:40:41: Synchronizer: "fetchingTotal: 2"
2021-08-17 15:40:41: Synchronizer: "fetchingProcessed: 2"
2021-08-17 15:40:41: Synchronizer: "updateLocal: 1"
2021-08-17 15:40:41: Synchronizer: "createLocal: 1"
2021-08-17 15:40:41: Synchronizer: "Total folders: 5"
2021-08-17 15:40:41: Synchronizer: "Total notes: 47"
2021-08-17 15:40:41: Synchronizer: "Total resources: 91"
2021-08-17 15:40:41: "Setting up recurrent sync with interval 300"
2021-08-17 15:40:41: "Updating all notifications..."
2021-08-17 15:40:41: "Garbage collecting alarms..."
2021-08-17 15:40:41: "Sync has finished and note has never been changed - reloading it"
2021-08-17 15:40:41: "Trying to reload note that has been deleted:", "null"
2021-08-17 15:40:42: "Saving settings..."
2021-08-17 15:40:42: "Settings have been saved."
2021-08-17 15:40:42: "DecryptionWorker: cannot start because no master key is currently loaded."
2021-08-17 15:41:43: "Saving settings..."
2021-08-17 15:41:43: "Settings have been saved."
2021-08-17 15:41:48: "CommandService::execute:", "openProfileDirectory", "[]"

Restarted the app and did another sync.

2021-08-17 16:12:48: Synchronizer: "Sync target info:", "{"version":2}"
2021-08-17 16:12:48: FileApi: "list "
2021-08-17 16:12:48: FileApi: "list "
2021-08-17 16:12:48: "SearchEngine: Updated FTS table in 3ms. Inserted: 0. Deleted: 0"
2021-08-17 16:12:48: "ResourceService::indexNoteResources: Completed"
2021-08-17 16:12:48: "ResourceService::deleteOrphanResources:", "[]"
2021-08-17 16:13:40: FileApi: "put temp/timeCheck726470.txt", "null"
2021-08-17 16:14:15: "Saving settings..."
2021-08-17 16:14:15: "Settings have been saved."
2021-08-17 16:14:51: FileApi: "stat temp/timeCheck726470.txt"
2021-08-17 16:15:54: FileApi: "delete temp/timeCheck726470.txt"
2021-08-17 16:15:54: FileApi: "put locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json", "null"
2021-08-17 16:18:00: FileApi: "list "
2021-08-17 16:18:00: FileApi: "list "
2021-08-17 16:19:43: FileApi: "put locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json", "null"
2021-08-17 16:20:36: FileApi: "delta "
2021-08-17 16:20:57: RevisionService: "RevisionService::maintenance: Starting..."
2021-08-17 16:20:57: RevisionService: "RevisionService::maintenance: Service is enabled"
2021-08-17 16:20:57: RevisionService: "RevisionService::collectRevisions: Created revisions for 0 notes"
2021-08-17 16:20:57: RevisionService: "RevisionService::maintenance: Done in 105ms"
2021-08-17 16:21:27: Synchronizer: "BasicDelta: Report: {"timestamp":1629084057000,"older":332,"newer":0,"equal":1}"
2021-08-17 16:21:27: Synchronizer: "Sync: fetchingTotal: Fetching delta items from sync target"
2021-08-17 16:21:27: FileApi: "delete locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json"
2021-08-17 16:21:28: "Saving settings..."
2021-08-17 16:21:28: "Settings have been saved."
2021-08-17 16:22:23: Synchronizer: "Sync: finished: Synchronisation finished [1629231058822]"
2021-08-17 16:22:23: Synchronizer: "Operations completed: "
2021-08-17 16:22:23: Synchronizer: "fetchingTotal: -"
2021-08-17 16:22:23: Synchronizer: "Total folders: 5"
2021-08-17 16:22:23: Synchronizer: "Total notes: 47"
2021-08-17 16:22:23: Synchronizer: "Total resources: 91"
2021-08-17 16:22:23: "Recurrent sync is disabled"
2021-08-17 16:22:23: "Updating all notifications..."
2021-08-17 16:22:23: "Garbage collecting alarms..."
2021-08-17 16:22:23: "Sync has finished and note has never been changed - reloading it"
2021-08-17 16:22:23: "Trying to reload note that has been deleted:", "null"
2021-08-17 16:22:23: "Saving settings..."
2021-08-17 16:22:23: "Settings have been saved."
2021-08-17 16:22:24: "DecryptionWorker: cannot start because no master key is currently loaded."
2021-08-17 16:22:55: "CommandService::execute:", "openProfileDirectory", "[]"

Here is what is displayed in the lower left corner

Completed: 08/17/2021 4:22 PM (685s)

Unfortunately, this is not a complete log file and only with mini excerpts it is difficult to analyze the whole thing.

I'm not 100% sure, but it looks like your Nextcloud is extrem slow.

  • Creating the lockfile takes almost two minutes
  • Getting the delta infos takes almost two minutes
  • Deleting the lockfile takes almost two minutes
2021-08-17 15:34:55: FileApi: "put locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json", "null"
2021-08-17 15:35:51: FileApi: "delta "
2021-08-17 15:36:49: Synchronizer: "BasicDelta: Report: {"timestamp":1628915384000,"older":330,"newer":2,"equal":1}"

2021-08-17 15:38:54: FileApi: "delete locks/sync_desktop_ca03e6fac27b4faabda94ad527561b7d.json"
2021-08-17 15:40:41: Synchronizer: "Sync: finished: Synchronisation finished [1629228492256]"

I will do some experimenting. Nextcloud is on my local LAN on a Gigabit Etherner connection.

Could you pleas run the following two commands and post the output.

curl -T C:\test.md <YOURSYNCURL>/test.md --user user:password -v --trace-time
curl -X DELETE <YOURSYNCURL>/test.md --user user:password -v --trace-time
21:44:21.772139 *   Trying 192.168.1.5:443...
21:44:21.774259 * Connected to www.xxxxxxxxx.net (192.168.1.5) port 443 (#0)
21:44:21.774591 * ALPN, offering h2
21:44:21.774631 * ALPN, offering http/1.1
21:44:21.780607 * successfully set certificate verify locations:
21:44:21.780660 *  CAfile: /etc/ssl/certs/ca-certificates.crt
21:44:21.780707 *  CApath: none
21:44:21.780958 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
21:44:21.786762 * TLSv1.3 (IN), TLS handshake, Server hello (2):
21:44:21.786957 * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
21:44:21.789884 * TLSv1.3 (IN), TLS handshake, Certificate (11):
21:44:21.790380 * TLSv1.3 (IN), TLS handshake, CERT verify (15):
21:44:21.790506 * TLSv1.3 (IN), TLS handshake, Finished (20):
21:44:21.790583 * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
21:44:21.790670 * TLSv1.3 (OUT), TLS handshake, Finished (20):
21:44:21.790773 * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
21:44:21.790853 * ALPN, server accepted to use http/1.1
21:44:21.790907 * Server certificate:
21:44:21.790949 *  subject: CN=www.xxxxxxxxx.net
21:44:21.790988 *  start date: Jul  1 09:11:35 2021 GMT
21:44:21.791022 *  expire date: Sep 29 09:11:34 2021 GMT
21:44:21.791065 *  subjectAltName: host "www.xxxxxxxxx.net" matched cert's "www.xxxxxxxxx.net"
21:44:21.791104 *  issuer: C=US; O=Let's Encrypt; CN=R3
21:44:21.791148 *  SSL certificate verify ok.
21:44:21.791193 * Server auth using Basic with user 'andy'
21:44:21.791265 > PUT /owncloud/remote.php/dav/files/andy/Joplin/test.md HTTP/1.1
21:44:21.791265 > Host: www.xxxxxxxxx.net
21:44:21.791265 > Authorization: Basic YW5keTpmZWIxOTIwMDE=
21:44:21.791265 > User-Agent: curl/7.78.0
21:44:21.791265 > Accept: */*
21:44:21.791265 > Content-Length: 2044
21:44:21.791265 > Expect: 100-continue
21:44:21.791265 > 
21:44:21.793480 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
21:44:21.793565 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
21:44:21.793630 * old SSL session ID is stale, removing
21:44:22.792469 * Done waiting for 100-continue
21:44:22.792821 * We are completely uploaded and fine

21:45:28.150420 * Mark bundle as not supporting multiuse
21:45:28.150467 < HTTP/1.1 100 Continue
21:45:29.382361 * Mark bundle as not supporting multiuse
21:45:29.382406 < HTTP/1.1 201 Created
21:45:29.382462 < Date: Thu, 19 Aug 2021 01:44:21 GMT
21:45:29.382511 < Server: Apache/2.4.41 (Ubuntu)
21:45:29.382555 < Referrer-Policy: no-referrer
21:45:29.382609 < X-Content-Type-Options: nosniff
21:45:29.382656 < X-Download-Options: noopen
21:45:29.382703 < X-Frame-Options: SAMEORIGIN
21:45:29.382750 < X-Permitted-Cross-Domain-Policies: none
21:45:29.382793 < X-Robots-Tag: none
21:45:29.382837 < X-XSS-Protection: 1; mode=block
21:45:29.382886 < Set-Cookie: oc4113171f9c=pvtj7tt7mh89tbvem9nsq3mj5h; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:45:29.382935 < Expires: Thu, 19 Nov 1981 08:52:00 GMT
21:45:29.382978 < Cache-Control: no-store, no-cache, must-revalidate
21:45:29.383020 < Pragma: no-cache
21:45:29.383070 < Set-Cookie: oc_sessionPassphrase=kXBvbH3xYGjVmDJE7IqLWVolO2QqDtaRMbR%2FTVkSIKdWBMeLLDNZ15BgksEjzCsr4YA9f2hPQSIbXgZloVVG4AM0W2k2VN1E7%2FJUQLcNkcjp7ukyqzgyYPMY44lEmwpV; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:45:29.383116 < Set-Cookie: oc4113171f9c=qf3lhantiu1lbhnl8fufker1j8; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:45:29.383163 < Content-Security-Policy: default-src 'none';
21:45:29.383213 < Set-Cookie: nc_sameSiteCookielax=true; path=/owncloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=lax
21:45:29.383265 < Set-Cookie: nc_sameSiteCookiestrict=true; path=/owncloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=strict
21:45:29.383315 < Set-Cookie: oc4113171f9c=ljko49aia1dde7e3sfnrkk8gu3; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:45:29.383362 < Set-Cookie: cookie_test=test; expires=Thu, 19-Aug-2021 02:45:26 GMT; Max-Age=3600
21:45:29.383407 < X-Hash-SHA256: ad2cd2bed9f5ca7a8038ad8c3d06992d2a7fc28c19ad98f39e2d63960fb35ede
21:45:29.383456 < X-Hash-SHA1: 7ca9123cbcacf0017f40974672380c7161a1fbda
21:45:29.383506 < X-Hash-MD5: b141ac5aeae1d814afef77a2f6e0f7a0
21:45:29.383551 < OC-FileId: 00158388oc4113171f9c
21:45:29.383589 < Content-Length: 0
21:45:29.383623 < ETag: "d6eb48d6bbf2b3aba7442f3ed8499c4d"
21:45:29.383664 < OC-ETag: "d6eb48d6bbf2b3aba7442f3ed8499c4d"
21:45:29.383705 < Content-Type: text/html; charset=UTF-8
21:45:29.383743 < 
21:45:29.383792 * Connection #0 to host www.xxxxxxxxx.net left intact
21:49:05.988185 *   Trying 192.168.1.5:443...
21:49:05.990523 * Connected to www.xxxxxxxxx.net (192.168.1.5) port 443 (#0)
21:49:05.991801 * ALPN, offering h2
21:49:05.991885 * ALPN, offering http/1.1
21:49:05.997800 * successfully set certificate verify locations:
21:49:05.997857 *  CAfile: /etc/ssl/certs/ca-certificates.crt
21:49:05.997899 *  CApath: none
21:49:05.998151 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
21:49:06.001548 * TLSv1.3 (IN), TLS handshake, Server hello (2):
21:49:06.001854 * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
21:49:06.003691 * TLSv1.3 (IN), TLS handshake, Certificate (11):
21:49:06.004831 * TLSv1.3 (IN), TLS handshake, CERT verify (15):
21:49:06.005065 * TLSv1.3 (IN), TLS handshake, Finished (20):
21:49:06.005190 * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
21:49:06.005327 * TLSv1.3 (OUT), TLS handshake, Finished (20):
21:49:06.005435 * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
21:49:06.005482 * ALPN, server accepted to use http/1.1
21:49:06.005521 * Server certificate:
21:49:06.005561 *  subject: CN=www.xxxxxxxxx.net
21:49:06.005619 *  start date: Jul  1 09:11:35 2021 GMT
21:49:06.005658 *  expire date: Sep 29 09:11:34 2021 GMT
21:49:06.005707 *  subjectAltName: host "www.xxxxxxxxx.net" matched cert's "www.xxxxxxxxx.net"
21:49:06.005755 *  issuer: C=US; O=Let's Encrypt; CN=R3
21:49:06.005794 *  SSL certificate verify ok.
21:49:06.005845 * Server auth using Basic with user 'andy'
21:49:06.005934 > DELETE /owncloud/remote.php/dav/files/andy/Joplin/test.md HTTP/1.1
21:49:06.005934 > Host: www.xxxxxxxxx.net
21:49:06.005934 > Authorization: Basic YW5keTpmZWIxOTIwMDE=
21:49:06.005934 > User-Agent: curl/7.78.0
21:49:06.005934 > Accept: */*
21:49:06.005934 > 
21:49:06.007612 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
21:49:06.007753 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
21:49:06.007819 * old SSL session ID is stale, removing
21:50:13.532999 * Mark bundle as not supporting multiuse
21:50:13.533053 < HTTP/1.1 204 No Content
21:50:13.533105 < Date: Thu, 19 Aug 2021 01:49:05 GMT
21:50:13.533153 < Server: Apache/2.4.41 (Ubuntu)
21:50:13.533202 < Referrer-Policy: no-referrer
21:50:13.533243 < X-Content-Type-Options: nosniff
21:50:13.533288 < X-Download-Options: noopen
21:50:13.533326 < X-Frame-Options: SAMEORIGIN
21:50:13.533375 < X-Permitted-Cross-Domain-Policies: none
21:50:13.533422 < X-Robots-Tag: none
21:50:13.533464 < X-XSS-Protection: 1; mode=block
21:50:13.533512 < Set-Cookie: oc4113171f9c=c9187sqlhb5orpnmadbbnr0vse; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:50:13.533558 < Expires: Thu, 19 Nov 1981 08:52:00 GMT
21:50:13.533597 < Cache-Control: no-store, no-cache, must-revalidate
21:50:13.533640 < Pragma: no-cache
21:50:13.533681 < Set-Cookie: oc_sessionPassphrase=%2FULIEvMr4n%2FNMsukO6AxY8rL%2FwXmWxB4j2hWDmHqsjMkfcmeJ1CkmdbEdloNVh%2B90drFY0z9545WwQZ9Pbg%2BKb949yMmU4zR65ey3EqhyYwFtHk4lSxuyrWGj60mClaX; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:50:13.533718 < Set-Cookie: oc4113171f9c=evajim19onjo4vd0t8d13hcq5e; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:50:13.533764 < Content-Security-Policy: default-src 'none';
21:50:13.533813 < Set-Cookie: nc_sameSiteCookielax=true; path=/owncloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=lax
21:50:13.533865 < Set-Cookie: nc_sameSiteCookiestrict=true; path=/owncloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=strict
21:50:13.533911 < Set-Cookie: oc4113171f9c=79d0e5rdk1j7ishjbbeuh8a06s; path=/owncloud; secure; HttpOnly; SameSite=Lax
21:50:13.533947 < Set-Cookie: cookie_test=test; expires=Thu, 19-Aug-2021 02:50:11 GMT; Max-Age=3600
21:50:13.533990 < 
21:50:13.534042 * Connection #0 to host www.xxxxxxxxx.net left intact

Ok, the problem is not Joplin.
As you can see there is a huge time jump in both commandos at once.

Both times the timestamp of the reply matches the request time, but the reply comes over a minute later.

21:44:21.791265 > 
21:45:29.382406 < HTTP/1.1 201 Created
21:45:29.382462 < Date: Thu, 19 Aug 2021 01:44:21 GMT
21:49:06.005934 > 
....
21:50:13.533053 < HTTP/1.1 204 No Content
21:50:13.533105 < Date: Thu, 19 Aug 2021 01:49:05 GMT

Therefore, it will be a network problem or a problem on the Nextcloud server.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.