nextcloud / mail

šŸ’Œ Mail app for Nextcloud
https://apps.nextcloud.com/apps/mail
GNU Affero General Public License v3.0
843 stars 260 forks source link

Account sync performance issue #8545

Open Mer0me opened 1 year ago

Mer0me commented 1 year ago

Steps to reproduce

  1. Configure several imap accounts with 2GB of emails under MS Exchange 2007
  2. Let Nextcloud perform default background sync of these account with system cron
  3. See multiple cron processes on the server, as it takes more than 30 minutes to execute

Expected behavior

Background sync of mail accounts should be quicker

Actual behavior

A single account with 2GB of mails sync can take several minutes to be executed. Even if we have just synced it a few minutes ago. When you have 400 accounts and each one take 3 minutes to sync, the background job may takes hours to finish and the nextcloud cronjob cannot be finished before the next one begins, five minutes later.

The old mail server (Exchange 2007) may be partly responsible of the slow sync, but other clients like Thunderbird, Outlook or some other webmails (SnappyMail) are displaying this very same mailboxes instantly after the first sync. Each future refresh takes then a few milliseconds to perform.

Syncing with occ command does not show relevant informations (see below) Disabling the Mail app allow the nextcloud cronjob to be executed in a couple of minutes as it should do for this instance scale I guess.

Mail app version

3.2.0

Mailserver or service

Exchange 2007

Operating system

Debian 11

PHP engine version

PHP 8.1

Web server

Apache (supported)

Database

MariaDB

Additional info

root@cloud:/var/www/nextcloud# time sudo -u www-data php8.1 ./occ mail:account:sync -vvv 190
[debug] account is up to date, skipping mailbox sync
[debug] Skipping mailbox sync for 12558
[debug] Skipping mailbox sync for 12560
[debug] Skipping mailbox sync for 12561
[debug] Skipping mailbox sync for 12562
[debug] Skipping mailbox sync for 12563
[debug] Skipping mailbox sync for 12564
[debug] Skipping mailbox sync for 12565
[debug] Skipping mailbox sync for 12566
[debug] Skipping mailbox sync for 16009
[debug] Skipping mailbox sync for 16037
[debug] Skipping mailbox sync for 16369
[debug] Skipping mailbox sync for 16073
[debug] Skipping mailbox sync for 16021
[debug] Skipping mailbox sync for 16022
[debug] Skipping mailbox sync for 16065
[debug] Skipping mailbox sync for 16011
[debug] Skipping mailbox sync for 16019
[debug] Skipping mailbox sync for 16028
[debug] Skipping mailbox sync for 16023
[debug] Skipping mailbox sync for 16018
[debug] Skipping mailbox sync for 16029
[debug] Skipping mailbox sync for 16020
[debug] Skipping mailbox sync for 16061
[debug] Skipping mailbox sync for 16062
[debug] Skipping mailbox sync for 16034
[debug] Skipping mailbox sync for 16015
[debug] Skipping mailbox sync for 16064
[debug] Skipping mailbox sync for 16066
[debug] Skipping mailbox sync for 16068
[debug] Skipping mailbox sync for 16010
[debug] Skipping mailbox sync for 16014
[debug] Skipping mailbox sync for 16025
[debug] Skipping mailbox sync for 16012
[debug] Skipping mailbox sync for 16060
[debug] Skipping mailbox sync for 16026
[debug] Skipping mailbox sync for 16027
[debug] Skipping mailbox sync for 16013
[debug] Skipping mailbox sync for 16069
[debug] Skipping mailbox sync for 16070
[debug] Skipping mailbox sync for 16071
[debug] Skipping mailbox sync for 16072
[debug] Skipping mailbox sync for 16030
[debug] Skipping mailbox sync for 16035
[debug] Skipping mailbox sync for 16036
[debug] Skipping mailbox sync for 16031
[debug] Skipping mailbox sync for 16032
[debug] Syncing 12559
[debug] Locking mailbox 12559 for new messages sync
[debug] Locking mailbox 12559 for changed messages sync
[debug] Locking mailbox 12559 for vanished messages sync
[debug] Running partial sync for 12559
[debug] partial sync 190:INBOX - get all known UIDs took 0s. 57/57MB memory used
[debug] partial sync 190:INBOX - get new messages via Horde took 2s. 58/58MB memory used
[debug] partial sync 190:INBOX - classified a chunk of new messages took 4s. 59/59MB memory used
[debug] partial sync 190:INBOX - persist new messages took 0s. 59/59MB memory used
[debug] partial sync 190:INBOX - get changed messages via Horde took 179s. 81/83MB memory used
[debug] partial sync 190:INBOX - persist changed messages took 2s. 81/84MB memory used
[debug] partial sync 190:INBOX - get vanished messages via Horde took 0s. 78/84MB memory used
[debug] partial sync 190:INBOX - delete vanished messages took 0s. 78/84MB memory used
**[debug] partial sync 190:INBOX took 187s**
[debug] Unlocking mailbox 12559 from vanished messages sync
[debug] Unlocking mailbox 12559 from changed messages sync
[debug] Unlocking mailbox 12559 from new messages sync
[debug] Skipping mailbox sync for 12570
[debug] Skipping mailbox sync for 12571
[debug] Skipping mailbox sync for 12572
[debug] Skipping mailbox sync for 12573
[debug] Skipping mailbox sync for 12574
[debug] Skipping mailbox sync for 12575
[debug] Skipping mailbox sync for 12576
[debug] Skipping mailbox sync for 12567
[debug] Skipping mailbox sync for 12568
[debug] Building threads for account 190
[debug] Account 190 has 2645 messages with threading information
[debug] Threading 2645 messages - build ID table took 0s. 81/84MB memory used
[debug] Threading 2645 messages - build root container took 0s. 81/84MB memory used
[debug] Threading 2645 messages - free ID table took 0s. 81/84MB memory used
[debug] Threading 2645 messages - prune containers took 0s. 81/84MB memory used
[debug] Threading 2645 messages - group by subject took 0s. 81/84MB memory used
[debug] Threading 2645 messages took 0s
[debug] Account 190 has 2308 threads
[debug] Account 190 has 3 messages with a new thread IDs
[debug] Chunk of 500 messages updated
83MB of memory used

