feat: fetch immediately after IDLE #4974

link2xt · 2023-11-10T03:33:17Z

hpk42

nice cleanup as far as i can tell.

Hocuri

Great that you digged this old issue up! My gut feeling is that we shouldn't merge a PR to such a sensitive area right before the release (plus, I did find one blocker for this PR so we can't merge it right away), but even if we don't it will be nice to get something like this in after the release!

src/imap/idle.rs

Hocuri · 2023-11-10T13:22:08Z

src/scheduler.rs

+    // Fetch the watched folder
+    // immediately after IDLE to reduce message delivery latency.
+    if let Err(err) = connection
+        .fetch_move_delete(ctx, &watch_folder, folder_meaning)
        .await
-        .context("idle")
+        .context("fetch_move_delete")
    {
-        Ok(session) => {
-            connection.session = Some(session);
-        }
-        Err(err) => {
-            connection.trigger_reconnect(ctx);
-            warn!(ctx, "{:#}", err);
-        }
+        connection.trigger_reconnect(ctx);
+        warn!(ctx, "{:#}", err);
    }
 }



A few lines above it says:

// Fetch the watched folder again in case scanning other folder moved messages // there. // // In most cases this will select the watched folder and return because there are // no new messages. We want to select the watched folder anyway before going IDLE // there, so this does not take additional protocol round-trip. [...] fetch_move_delete(...)

This can probably be removed if we fetch here.

Hocuri · 2023-11-10T13:30:31Z

src/scheduler.rs

-    // Fetch the watched folder.
-    if let Err(err) = connection
-        .fetch_move_delete(ctx, &watch_folder, folder_meaning)
-        .await
-        .context("fetch_move_delete")
-    {
-        connection.trigger_reconnect(ctx);
-        warn!(ctx, "{:#}", err);
-        return InterruptInfo::new(false);
-    }
-


Blocker: Some lines further down, it says:

// Scan additional folders only after finishing fetching the watched folder. // // On iOS the application has strictly limited time to work in background, so we may not // be able to scan all folders before time is up if there are many of them.

