diff options
Diffstat (limited to 'packages/meshbay-node/src')
6 files changed, 107 insertions, 2 deletions
diff --git a/packages/meshbay-node/src/meshbay_node/transfers.py b/packages/meshbay-node/src/meshbay_node/transfers.py index 3345cb9..477ec92 100644 --- a/packages/meshbay-node/src/meshbay_node/transfers.py +++ b/packages/meshbay-node/src/meshbay_node/transfers.py @@ -102,11 +102,24 @@ class Lease: # later, for ever. Seen doing exactly that in a node's log, every 30 s, # minutes after the transfers involved had finished. missed_grants: int = 0 + # What moved under this lease and over how long, for the line the node logs + # when it ends. Counted here because nothing else spans a transfer: a + # download is a run of independent chunk requests. + moved: int = 0 + first_used: float | None = None + last_moved: float = 0.0 @property def member(self) -> tuple[str, str]: return (self.group_id, self.user_id) + @property + def elapsed(self) -> float: + """Seconds from the first request under this lease to the last byte.""" + if self.first_used is None: + return 0.0 + return max(0.0, self.last_moved - self.first_used) + @dataclass class TransferSlots: @@ -223,8 +236,18 @@ class TransferSlots: lease.used = True lease.missed_grants = 0 lease.last_seen = time.monotonic() if now is None else now + if lease.first_used is None: + lease.first_used = lease.last_seen return True + def account(self, tr: str, nbytes: int, now: float | None = None) -> None: + """`nbytes` were served or received under this lease.""" + lease = self.leases.get(tr) + if lease is None: + return + lease.moved += nbytes + lease.last_moved = time.monotonic() if now is None else now + def close(self, tr: str, reason: str = REASON_DONE, now: float | None = None) -> tuple[Lease | None, list[Lease]]: """Give a slot back. Returns (the closed lease, newly granted ones). diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py index a44f097..c48e9ca 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/core.py @@ -14,7 +14,10 @@ from meshbay_common.protocol import MNP from meshbay_node import ops from meshbay_node import transfers as transfers_mod -from meshbay_node.transport.webrtc import sctp_fix # noqa: F401 (patches aiortc on import) +from meshbay_node.transport.webrtc import ( + sctp_fix, # noqa: F401 (patches aiortc on import) + sctp_stats, # noqa: F401 (patches aiortc on import) +) from meshbay_node.transport.webrtc.channel import ( _REPLY_TO, _DataChannelBuffer, diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py index 0434554..eafdaed 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/files.py @@ -319,6 +319,8 @@ class FilesMixin: if self._channel is None or self._channel.readyState != "open": return self._send(chunk_data) + if leased: + self._account(tr, len(chunk_data.get("ct") or b"")) log.debug("dl: sent file=%s chunk=%s bytes=%s buffered=%s", file_id[:12], chunk_index, len(chunk_data.get("ct") or b""), getattr(self._channel, "bufferedAmount", "?")) diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py new file mode 100644 index 0000000..338ded9 --- /dev/null +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/sctp_stats.py @@ -0,0 +1,43 @@ +"""Counts what aiortc's SCTP sender does not, applied on import (aiortc 1.15). + +aiortc halves its congestion window on every loss and drops it to one packet +when the T3 timer expires, and keeps no record of either. Those two counts are +what say whether a slow transfer was held back by the path: a window that never +grows past a few hundred KB is losses, and the node could not tell. + +A loss is counted when the sender enters fast recovery, so a burst of packets +dropped together is one loss, which is also one halving of the window. +""" + +from aiortc.rtcsctptransport import RTCSctpTransport + +_receive_sack_chunk = RTCSctpTransport._receive_sack_chunk +_t3_expired = RTCSctpTransport._t3_expired + + +async def _counting_receive_sack_chunk(self, chunk) -> None: + recovering = self._fast_recovery_exit is not None + await _receive_sack_chunk(self, chunk) + if not recovering and self._fast_recovery_exit is not None: + self._mb_losses = getattr(self, "_mb_losses", 0) + 1 + + +def _counting_t3_expired(self) -> None: + self._mb_t3 = getattr(self, "_mb_t3", 0) + 1 + _t3_expired(self) + + +RTCSctpTransport._receive_sack_chunk = _counting_receive_sack_chunk +RTCSctpTransport._t3_expired = _counting_t3_expired + + +def describe(pc) -> str: + """The association of `pc` as a log suffix, or nothing when it has none.""" + sctp = getattr(pc, "sctp", None) + if sctp is None: + return "" + srtt = getattr(sctp, "_srtt", None) + rtt = f"{srtt * 1000:.0f} ms" if srtt else "?" + return (f" sctp cwnd={sctp._cwnd // 1024} KB rtt={rtt}" + f" loss={getattr(sctp, '_mb_losses', 0)}" + f" t3={getattr(sctp, '_mb_t3', 0)}") diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py index 729c0a0..78c74d6 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/transfer_handlers.py @@ -11,6 +11,7 @@ from meshbay_common.protocol import MNP from meshbay_node import transfers as transfers_mod from meshbay_node.transfers import TransferSlots +from meshbay_node.transport.webrtc import sctp_stats from meshbay_node.transport.webrtc.limits import LEASE_GRANTED, LEASE_NONE, LEASE_QUEUED log = logging.getLogger("meshbay_node.transport.webrtc_server") @@ -25,6 +26,8 @@ if TYPE_CHECKING: # annotations only: the facade imports this module # noticing, so it trades latency for a timer that hardly ever runs. TRANSFER_SWEEP_SECS = 15 +MIB = 1024 * 1024 + class TransferMixin: def _slots(self) -> "TransferSlots": @@ -109,6 +112,29 @@ class TransferMixin: (self._user_id or "?")[:8], str(tr)[:8]) self._audit("transfer_unleased", str(tr)[:16]) + def _account(self, tr: str, nbytes: int) -> None: + slots = self._ctx.get("_transfer_slots") + if slots is not None: + slots.account(tr, nbytes) + + def _transfer_end_line(self, lease, reason: str) -> str: + """What a transfer moved, how fast, and what its association looked like. + + The node wrote nothing about throughput, so a slow download left no + trace in the journal and took a test bench to explain. The SCTP figures + are the association's totals since it opened, not this transfer's + share: a connection carries several transfers and they share one + window. + """ + line = (f"transfer: end {lease.kind} {lease.tr[:8]} {reason} " + f"{lease.moved / MIB:.1f} MB") + if lease.moved and lease.elapsed > 0: + line += (f" in {lease.elapsed:.1f} s " + f"({lease.moved / MIB / lease.elapsed:.2f} MB/s)") + owner = (self if lease.session_key == self._registry_key else + next(iter(self._sessions_everywhere(lease.session_key)), None)) + return line + sctp_stats.describe(getattr(owner, "_pc", None)) + def _transfer_state_msg(self, lease, state: str, reason: str = "") -> dict: slots = self._slots() out = { @@ -215,6 +241,7 @@ class TransferMixin: lease, granted = slots.close(tr, reason) if lease is not None: self._send(self._transfer_state_msg(lease, "closed", reason)) + log.info("%s", self._transfer_end_line(lease, reason)) self._announce(granted) def _release_transfers(self) -> None: @@ -223,6 +250,9 @@ class TransferMixin: if slots is None: return gone, granted = slots.release_session(self._registry_key) + for lease in gone: + log.info("%s", self._transfer_end_line( + lease, transfers_mod.REASON_SESSION_GONE)) if gone: log.info("transfer: session gone, released %d (%s)", len(gone), slots.summary()) @@ -251,6 +281,8 @@ class TransferMixin: ended, granted = slots.sweep() for lease, reason in ended: log.info("transfer: reclaimed %s (%s)", lease.tr[:8], reason) + if lease.state != "queued": + log.info("%s", self._transfer_end_line(lease, reason)) self._announce(granted, ended) log.debug("transfer: %s", slots.summary()) diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py index b19846c..c052703 100644 --- a/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py +++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc/upload_handlers.py @@ -18,7 +18,7 @@ from meshbay_node.roots import ( shell_active, ) from meshbay_node.transport.webrtc.disk import _append_chunk, _free_bytes -from meshbay_node.transport.webrtc.limits import LEASE_NONE, LEASE_QUEUED +from meshbay_node.transport.webrtc.limits import LEASE_GRANTED, LEASE_NONE, LEASE_QUEUED log = logging.getLogger("meshbay_node.transport.webrtc_server") @@ -227,6 +227,8 @@ class UploadMixin: _refuse("Invalid chunk encoding", "bad_chunk_encoding") return chunk_bytes = bytes(data) + if tr and state == LEASE_GRANTED: + self._account(tr, len(chunk_bytes)) if not SAFE_UPLOAD_NAME.match(filename): _refuse("Invalid filename", "invalid_filename") |