real    3m10,472s
user    0m14,859s
sys     0m9,391s

Look at the execution duration column of the oc_jobs table :

image

Resulting in nextcloud cron job launched at 15:15 is already running at 16:04 :

image

Mer0me commented 1 year ago

Sometimes, displaying the mailboxes of these accounts on Nextcloud Mail App is crashing with this log in the error console :

Could not sync envelopes: Request failed with status code 500 
Object { message: "Request failed with status code 500", name: "AxiosError", code: "ERR_BAD_RESPONSE", config: {ā€¦}, request: XMLHttpRequest, response: {ā€¦}, stack: "" }
actions.js:822:15
[ERROR] mail: Could not sync envelopes: Request failed with status code 500 
Object { app: "mail", uid: "username", level: 2, error: {ā€¦}, init: true }
ConsoleLogger.js:59:18
    value ConsoleLogger.js:59
    value ConsoleLogger.js:85
    n Mailbox.vue:473
    e match.js:32
    f match.js:2
    L match.js:2
    w match.js:2
    o match.js:2
    s match.js:2
    i match.js:2
    t match.js:2
    i match.js:27
    n Mailbox.vue:468
    u Mailbox.vue:50
    b Mailbox.vue:50
    y Mailbox.vue:50
    ir Mailbox.vue:50
    s Mailbox.vue:50
    (Asynchrone : promise callback)
    ir Mailbox.vue:50
    i Mailbox.vue:50
    sr Mailbox.vue:50
    sr Mailbox.vue:50
    sync Mailbox.vue:454
    initializeCache Mailbox.vue:207
    e Mailbox.vue:271
    u Mailbox.vue:50
    b Mailbox.vue:50
    y Mailbox.vue:50
    ir Mailbox.vue:50
    i Mailbox.vue:50
    sr Mailbox.vue:50
    sr Mailbox.vue:50
    e Mailbox.vue:276
    e match.js:29
    f match.js:2
    L match.js:2
    w match.js:2
    o match.js:2
    s match.js:2
    i match.js:2
    t match.js:2
    i match.js:27
    e Mailbox.vue:259
    u Mailbox.vue:50
    b Mailbox.vue:50
    y Mailbox.vue:50
    ir Mailbox.vue:50
    s Mailbox.vue:50
    (Asynchrone : promise callback)
    ir Mailbox.vue:50
    i Mailbox.vue:50
    sr Mailbox.vue:50
    sr Mailbox.vue:50
    loadEnvelopes Mailbox.vue:214
    e Mailbox.vue:188
    u Mailbox.vue:50
    b Mailbox.vue:50
    y Mailbox.vue:50
    ir Mailbox.vue:50
    i Mailbox.vue:50
    sr Mailbox.vue:50
    sr Mailbox.vue:50
    mounted Mailbox.vue:187
    VueJS 15
