Bug 1764501 - [devtools] Speedup adding messages out of order. r=ochameau.
authorNicolas Chevobbe <nchevobbe@mozilla.com>
Wed, 15 Jun 2022 12:57:07 +0000
changeset 620994 c678f72199826ead4f936cf173b32ba216618a24
parent 620993 657af115a0b736c258f062ed78b2a02e12196ea0
child 620995 1a2b8a3c8055176bd4d681efd819072ecf8247b9
push id164596
push usernchevobbe@mozilla.com
push dateWed, 15 Jun 2022 12:59:48 +0000
treeherderautoland@034347a53a02 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersochameau
bugs1764501
milestone103.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1764501 - [devtools] Speedup adding messages out of order. r=ochameau. In the console we might receive messages that need to be inserted at a specific position in the output to respect the chronological order. This is very visible when evaluating an expression in the console while we are fetching cached messages, or when the expression is logging lots of messages, since the evaluation result doesn't go through the ResourceCommand itself. Since we were relying on the order of insertion in `mutableMessagesById` for the order of messages in the output, we had no choice but clone the Map to insert the new message at the specific position. With lots of messages, this can be utterly slow, and is something people are experiencing. To fix this, we're adding a new state property, `mutableMessagesOrder`, which holds message ids in the chronological order. It's then used to compute `visibleMessages`. As we don't have to clone the Map anymore, it makes reordering as fast as looking for an index in the array and splicing it (which is fast). We also take this opportunity to switch away from our `findIndex` usage; most often than not, the messages will be reinserted at the end of the array, so we can loop through it backward to find the index faster. We still keep `mutableMessagesById` as a Map so lookup are fast, and we don't have to deal with impacts we'd have if we'd switch to an object. The existing node test helper to get a message at a specific index are migrated to make use of `mutableMessagesOrder`, and a few test cases and assertions are added to check that the new property is handled correctly. Differential Revision: https://phabricator.services.mozilla.com/D148658
devtools/client/webconsole/reducers/messages.js
devtools/client/webconsole/test/node/helpers.js
devtools/client/webconsole/test/node/store/messages.test.js
--- a/devtools/client/webconsole/reducers/messages.js
+++ b/devtools/client/webconsole/reducers/messages.js
@@ -53,16 +53,21 @@ const {
 
 const MessageState = overrides =>
   Object.freeze(
     Object.assign(
       {
         // List of all the messages added to the console. Unlike other properties, this Map
         // will be mutated on state changes for performance reasons.
         mutableMessagesById: new Map(),
+        // Array of message ids, in chronological order. We use a dedicated property to store
+        // the order (instead of relying on the order of insertion in mutableMessagesById)
+        // as we might receive messages that need to be inserted at a specific index. Doing
+        // so on the Map can be costly, especially when the Map holds lots of messages.
+        mutableMessagesOrder: [],
         // List of elements matching the selector of CSS Warning messages(populated
         // on-demand via the UI).
         cssMessagesMatchingElements: new Map(),
         // Array of the visible messages.
         visibleMessages: [],
         // Object for the filtered messages.
         filteredMessagesCount: getDefaultFiltersCounter(),
         // List of the message ids which are opened.
@@ -98,16 +103,17 @@ function cloneState(state) {
     cssMessagesMatchingElements: new Map(state.cssMessagesMatchingElements),
     groupsById: new Map(state.groupsById),
     frontsToRelease: [...state.frontsToRelease],
     repeatById: { ...state.repeatById },
     networkMessagesUpdateById: { ...state.networkMessagesUpdateById },
     warningGroupsById: new Map(state.warningGroupsById),
     // no need to mutate the properties below as they're not directly triggering re-render
     mutableMessagesById: state.mutableMessagesById,
+    mutableMessagesOrder: state.mutableMessagesOrder,
     currentGroup: state.currentGroup,
     lastMessageId: state.lastMessageId,
   };
 }
 
 /**
  * Add a console message to the state.
  *
@@ -256,31 +262,35 @@ function addMessage(newMessage, state, f
     state.warningGroupsById.set(newMessage.id, []);
   }
 
   const addedMessage = Object.freeze(newMessage);
 
   // If the new message isn't the "oldest" one, then we need to insert it at the right
   // position in the message map.
   if (isUnsorted) {
-    const entries = Array.from(state.mutableMessagesById.entries());
-    const newMessageIndex = entries.findIndex(
-      entry => entry[1].timeStamp > addedMessage.timeStamp
-    );
-    // This shouldn't happen as `isUnsorted` would only be true if the last message is
-    // younger than the added message.
-    if (newMessageIndex === -1) {
-      state.mutableMessagesById.set(addedMessage.id, addedMessage);
-    } else {
-      entries.splice(newMessageIndex, 0, [addedMessage.id, addedMessage]);
-      state.mutableMessagesById = new Map(entries);
+    let newMessageIndex = 0;
+    // This is can be on a hot path, so we're not using `findIndex`, which could be slow.
+    // Furthermore, there's a high chance the message beed to be inserted somewhere at the
+    // end of the list, so we loop through mutableMessagesOrder in reverse order.
+    for (let i = state.mutableMessagesOrder.length - 1; i >= 0; i--) {
+      const message = state.mutableMessagesById.get(
+        state.mutableMessagesOrder[i]
+      );
+      if (message.timeStamp <= addedMessage.timeStamp) {
+        newMessageIndex = i + 1;
+        break;
+      }
     }
+
+    state.mutableMessagesOrder.splice(newMessageIndex, 0, addedMessage.id);
   } else {
-    state.mutableMessagesById.set(addedMessage.id, addedMessage);
+    state.mutableMessagesOrder.push(addedMessage.id);
   }
+  state.mutableMessagesById.set(addedMessage.id, addedMessage);
 
   if (newMessage.type === "trace") {
     // We want the stacktrace to be open by default.
     state.messagesUiById.push(newMessage.id);
   } else if (isGroupType(newMessage.type)) {
     state.currentGroup = newMessage.id;
     state.groupsById.set(newMessage.id, parentGroups);
 
@@ -317,26 +327,30 @@ function addMessage(newMessage, state, f
           break;
         }
       }
       // Inserts the new warning message at the wanted location "in" the warning group.
       state.visibleMessages.splice(index + 1, 0, newMessage.id);
     } else if (isUnsorted) {
       // If the new message wasn't the "oldest" one, then we need to insert its id at
       // the right position in the array.
-      const index = state.visibleMessages.findIndex(
-        id => state.mutableMessagesById.get(id).timeStamp > newMessage.timeStamp
-      );
-      // If the index wasn't found, it means the new message is the oldest of the visible
-      // messages, so we can directly push it into the array.
-      if (index == -1) {
-        state.visibleMessages.push(newMessage.id);
-      } else {
-        state.visibleMessages.splice(index, 0, newMessage.id);
+      // This is can be on a hot path, so we're not using `findIndex`, which could be slow.
+      // Furthermore, there's a high chance the message beed to be inserted somewhere at the
+      // end of the list, so we loop through visibleMessages in reverse order.
+      let index = 0;
+      for (let i = state.visibleMessages.length - 1; i >= 0; i--) {
+        const id = state.visibleMessages[i];
+        if (
+          state.mutableMessagesById.get(id).timeStamp <= newMessage.timeStamp
+        ) {
+          index = i + 1;
+          break;
+        }
       }
+      state.visibleMessages.splice(index, 0, newMessage.id);
     } else {
       state.visibleMessages.push(newMessage.id);
     }
     maybeSortVisibleMessages(state, false);
   } else if (DEFAULT_FILTERS.includes(cause)) {
     state.filteredMessagesCount.global++;
     state.filteredMessagesCount[cause]++;
   }
@@ -460,17 +474,18 @@ function messages(
       const openState = { ...state };
       openState.messagesUiById = [...messagesUiById, action.id];
       const currMessage = mutableMessagesById.get(action.id);
 
       // If the message is a console.group/groupCollapsed or a warning group.
       if (isGroupType(currMessage.type) || isWarningGroup(currMessage)) {
         // We want to make its children visible
         const messagesToShow = [];
-        for (const [id, message] of mutableMessagesById) {
+        for (const id of state.mutableMessagesOrder) {
+          const message = mutableMessagesById.get(id);
           if (
             !visibleMessages.includes(message.id) &&
             ((isWarningGroup(currMessage) && !!getWarningGroupType(message)) ||
               (isGroupType(currMessage.type) &&
                 getParentGroups(message.groupId, groupsById).includes(
                   action.id
                 ))) &&
             getMessageVisibility(message, {
@@ -626,17 +641,18 @@ function messages(
     case constants.WARNING_GROUPS_TOGGLE:
       // There's no warningGroups, and the pref was set to false,
       // we don't need to do anything.
       if (!prefsState.groupWarnings && state.warningGroupsById.size === 0) {
         return state;
       }
 
       let needSort = false;
-      for (const [msgId, message] of state.mutableMessagesById) {
+      for (const msgId of state.mutableMessagesOrder) {
+        const message = state.mutableMessagesById.get(msgId);
         const warningGroupType = getWarningGroupType(message);
         if (warningGroupType) {
           const warningGroupMessageId = getParentWarningGroupMessageId(message);
 
           // If there's no warning group for the type/innerWindowID yet.
           if (!state.mutableMessagesById.has(warningGroupMessageId)) {
             // We create it and add it to the store.
             const groupMessage = createWarningGroupMessage(
@@ -709,25 +725,27 @@ function setVisibleMessages({
   messagesState,
   filtersState,
   prefsState,
   uiState,
   forceTimestampSort = false,
 }) {
   const {
     mutableMessagesById,
+    mutableMessagesOrder,
     visibleMessages,
     messagesUiById,
   } = messagesState;
 
   const messagesToShow = new Set();
   const matchedGroups = new Set();
   const filtered = getDefaultFiltersCounter();
 
-  mutableMessagesById.forEach((message, msgId) => {
+  mutableMessagesOrder.forEach(msgId => {
+    const message = mutableMessagesById.get(msgId);
     const groupParentId = message.groupId;
     let hasMatchedAncestor = false;
     const ancestors = [];
 
     if (groupParentId) {
       let ancestorId = groupParentId;
 
       // we track the message's ancestors and their state
@@ -872,17 +890,18 @@ function limitTopLevelMessageCount(newSt
 
   if (topLevelCount <= logLimit) {
     return newState;
   }
 
   const removedMessagesId = [];
 
   let cleaningGroup = false;
-  for (const [id, message] of newState.mutableMessagesById) {
+  for (const id of newState.mutableMessagesOrder) {
+    const message = newState.mutableMessagesById.get(id);
     // If we were cleaning a group and the current message does not have
     // a groupId, we're done cleaning.
     if (cleaningGroup === true && !message.groupId) {
       cleaningGroup = false;
     }
 
     // If we're not cleaning a group and the message count is below the logLimit,
     // we exit the loop.
@@ -957,17 +976,23 @@ function removeMessagesFromState(state, 
   const cleanUpObject = object =>
     [...Object.entries(object)].reduce((res, [id, value]) => {
       if (!isInRemovedId(id)) {
         res[id] = value;
       }
       return res;
     }, {});
 
-  removedMessagesIds.forEach(id => state.mutableMessagesById.delete(id));
+  removedMessagesIds.forEach(id => {
+    state.mutableMessagesById.delete(id);
+    state.mutableMessagesOrder.splice(
+      state.mutableMessagesOrder.indexOf(id),
+      1
+    );
+  });
 
   if (state.messagesUiById.find(isInRemovedId)) {
     state.messagesUiById = state.messagesUiById.filter(
       id => !isInRemovedId(id)
     );
   }
 
   if (isInRemovedId(state.currentGroup)) {
--- a/devtools/client/webconsole/test/node/helpers.js
+++ b/devtools/client/webconsole/test/node/helpers.js
@@ -76,18 +76,18 @@ function clonePacket(packet) {
 /**
  * Return the message in the store at the given index.
  *
  * @param {object} state - The redux state of the console.
  * @param {int} index - The index of the message in the map.
  * @return {Message} - The message, or undefined if the index does not exists in the map.
  */
 function getMessageAt(state, index) {
-  const messages = getMutableMessagesById(state);
-  return messages.get([...messages.keys()][index]);
+  const messageMap = getMutableMessagesById(state);
+  return messageMap.get(state.messages.mutableMessagesOrder[index]);
 }
 
 /**
  * Return the first message in the store.
  *
  * @param {object} state - The redux state of the console.
  * @return {Message} - The last message, or undefined if there are no message in store.
  */
@@ -97,17 +97,17 @@ function getFirstMessage(state) {
 
 /**
  * Return the last message in the store.
  *
  * @param {object} state - The redux state of the console.
  * @return {Message} - The last message, or undefined if there are no message in store.
  */
 function getLastMessage(state) {
-  const lastIndex = getMutableMessagesById(state).size - 1;
+  const lastIndex = state.messages.mutableMessagesOrder.length - 1;
   return getMessageAt(state, lastIndex);
 }
 
 function getFiltersPrefs() {
   return Object.values(PREFS.FILTER).reduce((res, pref) => {
     res[pref] = prefsService.getBoolPref(pref);
     return res;
   }, {});
--- a/devtools/client/webconsole/test/node/store/messages.test.js
+++ b/devtools/client/webconsole/test/node/store/messages.test.js
@@ -315,16 +315,17 @@ describe("Message reducer:", () => {
       const state = getState();
       expect(getMutableMessagesById(state).size).toBe(0);
       expect(getVisibleMessages(state).length).toBe(0);
       expect(getAllMessagesUiById(state).length).toBe(0);
       expect(getGroupsById(state).size).toBe(0);
       expect(getAllCssMessagesMatchingElements(state).size).toBe(0);
       expect(getCurrentGroup(state)).toBe(null);
       expect(getAllRepeatById(state)).toEqual({});
+      expect(state.messages.mutableMessagesOrder).toEqual([]);
     });
 
     it("cleans the repeatsById object when messages are pruned", () => {
       const { dispatch, getState } = setupStore(
         [
           "console.log('foobar', 'test')",
           "console.log('foobar', 'test')",
           "console.log(undefined)",
@@ -378,16 +379,19 @@ describe("Message reducer:", () => {
       }
 
       const messages = getMutableMessagesById(getState());
       expect(messages.size).toBe(logLimit);
       expect(getFirstMessage(getState()).parameters[0]).toBe(`message num 3`);
       expect(getLastMessage(getState()).parameters[0]).toBe(
         `message num ${logLimit + 2}`
       );
+
+      const { mutableMessagesOrder } = getState().messages;
+      expect(mutableMessagesOrder.length).toBe(logLimit);
     });
 
     it("properly limits number of messages when there are nested groups", () => {
       const logLimit = 1000;
       const { dispatch, getState } = setupStore([], {
         storeOptions: {
           logLimit,
         },
@@ -416,19 +420,22 @@ describe("Message reducer:", () => {
 
       for (let i = 0; i < logLimit; i++) {
         packet.message.arguments = [`message-${i}`];
         dispatch(actions.messagesAdd([packet]));
       }
 
       const visibleMessages = getVisibleMessages(getState());
       const messages = getMutableMessagesById(getState());
+      const { mutableMessagesOrder } = getState().messages;
 
       expect(messages.size).toBe(logLimit);
       expect(visibleMessages.length).toBe(logLimit);
+      expect(mutableMessagesOrder.length).toBe(logLimit);
+
       expect(messages.get(visibleMessages[0]).parameters[0]).toBe(`message-0`);
       expect(messages.get(visibleMessages[logLimit - 1]).parameters[0]).toBe(
         `message-${logLimit - 1}`
       );
 
       // The groups were cleaned up.
       const groups = getGroupsById(getState());
       expect(groups.size).toBe(0);
@@ -643,16 +650,83 @@ describe("Message reducer:", () => {
       delete packet.message.counter;
 
       dispatch(actions.messagesAdd([packet]));
       // The message should not be added to the state.
       expect(getMutableMessagesById(getState()).size).toBe(0);
     });
   });
 
+  describe("mutableMessagesOrder", () => {
+    it("adds a message to an empty store", () => {
+      const { dispatch, getState } = setupStore();
+
+      const packet = stubPackets.get("console.log('foobar', 'test')");
+      dispatch(actions.messagesAdd([packet]));
+
+      const { mutableMessagesOrder } = getState().messages;
+      expect(mutableMessagesOrder.length).toBe(1);
+      expect(mutableMessagesOrder[0]).toBe(
+        // Don't get getMessageIndexAt/getFirstMessage since it relies on mutableMessagesOrder
+        [...getMutableMessagesById(getState()).keys()][0]
+      );
+    });
+
+    it("reorder messages", () => {
+      const { dispatch, getState } = setupStore();
+
+      const naNpacket = stubPackets.get("console.log(NaN)");
+      dispatch(actions.messagesAdd([naNpacket]));
+
+      // Add a message that has a shorter timestamp than the previous one, and thus, should
+      // be displayed before
+      const nullPacket = clonePacket(stubPackets.get("console.log(null)"));
+      nullPacket.message.timeStamp = naNpacket.message.timeStamp - 10;
+      dispatch(actions.messagesAdd([nullPacket]));
+
+      // Add a message that should be display between the 2 previous messages
+      const undefinedPacket = clonePacket(
+        stubPackets.get("console.log(undefined)")
+      );
+      undefinedPacket.message.timeStamp = naNpacket.message.timeStamp - 5;
+      dispatch(actions.messagesAdd([undefinedPacket]));
+
+      const { mutableMessagesOrder } = getState().messages;
+      const [nanMessage, nullMessage, undefinedMessage] = [
+        ...getMutableMessagesById(getState()).values(),
+      ];
+      const visibleMessages = getVisibleMessages(getState());
+
+      // Checking that messages in the Map are the expected ones
+      expect(nanMessage.parameters[0].type).toBe("NaN");
+      expect(nullMessage.parameters[0].type).toBe("null");
+      expect(undefinedMessage.parameters[0].type).toBe("undefined");
+
+      // Check that mutableMessagesOrder has the message ids in the chronological order
+      expect(mutableMessagesOrder).toEqual([
+        nullMessage.id,
+        undefinedMessage.id,
+        nanMessage.id,
+      ]);
+
+      // Since we didn't filtered anything, visibleMessages should be similar to mutableMessagesOrder
+      expect(mutableMessagesOrder).toEqual(visibleMessages);
+
+      // Check that visibleMessages is computed from mutableMessagesOrder when filtering
+      dispatch(actions.filterToggle("log"));
+      expect(getVisibleMessages(getState())).toEqual([]);
+      dispatch(actions.filterToggle("log"));
+      expect(getVisibleMessages(getState())).toEqual([
+        nullMessage.id,
+        undefinedMessage.id,
+        nanMessage.id,
+      ]);
+    });
+  });
+
   describe("expandedMessageIds", () => {
     it("opens console.trace messages when they are added", () => {
       const { dispatch, getState } = setupStore();
 
       const message = stubPackets.get("console.trace()");
       dispatch(actions.messagesAdd([message]));
 
       const expanded = getAllMessagesUiById(getState());
@@ -1152,18 +1226,20 @@ describe("Message reducer:", () => {
 
       let expanded = getAllMessagesUiById(getState());
       expect(expanded.length).toBe(2);
 
       const secondTraceMessage = getMessageAt(getState(), 2);
       dispatch(actions.messageRemove(secondTraceMessage.id));
 
       const messages = getMutableMessagesById(getState());
+      const { mutableMessagesOrder } = getState().messages;
       // The messages was removed
       expect(messages.size).toBe(3);
+      expect(mutableMessagesOrder.length).toBe(3);
 
       // Its id was removed from the messagesUI property as well
       expanded = getAllMessagesUiById(getState());
       expect(expanded.length).toBe(1);
       expect(expanded.includes(secondTraceMessage.id)).toBeFalsy();
     });
   });
 });