diff options
| -rw-r--r-- | changelog.d/4890.feature | 1 | ||||
| -rw-r--r-- | docs/sample_config.yaml | 8 | ||||
| -rw-r--r-- | synapse/config/ratelimiting.py | 12 | ||||
| -rw-r--r-- | synapse/federation/sender/__init__.py | 115 | ||||
| -rw-r--r-- | synapse/federation/sender/per_destination_queue.py | 64 | ||||
| -rw-r--r-- | synapse/handlers/receipts.py | 2 | ||||
| -rw-r--r-- | tests/federation/test_federation_sender.py | 128 |
7 files changed, 308 insertions, 22 deletions
diff --git a/changelog.d/4890.feature b/changelog.d/4890.feature new file mode 100644 index 0000000000..8d74262250 --- /dev/null +++ b/changelog.d/4890.feature @@ -0,0 +1 @@ +Batch up outgoing read-receipts to reduce federation traffic. diff --git a/docs/sample_config.yaml b/docs/sample_config.yaml index f9886a900d..d72b90a37b 100644 --- a/docs/sample_config.yaml +++ b/docs/sample_config.yaml @@ -438,6 +438,14 @@ log_config: "CONFDIR/SERVERNAME.log.config" # #federation_rc_concurrent: 3 +# Target outgoing federation transaction frequency for sending read-receipts, +# per-room. +# +# If we end up trying to send out more read-receipts, they will get buffered up +# into fewer transactions. +# +#federation_rr_transactions_per_room_per_second: 50 + # Directory where uploaded images and attachments are stored. diff --git a/synapse/config/ratelimiting.py b/synapse/config/ratelimiting.py index 898a19dd8c..5a68399e63 100644 --- a/synapse/config/ratelimiting.py +++ b/synapse/config/ratelimiting.py @@ -42,6 +42,10 @@ class RatelimitConfig(Config): self.federation_rc_reject_limit = config.get("federation_rc_reject_limit", 50) self.federation_rc_concurrent = config.get("federation_rc_concurrent", 3) + self.federation_rr_transactions_per_room_per_second = config.get( + "federation_rr_transactions_per_room_per_second", 50, + ) + def default_config(self, **kwargs): return """\ ## Ratelimiting ## @@ -111,4 +115,12 @@ class RatelimitConfig(Config): # single server # #federation_rc_concurrent: 3 + + # Target outgoing federation transaction frequency for sending read-receipts, + # per-room. + # + # If we end up trying to send out more read-receipts, they will get buffered up + # into fewer transactions. + # + #federation_rr_transactions_per_room_per_second: 50 """ diff --git a/synapse/federation/sender/__init__.py b/synapse/federation/sender/__init__.py index 1bcc353d18..1dc041752b 100644 --- a/synapse/federation/sender/__init__.py +++ b/synapse/federation/sender/__init__.py @@ -104,7 +104,26 @@ class FederationSender(object): self._processing_pending_presence = False + # map from room_id to a set of PerDestinationQueues which we believe are + # awaiting a call to flush_read_receipts_for_room. The presence of an entry + # here for a given room means that we are rate-limiting RR flushes to that room, + # and that there is a pending call to _flush_rrs_for_room in the system. + self._queues_awaiting_rr_flush_by_room = { + } # type: dict[str, set[PerDestinationQueue]] + + self._rr_txn_interval_per_room_ms = ( + 1000.0 / hs.get_config().federation_rr_transactions_per_room_per_second + ) + def _get_per_destination_queue(self, destination): + """Get or create a PerDestinationQueue for the given destination + + Args: + destination (str): server_name of remote server + + Returns: + PerDestinationQueue + """ queue = self._per_destination_queues.get(destination) if not queue: queue = PerDestinationQueue(self.hs, self._transaction_manager, destination) @@ -250,33 +269,91 @@ class FederationSender(object): Args: receipt (synapse.types.ReadReceipt): receipt to be sent """ + + # Some background on the rate-limiting going on here. + # + # It turns out that if we attempt to send out RRs as soon as we get them from + # a client, then we end up trying to do several hundred Hz of federation + # transactions. (The number of transactions scales as O(N^2) on the size of a + # room, since in a large room we have both more RRs coming in, and more servers + # to send them to.) + # + # This leads to a lot of CPU load, and we end up getting behind. The solution + # currently adopted is as follows: + # + # The first receipt in a given room is sent out immediately, at time T0. Any + # further receipts are, in theory, batched up for N seconds, where N is calculated + # based on the number of servers in the room to achieve a transaction frequency + # of around 50Hz. So, for example, if there were 100 servers in the room, then + # N would be 100 / 50Hz = 2 seconds. + # + # Then, after T+N, we flush out any receipts that have accumulated, and restart + # the timer to flush out more receipts at T+2N, etc. If no receipts accumulate, + # we stop the cycle and go back to the start. + # + # However, in practice, it is often possible to flush out receipts earlier: in + # particular, if we are sending a transaction to a given server anyway (for + # example, because we have a PDU or a RR in another room to send), then we may + # as well send out all of the pending RRs for that server. So it may be that + # by the time we get to T+N, we don't actually have any RRs left to send out. + # Nevertheless we continue to buffer up RRs for the room in question until we + # reach the point that no RRs arrive between timer ticks. + # + # For even more background, see https://github.com/matrix-org/synapse/issues/4730. + + room_id = receipt.room_id + # Work out which remote servers should be poked and poke them. - domains = yield self.state.get_current_hosts_in_room(receipt.room_id) + domains = yield self.state.get_current_hosts_in_room(room_id) domains = [d for d in domains if d != self.server_name] if not domains: return - logger.debug("Sending receipt to: %r", domains) + queues_pending_flush = self._queues_awaiting_rr_flush_by_room.get( + room_id + ) - content = { - receipt.room_id: { - receipt.receipt_type: { - receipt.user_id: { - "event_ids": receipt.event_ids, - "data": receipt.data, - }, - }, - }, - } - key = (receipt.room_id, receipt.receipt_type, receipt.user_id) + # if there is no flush yet scheduled, we will send out these receipts with + # immediate flushes, and schedule the next flush for this room. + if queues_pending_flush is not None: + logger.debug("Queuing receipt for: %r", domains) + else: + logger.debug("Sending receipt to: %r", domains) + self._schedule_rr_flush_for_room(room_id, len(domains)) for domain in domains: - self.build_and_send_edu( - destination=domain, - edu_type="m.receipt", - content=content, - key=key, - ) + queue = self._get_per_destination_queue(domain) + queue.queue_read_receipt(receipt) + + # if there is already a RR flush pending for this room, then make sure this + # destination is registered for the flush + if queues_pending_flush is not None: + queues_pending_flush.add(queue) + else: + queue.flush_read_receipts_for_room(room_id) + + def _schedule_rr_flush_for_room(self, room_id, n_domains): + # that is going to cause approximately len(domains) transactions, so now back + # off for that multiplied by RR_TXN_INTERVAL_PER_ROOM + backoff_ms = self._rr_txn_interval_per_room_ms * n_domains + + logger.debug("Scheduling RR flush in %s in %d ms", room_id, backoff_ms) + self.clock.call_later(backoff_ms, self._flush_rrs_for_room, room_id) + self._queues_awaiting_rr_flush_by_room[room_id] = set() + + def _flush_rrs_for_room(self, room_id): + queues = self._queues_awaiting_rr_flush_by_room.pop(room_id) + logger.debug("Flushing RRs in %s to %s", room_id, queues) + + if not queues: + # no more RRs arrived for this room; we are done. + return + + # schedule the next flush + self._schedule_rr_flush_for_room(room_id, len(queues)) + + for queue in queues: + queue.flush_read_receipts_for_room(room_id) @logcontext.preserve_fn # the caller should not yield on this @defer.inlineCallbacks diff --git a/synapse/federation/sender/per_destination_queue.py b/synapse/federation/sender/per_destination_queue.py index 385039add4..be99211003 100644 --- a/synapse/federation/sender/per_destination_queue.py +++ b/synapse/federation/sender/per_destination_queue.py @@ -80,6 +80,10 @@ class PerDestinationQueue(object): # destination self._pending_presence = {} # type: dict[str, UserPresenceState] + # room_id -> receipt_type -> user_id -> receipt_dict + self._pending_rrs = {} + self._rrs_pending_flush = False + # stream_id of last successfully sent to-device message. # NB: may be a long or an int. self._last_device_stream_id = 0 @@ -87,6 +91,9 @@ class PerDestinationQueue(object): # stream_id of last successfully sent device list update. self._last_device_list_stream_id = 0 + def __str__(self): + return "PerDestinationQueue[%s]" % self._destination + def pending_pdu_count(self): return len(self._pending_pdus) @@ -118,6 +125,30 @@ class PerDestinationQueue(object): }) self.attempt_new_transaction() + def queue_read_receipt(self, receipt): + """Add a RR to the list to be sent. Doesn't start the transmission loop yet + (see flush_read_receipts_for_room) + + Args: + receipt (synapse.api.receipt_info.ReceiptInfo): receipt to be queued + """ + self._pending_rrs.setdefault( + receipt.room_id, {}, + ).setdefault( + receipt.receipt_type, {} + )[receipt.user_id] = { + "event_ids": receipt.event_ids, + "data": receipt.data, + } + + def flush_read_receipts_for_room(self, room_id): + # if we don't have any read-receipts for this room, it may be that we've already + # sent them out, so we don't need to flush. + if room_id not in self._pending_rrs: + return + self._rrs_pending_flush = True + self.attempt_new_transaction() + def send_keyed_edu(self, edu, key): self._pending_edus_keyed[(edu.edu_type, key)] = edu self.attempt_new_transaction() @@ -183,10 +214,12 @@ class PerDestinationQueue(object): # We can only include at most 50 PDUs per transactions pending_pdus, self._pending_pdus = pending_pdus[:50], pending_pdus[50:] - pending_edus = self._pending_edus + pending_edus = [] + + pending_edus.extend(self._get_rr_edus(force_flush=False)) # We can only include at most 100 EDUs per transactions - pending_edus, self._pending_edus = pending_edus[:100], pending_edus[100:] + pending_edus.extend(self._pop_pending_edus(100 - len(pending_edus))) pending_edus.extend( self._pending_edus_keyed.values() @@ -224,6 +257,11 @@ class PerDestinationQueue(object): self._last_device_stream_id = device_stream_id return + # if we've decided to send a transaction anyway, and we have room, we + # may as well send any pending RRs + if len(pending_edus) < 100: + pending_edus.extend(self._get_rr_edus(force_flush=True)) + # END CRITICAL SECTION success = yield self._transaction_manager.send_new_transaction( @@ -285,6 +323,28 @@ class PerDestinationQueue(object): # We want to be *very* sure we clear this after we stop processing self.transmission_loop_running = False + def _get_rr_edus(self, force_flush): + if not self._pending_rrs: + return + if not force_flush and not self._rrs_pending_flush: + # not yet time for this lot + return + + edu = Edu( + origin=self._server_name, + destination=self._destination, + edu_type="m.receipt", + content=self._pending_rrs, + ) + self._pending_rrs = {} + self._rrs_pending_flush = False + yield edu + + def _pop_pending_edus(self, limit): + pending_edus = self._pending_edus + pending_edus, self._pending_edus = pending_edus[:limit], pending_edus[limit:] + return pending_edus + @defer.inlineCallbacks def _get_new_device_messages(self): last_device_stream_id = self._last_device_stream_id diff --git a/synapse/handlers/receipts.py b/synapse/handlers/receipts.py index dd783ae134..274d2946ad 100644 --- a/synapse/handlers/receipts.py +++ b/synapse/handlers/receipts.py @@ -118,7 +118,7 @@ class ReceiptsHandler(BaseHandler): if not is_new: return - self.federation.send_read_receipt(receipt) + yield self.federation.send_read_receipt(receipt) @defer.inlineCallbacks def get_receipts_for_room(self, room_id, to_key): diff --git a/tests/federation/test_federation_sender.py b/tests/federation/test_federation_sender.py new file mode 100644 index 0000000000..28e7e27416 --- /dev/null +++ b/tests/federation/test_federation_sender.py @@ -0,0 +1,128 @@ +# -*- coding: utf-8 -*- +# Copyright 2019 New Vector Ltd +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from mock import Mock + +from twisted.internet import defer + +from synapse.types import ReadReceipt + +from tests.unittest import HomeserverTestCase + + +class FederationSenderTestCases(HomeserverTestCase): + def make_homeserver(self, reactor, clock): + return super(FederationSenderTestCases, self).setup_test_homeserver( + state_handler=Mock(spec=["get_current_hosts_in_room"]), + federation_transport_client=Mock(spec=["send_transaction"]), + ) + + def test_send_receipts(self): + mock_state_handler = self.hs.get_state_handler() + mock_state_handler.get_current_hosts_in_room.return_value = ["test", "host2"] + + mock_send_transaction = self.hs.get_federation_transport_client().send_transaction + mock_send_transaction.return_value = defer.succeed({}) + + sender = self.hs.get_federation_sender() + receipt = ReadReceipt("room_id", "m.read", "user_id", ["event_id"], {"ts": 1234}) + self.successResultOf(sender.send_read_receipt(receipt)) + + self.pump() + + # expect a call to send_transaction + mock_send_transaction.assert_called_once() + json_cb = mock_send_transaction.call_args[0][1] + data = json_cb() + self.assertEqual(data['edus'], [ + { + 'edu_type': 'm.receipt', + 'content': { + 'room_id': { + 'm.read': { + 'user_id': { + 'event_ids': ['event_id'], + 'data': {'ts': 1234}, + }, + }, + }, + }, + }, + ]) + + def test_send_receipts_with_backoff(self): + """Send two receipts in quick succession; the second should be flushed, but + only after 20ms""" + mock_state_handler = self.hs.get_state_handler() + mock_state_handler.get_current_hosts_in_room.return_value = ["test", "host2"] + + mock_send_transaction = self.hs.get_federation_transport_client().send_transaction + mock_send_transaction.return_value = defer.succeed({}) + + sender = self.hs.get_federation_sender() + receipt = ReadReceipt("room_id", "m.read", "user_id", ["event_id"], {"ts": 1234}) + self.successResultOf(sender.send_read_receipt(receipt)) + + self.pump() + + # expect a call to send_transaction + mock_send_transaction.assert_called_once() + json_cb = mock_send_transaction.call_args[0][1] + data = json_cb() + self.assertEqual(data['edus'], [ + { + 'edu_type': 'm.receipt', + 'content': { + 'room_id': { + 'm.read': { + 'user_id': { + 'event_ids': ['event_id'], + 'data': {'ts': 1234}, + }, + }, + }, + }, + }, + ]) + mock_send_transaction.reset_mock() + + # send the second RR + receipt = ReadReceipt("room_id", "m.read", "user_id", ["other_id"], {"ts": 1234}) + self.successResultOf(sender.send_read_receipt(receipt)) + self.pump() + mock_send_transaction.assert_not_called() + + self.reactor.advance(19) + mock_send_transaction.assert_not_called() + + self.reactor.advance(10) + mock_send_transaction.assert_called_once() + json_cb = mock_send_transaction.call_args[0][1] + data = json_cb() + self.assertEqual(data['edus'], [ + { + 'edu_type': 'm.receipt', + 'content': { + 'room_id': { + 'm.read': { + 'user_id': { + 'event_ids': ['other_id'], + 'data': {'ts': 1234}, + }, + }, + }, + }, + }, + ]) |