Uncaught (in promise) 
Object { message: "Request failed with status code 500", name: "AxiosError", code: "ERR_BAD_RESPONSE", config: {ā€¦}, request: XMLHttpRequest, response: {ā€¦}, stack: "" }
ā€‹
code: "ERR_BAD_RESPONSE"
ā€‹
config: Object { timeout: 0, xsrfCookieName: "XSRF-TOKEN", xsrfHeaderName: "X-XSRF-TOKEN", ā€¦ }
ā€‹
message: "Request failed with status code 500"
ā€‹
name: "AxiosError"
ā€‹
request: XMLHttpRequest { readyState: 4, timeout: 0, withCredentials: false, ā€¦ }
ā€‹
response: Object { data: {ā€¦}, status: 500, statusText: "Internal Server Error", ā€¦ }
ā€‹
stack: ""
ā€‹
<prototype>: Object { constructor: a(e, t, n, r, a), toJSON: toJSON()
, stack: "", ā€¦ }
ChristophWurst commented 1 year ago

https://github.com/nextcloud/mail/pull/8494 should address this.

Mer0me commented 1 year ago

Mail v3.2.4 does not address the problem. Should it ?

root@cloud:/var/www/nextcloud# time sudo -u www-data php8.1 ./occ mail:account:sync -vvv 190
[debug] Skipping mailbox sync for 12558
[debug] Skipping mailbox sync for 12560
[debug] Skipping mailbox sync for 12561
[debug] Skipping mailbox sync for 12562
[debug] Skipping mailbox sync for 12563
[debug] Skipping mailbox sync for 12564
[debug] Skipping mailbox sync for 12565
[debug] Skipping mailbox sync for 12566
[debug] Skipping mailbox sync for 16009
[debug] Skipping mailbox sync for 16037
[debug] Skipping mailbox sync for 16369
[debug] Skipping mailbox sync for 16073
[debug] Skipping mailbox sync for 16021
[debug] Skipping mailbox sync for 16022
[debug] Skipping mailbox sync for 16065
[debug] Skipping mailbox sync for 16011
[debug] Skipping mailbox sync for 16019
[debug] Skipping mailbox sync for 16028
[debug] Skipping mailbox sync for 16023
[debug] Skipping mailbox sync for 16018
[debug] Skipping mailbox sync for 16029
[debug] Skipping mailbox sync for 16020
[debug] Skipping mailbox sync for 16061
[debug] Skipping mailbox sync for 16062
[debug] Skipping mailbox sync for 16034
[debug] Skipping mailbox sync for 16015
[debug] Skipping mailbox sync for 16064
[debug] Skipping mailbox sync for 16066
[debug] Skipping mailbox sync for 16068
[debug] Skipping mailbox sync for 16010
[debug] Skipping mailbox sync for 16014
[debug] Skipping mailbox sync for 16025
[debug] Skipping mailbox sync for 16012
[debug] Skipping mailbox sync for 16060
[debug] Skipping mailbox sync for 16026
[debug] Skipping mailbox sync for 16027
[debug] Skipping mailbox sync for 16013
[debug] Skipping mailbox sync for 16069
[debug] Skipping mailbox sync for 16070
[debug] Skipping mailbox sync for 16071
[debug] Skipping mailbox sync for 16072
[debug] Skipping mailbox sync for 16030
[debug] Skipping mailbox sync for 16035
[debug] Skipping mailbox sync for 16036
[debug] Skipping mailbox sync for 16031
[debug] Skipping mailbox sync for 16032
[debug] Syncing 12559
[debug] Locking mailbox 12559 for new messages sync
[debug] Locking mailbox 12559 for changed messages sync
[debug] Locking mailbox 12559 for vanished messages sync
[debug] Running partial sync for 12559
[debug] partial sync 190:INBOX - get all known UIDs took 0s. 58/59MB memory used
[debug] partial sync 190:INBOX - get new messages via Horde took 4s. 59/59MB memory used
[debug] partial sync 190:INBOX - classified a chunk of new messages took 18s. 60/60MB memory used
[debug] partial sync 190:INBOX - persist new messages took 0s. 60/60MB memory used
[debug] partial sync 190:INBOX - get changed messages via Horde took 297s. 82/84MB memory used
[debug] partial sync 190:INBOX - persist changed messages took 2s. 82/85MB memory used
[debug] partial sync 190:INBOX - get vanished messages via Horde took 0s. 79/85MB memory used
[debug] partial sync 190:INBOX - delete vanished messages took 0s. 79/85MB memory used
[debug] partial sync 190:INBOX took 321s
[debug] Unlocking mailbox 12559 from vanished messages sync
[debug] Unlocking mailbox 12559 from changed messages sync
[debug] Unlocking mailbox 12559 from new messages sync
[debug] Skipping mailbox sync for 12570
[debug] Skipping mailbox sync for 12571
[debug] Skipping mailbox sync for 12572
[debug] Skipping mailbox sync for 12573
[debug] Skipping mailbox sync for 12574
[debug] Skipping mailbox sync for 12575
[debug] Skipping mailbox sync for 12576
[debug] Skipping mailbox sync for 12567
[debug] Skipping mailbox sync for 12568
[debug] Building threads for account 190
[debug] Account 190 has 2643 messages with threading information
[debug] Threading 2643 messages - build ID table took 0s. 82/85MB memory used
[debug] Threading 2643 messages - build root container took 0s. 82/85MB memory used
[debug] Threading 2643 messages - free ID table took 0s. 82/85MB memory used
[debug] Threading 2643 messages - prune containers took 0s. 82/85MB memory used
[debug] Threading 2643 messages - group by subject took 0s. 82/85MB memory used
[debug] Threading 2643 messages took 0s
[debug] Account 190 has 2306 threads
[debug] Account 190 has 4 messages with a new thread IDs
[debug] Chunk of 500 messages updated
84MB of memory used

**real    5m32,460s**
user    0m9,327s
sys     0m6,006s

5m32s syncing a single mail account. Sync in thunderbird for this very same account is instantly done.

=> Multiple Nextcloud cronjobs are running together because of background mail syncing slowing them down... image

jiriks74 commented 6 months ago

I think that this is being worked on in #7770

ChristophWurst commented 6 months ago

[debug] partial sync 190:INBOX - get changed messages via Horde took 297s. 82/84MB memory used

the majority of time was spent on the IMAP connection. Are your IMAP server and Nextcloud server far apart?

https://github.com/nextcloud/mail/pull/9235 for the recent sync improvements. These have no effect on slow IMAP servers.

ChristophWurst commented 6 months ago

https://github.com/nextcloud/mail/pull/8453 could be an improvement for the slow IMAP server but we currently are not able to make it work.