Now that fetch_mode_delete was moved down, it will be done after scanning, which will be a problem for iOS, then. Probably we need another fetch_move_delete() before the loops. In inbox_loop we then need to make sure that fetch_existing_msgs() (and possibly resync_folders(), I didn't look into it) is executed before fetch_move_delete(), which will need some additional logic.

link2xt · 2023-11-10T16:09:52Z

I moved refactoring out to #4977, will merge it then rebase this PR.
This one is not good enough for a stable release and may indeed make things worse for iOS.
For iOS we need a simple sync "fetch everything once" function #4420, then can do whatever we want in this loop.

link2xt · 2023-11-10T22:27:16Z

I measured with https://github.com/deltachat/pingpong, this does not have any measurable impact when running on a fast network, from b1 to nine.

TL;DR 90% of the time is spent waiting between sending a message over SMTP and the server waking up IDLE client. We should optimize the server, not the client.

With this PR (round trip time in seconds, sending a message to the bot and receiving a reply back, no encryption, no moving to DeltaChat folder):

min:    1.1270592212677
p05:    1.14483976364136
median: 1.16397380828857
p95:    1.18385410308838
max:    1.22627139091492

With 1.130.0 core:

min:    1.12097477912903
p05:    1.12548685073853
median: 1.14409327507019
p95:    1.20510101318359
max:    1.22065734863281

This is with <1ms RTT when running ping from b1 to nine, more like 0.5ms RTT.

This is how it goes in the logs:

2023-11-10 23:43:46,555 ping: Got an incoming message                        
28,32.81958556175232                                                                           
2023-11-10 23:43:46,562 ping: src/imap.rs:1572: Successfully received 1 UIDs.            
2023-11-10 23:43:46,563 ping: src/imap.rs:893: 1 mails read from "INBOX".                   
2023-11-10 23:43:46,564 ping: src/contact.rs:1739: Recently seen loop waiting for 0h 9m 29s or interrupt
2023-11-10 23:43:46,565 ping: src/scheduler.rs:611: IMAP session supports IDLE, using it.
2023-11-10 23:43:46,566 ping: src/imap/idle.rs:85: INBOX: Idle entering wait-on-remote state                                                                                                   
2023-11-10 23:43:46,566 ping: src/e2ee.rs:65: peerstate for "[email protected]" is nopreference
2023-11-10 23:43:46,567 ping: src/scheduler.rs:752: smtp fake idle - interrupted                                                                                                               
2023-11-10 23:43:46,568 ping: src/ephemeral.rs:567: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2023-11-10 23:43:46,569 ping: src/smtp.rs:652: Selected rows from SMTP queue: [29]. 
2023-11-10 23:43:46,570 ping: src/smtp.rs:565: Try number 1 to send message Msg#66 (entry 29) over SMTP
2023-11-10 23:43:46,571 ping: src/message.rs:1624: Seen message Msg#65.                    
2023-11-10 23:43:46,571 ping: src/imap/idle.rs:106: INBOX: Idle wait was interrupted     
2023-11-10 23:43:46,572 ping: src/imap.rs:893: 0 mails read from "INBOX".                   
2023-11-10 23:43:46,573 ping: src/imap.rs:1178: Marked messages 28 in folder INBOX as seen.                                                                                                    
2023-11-10 23:43:46,574 ping: src/scheduler.rs:611: IMAP session supports IDLE, using it.
2023-11-10 23:43:46,575 ping: src/imap/idle.rs:85: INBOX: Idle entering wait-on-remote state                                                                                                   
2023-11-10 23:43:46,598 ping: src/smtp/send.rs:70: Message len=1168 was SMTP-sent to [email protected].
2023-11-10 23:43:46,599 ping: src/scheduler.rs:726: smtp fake idle - started
2023-11-10 23:43:46,600 ping: src/scheduler.rs:748: smtp has no messages to retry, waiting for interrupt
2023-11-10 23:43:47,116 echo: src/imap/idle.rs:97: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(29)) }
2023-11-10 23:43:47,121 echo: src/imap.rs:1415: Starting a full FETCH of message set "29".
2023-11-10 23:43:47,127 echo: src/imap.rs:1533: Passing message UID 29 to receive_imf().                                                                                                       
2023-11-10 23:43:47,128 echo: src/receive_imf.rs:121: Receiving message, seen=false...
2023-11-10 23:43:47,129 echo: src/receive_imf.rs:160: Received message has Message-Id: [email protected]
2023-11-10 23:43:47,130 echo: src/receive_imf.rs:2255: Not creating ad-hoc group: too few contacts.
2023-11-10 23:43:47,130 echo: src/receive_imf.rs:1320: Message has 1 parts and is assigned to chat #Chat#10.
2023-11-10 23:43:47,130 echo: src/contact.rs:1739: Recently seen loop waiting for 0h 9m 27s or interrupt
2023-11-10 23:43:47,131 echo got an incoming message
2023-11-10 23:43:47,137 echo: src/imap.rs:1572: Successfully received 1 UIDs.
2023-11-10 23:43:47,138 echo: src/imap.rs:893: 1 mails read from "INBOX".
2023-11-10 23:43:47,139 echo: src/scheduler.rs:611: IMAP session supports IDLE, using it.
2023-11-10 23:43:47,139 echo: src/imap/idle.rs:85: INBOX: Idle entering wait-on-remote state
2023-11-10 23:43:47,140 echo: src/e2ee.rs:65: peerstate for "[email protected]" is nopreference
2023-11-10 23:43:47,140 echo: src/scheduler.rs:752: smtp fake idle - interrupted
2023-11-10 23:43:47,141 echo: src/ephemeral.rs:567: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2023-11-10 23:43:47,141 echo: src/smtp.rs:652: Selected rows from SMTP queue: [29].
2023-11-10 23:43:47,142 echo: src/smtp.rs:565: Try number 1 to send message Msg#67 (entry 29) over SMTP
2023-11-10 23:43:47,184 echo: src/smtp/send.rs:70: Message len=1168 was SMTP-sent to [email protected].
2023-11-10 23:43:47,185 echo: src/scheduler.rs:726: smtp fake idle - started
2023-11-10 23:43:47,186 echo: src/scheduler.rs:748: smtp has no messages to retry, waiting for interrupt
2023-11-10 23:43:47,701 ping: src/imap/idle.rs:97: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(29)) }
2023-11-10 23:43:47,706 ping: src/imap.rs:1415: Starting a full FETCH of message set "29".
2023-11-10 23:43:47,712 ping: src/imap.rs:1533: Passing message UID 29 to receive_imf().
2023-11-10 23:43:47,712 ping: src/receive_imf.rs:121: Receiving message, seen=false...
2023-11-10 23:43:47,713 ping: src/receive_imf.rs:160: Received message has Message-Id: [email protected]
2023-11-10 23:43:47,713 ping: src/receive_imf.rs:2255: Not creating ad-hoc group: too few contacts.
2023-11-10 23:43:47,713 ping: src/receive_imf.rs:1320: Message has 1 parts and is assigned to chat #Chat#10.
2023-11-10 23:43:47,714 ping: src/contact.rs:1739: Recently seen loop waiting for 0h 9m 28s or interrupt
2023-11-10 23:43:47,714 ping: Got an incoming message
29,33.97903847694397

