Merge pull request #1228 from matrix-org/hs/debounce-improvements

Debounce performance improvements

changelog.d/1228.bugfix

@@ -0,0 +1 @@
+Fix an issue where the QuitDebouncer would reprocess old QUITs, and process QUITs too early during the debouncing process.

src/bridge/QuitDebouncer.ts

@@ -1,6 +1,5 @@
 import { IrcServer } from "../irc/IrcServer";
 import Log from "../logging";
-import { Queue } from "../util/Queue";
 
 const log = Log("QuitDebouncer");
 
@@ -11,19 +10,19 @@ export class QuitDebouncer {
         [domain: string]: {
             quitTimestampsMs: number[];
             splitChannelUsers: Map<string, Set<string>>; //"$channel $nick"
+            existingTimeouts: Set<string>; // Existing channel timeouts
         };
     };
 
-    private quitProcessQueue: Queue<{channel: string; server: IrcServer}>;
+    private wasSplitOccuring = false;
 
     constructor(
         servers: IrcServer[],
-        private handleQuit: (item: {channel: string; server: IrcServer}) => Promise<void>) {
+        private handleQuit: (channel: string, server: IrcServer, nicks: string[]) => Promise<void>) {
         // Measure the probability of a net-split having just happened using QUIT frequency.
         // This is to smooth incoming PART spam from IRC clients that suffer from a
         // net-split (or other issues that lead to mass PART-ings)
         this.debouncerForServer = {};
-        this.quitProcessQueue = new Queue(this.handleQuit);
 
         // Keep a track of the times at which debounceQuit was called, and use this to
         // determine the rate at which quits are being received. This can then be used
@@ -32,6 +31,7 @@ export class QuitDebouncer {
             this.debouncerForServer[domain] = {
                 quitTimestampsMs: [],
                 splitChannelUsers: new Map(),
+                existingTimeouts: new Set(),
             };
         });
     }
@@ -43,31 +43,47 @@ export class QuitDebouncer {
      * @param {IrcServer} server The sending IRC server.
      */
     public onJoin(nick: string, channel: string, server: IrcServer) {
-        if (!this.debouncerForServer[server.domain]) {
+        const debouncer = this.debouncerForServer[server.domain];
+        if (!debouncer) {
             return;
         }
-        const set = this.debouncerForServer[server.domain].splitChannelUsers.get(channel);
+        const set = debouncer.splitChannelUsers.get(channel);
         if (!set) {
+            // We are either not debouncing, or this channel has been handled already.
             return;
         }
         set.delete(nick);
-
+        if (debouncer.existingTimeouts.has(channel)) {
+            // We are already handling this one.
+            return;
+        }
         if (set.size === 0) {
+            // Nobody to debounce, yay.
             return;
         }
-        this.quitProcessQueue.enqueue(channel+server.domain, {channel, server});
+        const delay = Math.max(server.getQuitDebounceDelayMinMs(), server.getQuitDebounceDelayMaxMs() * Math.random());
+        log.info(`Will attempt to reconnect users for ${channel} after ${delay}ms`)
+        setTimeout(() => {
+            // Clear our existing sets, we're about to operate on the channel.
+            const nicks = this.getQuitNicksForChannel(channel, server);
+            debouncer.splitChannelUsers.delete(channel);
+            debouncer.existingTimeouts.delete(channel);
+            this.handleQuit(channel, server, nicks);
+        }, delay);
+        debouncer.existingTimeouts.add(channel);
     }
 
     /**
      * Get a list of nicknames that have been QUIT from a channel.
      * @param channel The IRC channel
      * @param server The IRC server
      */
-    public getQuitNicksForChannel(channel: string, server: IrcServer) {
+    private getQuitNicksForChannel(channel: string, server: IrcServer) {
         // A little hint on iterators here:
         // You can return values() (an IterableIterator<string>) and if the Set gets modified,
         // the iterator will skip the value that was deleted.
-        return this.debouncerForServer[server.domain].splitChannelUsers.get(channel)?.values() || [];
+        const nicks = this.debouncerForServer[server.domain].splitChannelUsers.get(channel)?.values();
+        return nicks ? [...nicks] : [];
     }
 
     /**
@@ -104,8 +120,13 @@ export class QuitDebouncer {
         // We don't want to debounce users that are quiting legitimately so return early, and
         // we do want to make their virtual matrix user leave the room, so return true.
         if (!isSplitOccuring) {
+            this.wasSplitOccuring = isSplitOccuring;
             return true;
         }
+        else if (isSplitOccuring !== this.wasSplitOccuring) {
+            log.warn(`A netsplit is occuring: debouncing QUITs`)
+            this.wasSplitOccuring = true;
+        }
 
         log.debug(`Dropping QUIT for ${nick}`);
         channels.forEach((channel) => {

src/irc/IrcEventBroker.ts

@@ -210,13 +210,20 @@ export class IrcEventBroker {
     /**
      * This function is called when the quit debouncer has deemed it safe to start sending
      * quits from users who were debounced.
-     * @param item The channel/server pair to send QUITs from
+     * @param channel The channel to handle QUITs for.
+     * @param server The channels server.
+     * @param nicks The set of nicks for the channel.
      */
-    private async handleDebouncedQuit(item: {channel: string; server: IrcServer}) {
+    private async handleDebouncedQuit(channel: string, server: IrcServer, nicks: string[]) {
+        log.info(`Sending delayed QUITs for ${channel} (${nicks.length} nicks)`);
+        if (nicks.length === 0) {
+            return;
+        }
         const createUser = (nick: string) => {
             return new IrcUser(
-                item.server, nick,
-                this.pool.nickIsVirtual(item.server, nick)
+                server,
+                nick,
+                this.pool.nickIsVirtual(server, nick)
             );
         };
 
@@ -229,11 +236,14 @@ export class IrcEventBroker {
                 })
             );
         };
-        const req = createRequest();
-        log.info(`Sending delayed QUITs for ${item.channel}`);
-        for (const nick of this.quitDebouncer.getQuitNicksForChannel(item.channel, item.server)) {
+        for (const nick of nicks) {
+            const req = createRequest();
             await complete(req, this.ircHandler.onPart(
-                req, item.server, createUser(nick), item.channel, "quit"
+                req,
+                server,
+                createUser(nick),
+                channel,
+                "quit"
             ));
         }
     }

src/irc/Scheduler.ts

@@ -66,12 +66,12 @@ export default {
             } as QueueItem
         );
 
-        log.info(
+        log.debug(
             `Queued scheduled promise for ${server.domain} ${nick}` +
             (addedDelayMs > 0 ? ` with ${Math.round(addedDelayMs)}ms added delay`:'')
         );
 
-        log.info(
+        log.debug(
             `Queue for ${server.domain} length = ${q.size()}`
         );