chatmail
feat: fetch immediately after IDLE
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.
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.
Closing, see https://github.com/deltachat/deltachat-core-rust/issues/3783#issuecomment-2289601027
