msglist: Mark-as-read button takes a long time (batch-processing already-read messages)

[chrisbobbe]

In #test here on CZO, if I let there be just one unread message, then I tap the recently added "Mark 1 message as read" button (#364), it regularly takes 4 to 5 seconds for that single message to get marked as read.

It looks like the server is doing some work on (maybe just accessing) a large number of messages that are already read. Here is some console output, where you'll see response data from the mark-as-read requests, alternating with the corresponding mark-as-read events:

flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 6592, last_processed_id: 111506, found_oldest: true, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 349}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=349
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 111507, last_processed_id: 140521, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 350}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=350
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 140522, last_processed_id: 195418, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 351}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=351
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 195419, last_processed_id: 252425, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 352}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=352
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 252426, last_processed_id: 289615, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 353}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=353
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 289616, last_processed_id: 398144, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 354}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=354
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 398145, last_processed_id: 518465, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 355}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=355
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 518467, last_processed_id: 562938, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 356}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=356
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 562939, last_processed_id: 589484, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 357}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=357
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 589489, last_processed_id: 638377, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 358}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=358
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 638378, last_processed_id: 672835, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 359}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=359
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 672841, last_processed_id: 717066, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 360}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=360
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 717113, last_processed_id: 766626, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 361}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=361
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 766925, last_processed_id: 813760, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 362}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=362
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 813762, last_processed_id: 852617, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 363}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=363
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 852618, last_processed_id: 907987, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 364}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=364
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 907988, last_processed_id: 1003573, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 365}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=365
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1003584, last_processed_id: 1094351, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 366}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=366
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1094352, last_processed_id: 1140817, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 367}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=367
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1140818, last_processed_id: 1208730, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 368}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=368
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1208732, last_processed_id: 1273225, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 369}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=369
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1273371, last_processed_id: 1375173, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 370}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=370
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1375174, last_processed_id: 1474227, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 371}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=371
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1474228, last_processed_id: 1564493, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 372}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=372
flutter: {result: success, msg: , processed_count: 1000, updated_count: 0, first_processed_id: 1564497, last_processed_id: 1666108, found_oldest: false, found_newest: false}
flutter: POST https://chat.zulip.org/api/v1/messages/flags/narrow
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [], all: false, id: 373}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=373
flutter: {result: success, msg: , processed_count: 100, updated_count: 1, first_processed_id: 1666111, last_processed_id: 1680078, found_oldest: false, found_newest: true}
flutter: mark-as-read time: 4352ms
flutter: {type: update_message_flags, op: add, operation: add, flag: read, messages: [1680078], all: false, id: 374}
flutter: server event: update_message_flags/add read
flutter: GET https://chat.zulip.org/api/v1/events?queue_id=50c5a217-6f4b-45ce-bcfa-3888e2b3ba88&last_event_id=374

(It's odd there to see mark-as-read events where all is false and messages is empty. I don't think that case is acknowledged in the API doc.)

Note that in the request response, first_processed_id increases over lots of message IDs that are already read. This seems like work that could be avoided. I found that I can cut out all the unnecessary work by adding is: unread to the requested narrow, making the request take a short time, as expected:

diff --git lib/widgets/message_list.dart lib/widgets/message_list.dart
index 85806968e..de167ce4c 100644
--- lib/widgets/message_list.dart
+++ lib/widgets/message_list.dart
@@ -720,7 +720,7 @@ Future<void> markNarrowAsRead(BuildContext context, Narrow narrow) async {
     // search query and thus worth using as an optimization
     // when processing all messages.
     AllMessagesNarrow() => [ApiNarrowIsUnread()],
-    _                   => narrow.apiEncode(),
+    _                   => narrow.apiEncode()..add(ApiNarrowIsUnread()),
   };
   while (true) {
     final result = await updateMessageFlagsForNarrow(connection,

But this might be a case where the server shouldn't need the client to tell it to make that optimization, and it should just go ahead and make it.

(Same with the all-messages case; here's more of the code in main surrounding that diff, with a relevant comment:

  final apiNarrow = switch (narrow) {
    // Since there's a database index on is:unread, it's a fast
    // search query and thus worth using as an optimization
    // when processing all messages.
    AllMessagesNarrow() => [ApiNarrowIsUnread()],
    _                   => narrow.apiEncode(),
  };

.)

[gnprice]

Hmm, yeah, we should just always include is:unread. In web the only place that explicitly appears is when marking all messages as read… but that's also the only place it's using the new, general API. For marking a stream or topic as read, it's using the special endpoints for those.

And in the server implementation of those endpoints, the is:unread filter indeed gets included:

def do_mark_stream_messages_as_read(
    user_profile: UserProfile, stream_recipient_id: int, topic_name: Optional[str] = None
) -> int:
    with transaction.atomic(savepoint=False):
        query = (
            UserMessage.select_for_update_query()
            .filter(
                user_profile=user_profile,
                message__recipient_id=stream_recipient_id,
            )
            .extra(
                where=[UserMessage.where_unread()],
            )
        )

        if topic_name:
            query = filter_by_topic_name_via_message(
                query=query,
                topic_name=topic_name,
            )

(note the where_unread). So we should do the same.

This also makes the switch unnecessary; we can just unconditionally use narrow.apiEncode()..add(ApiNarrowIsUnread()).

It'd probably also be good for the server to notice when we're adding the "read" flag, and add the is:unread filter automatically. That'll be harmless if the client has already included it.