The most interesting part is:

2023-11-10 23:43:46,600 ping: src/scheduler.rs:748: smtp has no messages to retry, waiting for interrupt
2023-11-10 23:43:47,116 echo: src/imap/idle.rs:97: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(29)) }

It took 47.116 - 46.600 = 0.516 seconds from the time ping process considers the mail to be SMTP-sent until echo process has IDLE interrupted. 2x this is 1.032, the rest is something like 10ms spent on the client for a whole RTT. Looks like we have to optimize the server, not the client.

Hocuri · 2024-08-14T18:55:30Z

Closing, see #3783 (comment)

link2xt mentioned this pull request Nov 10, 2023

Immediately fetch after EXISTS response #3783

Closed

3 tasks

link2xt force-pushed the link2xt/fetch-after-idle branch 2 times, most recently from 21cbe7e to 9e48f99 Compare November 10, 2023 05:16

link2xt requested review from iequidoo and Hocuri November 10, 2023 05:25

hpk42 approved these changes Nov 10, 2023

View reviewed changes

Hocuri reviewed Nov 10, 2023

View reviewed changes

link2xt force-pushed the link2xt/fetch-after-idle branch 2 times, most recently from 9e1128b to 5000b5a Compare November 10, 2023 16:07

link2xt mentioned this pull request Nov 10, 2023

IMAP refactoring #4977

Merged

link2xt force-pushed the link2xt/fetch-after-idle branch from 5000b5a to 2ca0ec2 Compare November 10, 2023 16:38

link2xt force-pushed the main branch 2 times, most recently from ca190eb to d7aecab Compare November 10, 2023 17:56

feat: fetch new messages immediately after IDLE to reduce delay

243317b

link2xt force-pushed the link2xt/fetch-after-idle branch from 2ca0ec2 to 243317b Compare November 10, 2023 19:31

link2xt marked this pull request as draft November 10, 2023 20:24

link2xt mentioned this pull request Nov 10, 2023

500 ms delay between sending a message over SMTP and getting IDLE notified chatmail/relay#72

Closed

link2xt force-pushed the main branch 2 times, most recently from 1abb12e to 2af9ff1 Compare March 4, 2024 21:10

Hocuri closed this Aug 14, 2024

Hocuri deleted the link2xt/fetch-after-idle branch August 15, 2024 16:39

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

feat: fetch immediately after IDLE #4974

feat: fetch immediately after IDLE #4974

Uh oh!

link2xt commented Nov 10, 2023 •

edited

Loading

Uh oh!

hpk42 left a comment

Uh oh!

Hocuri left a comment •

edited

Loading

Uh oh!

Uh oh!

Hocuri Nov 10, 2023

Uh oh!

Hocuri Nov 10, 2023 •

edited

Loading

Uh oh!

link2xt commented Nov 10, 2023 •

edited

Loading

Uh oh!

link2xt commented Nov 10, 2023 •

edited

Loading

Uh oh!

Hocuri commented Aug 14, 2024

Uh oh!

Uh oh!

Uh oh!

feat: fetch immediately after IDLE #4974

feat: fetch immediately after IDLE #4974

Uh oh!

Conversation

link2xt commented Nov 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

hpk42 left a comment

Choose a reason for hiding this comment

Uh oh!

Hocuri left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Hocuri Nov 10, 2023

Choose a reason for hiding this comment

Uh oh!

Hocuri Nov 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

link2xt commented Nov 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

link2xt commented Nov 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Hocuri commented Aug 14, 2024

Uh oh!

Uh oh!

link2xt commented Nov 10, 2023 •

edited

Loading

Hocuri left a comment •

edited

Loading

Hocuri Nov 10, 2023 •

edited

Loading

link2xt commented Nov 10, 2023 •

edited

Loading

link2xt commented Nov 10, 2023 •

edited

Loading