Opened 10 months ago

Last modified 3 months ago

#2427 new enhancement

Maintaining bandwidth correctly: PeerState.java

Reported by: jogger Owned by: zzz
Priority: major Milestone: undecided
Component: router/transport Version: 0.9.38
Keywords: Cc:
Parent Tickets: #2412, #2506 Sensitive: no

Description

I am making this a separate ticket, as it is of fundamental importance. This is to resolve the following issues:

  • Whenever available bandwidth is checked, it must be made sure that the value returned belongs to the current time interval. getSendWindowBytesRemaining() ignores this. This is the major performance issue I2CP users complained about as they often come with large chunks of data that will then neither notify getNextVolley() nor cause an immediate send that should be allowed.
  • Maintaining bandwidth in long time intervals (currently ≥ 1000 ms by allocateSendingBytes()) leads to short term traffic bursts, as allowed traffic may concentrate at the end and the beginning of two consecutive time intervals, possibly causing a short term overload for outbound queues and the network connection.

The solution is easy by moving the bandwidth refill to getSendWindowBytesRemaining() and handing out bandwidth in much smaller chunks as low as 8 bytes only (unlikely, but possible on fast CPU). I simply do this before each send, provided the system clock has advanced. The maintenance of send window size stays untouched as well as the ACK logic.

Results are convincing:

  • I2CP traffic outbound (seeding torrents) clearly up
  • UDP packet pusher CPU usage clearly down
  • message delay seems down a bit
  • UDP send pauses smaller / more evenly distributed according to tcpdump

This is independent of #2412, however they make a perfect team as the improved logic in #2412 heavily relies on the correctness of the above functions.

Hope this diff is correct.

--- "PeerState orig.java"	2019-02-06 13:21:26.571744716 +0100
+++ "PeerState patch.java"	2019-02-06 14:06:03.014869734 +0100
@@ -479,7 +479,20 @@
 
     /** how many bytes can we send to the peer in the current second */
     public int getSendWindowBytesRemaining() {
-        synchronized(_outboundMessages) {
+        synchronized(_outboundMessages) { // possibly reentrant
+            long now = _context.clock().now();
+            int duration = (int)(now - _lastSendRefill);
+            if (_sendBytes > 0 && duration > 0 || duration >= 1000) {
+                _sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + (_sendWindowBytes * duration + 500) / 1000, _sendWindowBytes);
+                _sendBps = (99 * _sendBps + _sendBytes + 50) / 100;
+             //if (isForACK) {
+            //    _sendACKBytes += size;
+            //    _sendACKBps = (int)(0.9f*(float)_sendACKBps + 0.1f*((float)_sendACKBytes * (1000f/(float)duration)));
+            //}
+               _sendBytes = 0;
+            //_sendACKBytes = 0;
+                _lastSendRefill = now;
+            }
             return _sendWindowBytesRemaining;
         }
     }
@@ -694,43 +707,29 @@
     /**
      *  Caller should synch
      */
-    private boolean allocateSendingBytes(int size, boolean isForACK, int messagePushCount) { 
-        long now = _context.clock().now();
-        long duration = now - _lastSendRefill;
-        if (duration >= 1000) {
-            _sendWindowBytesRemaining = _sendWindowBytes;
-            _sendBytes += size;
-            _sendBps = (int)(0.9f*_sendBps + 0.1f*(_sendBytes * (1000f/duration)));
-            //if (isForACK) {
-            //    _sendACKBytes += size;
-            //    _sendACKBps = (int)(0.9f*(float)_sendACKBps + 0.1f*((float)_sendACKBytes * (1000f/(float)duration)));
-            //}
-            _sendBytes = 0;
-            //_sendACKBytes = 0;
-            _lastSendRefill = now;
-        }
+    private boolean allocateSendingBytes(int size, boolean isForACK, int messagePushCount) {
         //if (true) return true;
-        if (IGNORE_CWIN || size <= _sendWindowBytesRemaining || (ALWAYS_ALLOW_FIRST_PUSH && messagePushCount == 0)) {
+        if (size <= getSendWindowBytesRemaining() || IGNORE_CWIN || isForACK || (ALWAYS_ALLOW_FIRST_PUSH && messagePushCount == 0)) {
             if ( (messagePushCount == 0) && (_concurrentMessagesActive > _concurrentMessagesAllowed) ) {
                 _consecutiveRejections++;
                 _context.statManager().addRateData("udp.rejectConcurrentActive", _concurrentMessagesActive, _consecutiveRejections);
                 return false;
-            } else if (messagePushCount == 0) {
+            }
+            if (messagePushCount == 0) {
                 _context.statManager().addRateData("udp.allowConcurrentActive", _concurrentMessagesActive, _concurrentMessagesAllowed);
                 _concurrentMessagesActive++;
                 if (_consecutiveRejections > 0) 
                     _context.statManager().addRateData("udp.rejectConcurrentSequence", _consecutiveRejections, _concurrentMessagesActive);
                 _consecutiveRejections = 0;
             }
-            _sendWindowBytesRemaining -= size; 
+            _sendWindowBytesRemaining -= size;
             _sendBytes += size;
-            _lastSendTime = now;
-            //if (isForACK) 
+            _lastSendTime = _context.clock().now();
+            //if (isForACK)
             //    _sendACKBytes += size;
             return true;
-        } else {
-            return false;
         }
+        return false;
     }
     
     /** if we need to contact them, do we need to talk to an introducer? */
@@ -1178,22 +1177,16 @@
                         _sendWindowBytes += bytesACKed; //512; // bytesACKed;
                 //}
             }
-        } else {
-            int allow = _concurrentMessagesAllowed - 1;
-            if (allow < MIN_CONCURRENT_MSGS)
-                allow = MIN_CONCURRENT_MSGS;
-            _concurrentMessagesAllowed = allow;
-        }
+        } else
+            _concurrentMessagesAllowed = Math.max(_concurrentMessagesAllowed - 1, MIN_CONCURRENT_MSGS);
+
         if (_sendWindowBytes > MAX_SEND_WINDOW_BYTES)
             _sendWindowBytes = MAX_SEND_WINDOW_BYTES;
         _lastReceiveTime = _context.clock().now();
         _lastSendFullyTime = _lastReceiveTime;
         
         //if (true) {
-            if (_sendWindowBytesRemaining + bytesACKed <= _sendWindowBytes)
-                _sendWindowBytesRemaining += bytesACKed;
-            else
-                _sendWindowBytesRemaining = _sendWindowBytes;
+            _sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + bytesACKed, _sendWindowBytes);
         //}
         
         if (numSends < 2) {

Subtickets

Attachments (2)

udp_sendBps.png (149.6 KB) - added by Zlatin Balevsky 9 months ago.
sendBps_graph_2.png (347.6 KB) - added by Zlatin Balevsky 4 months ago.
Stat still broken

Download all attachments as: .zip

Change History (18)

comment:1 Changed 10 months ago by jogger

After introducing the sliding window now there is a cosmetic glitch in the above full stats only calculation of _sendBps. Should be

_sendBps = (99 * _sendBps + _sendBytes * 1000 / duration + 50) / 100;

comment:2 Changed 10 months ago by zzz

@OP reference to "the major performance issue I2CP users complained about" ? link or ticket?

related: #2424

comment:3 Changed 9 months ago by jogger

I was referring to complaints in current and previous forums about torrent send speed. The updated bandwidth calculation deals with possibly not allowing traffic that would fit the send window.

comment:4 Changed 9 months ago by zzz

Parent Tickets: 2412

This ticket is to fix a bug described in #2412 comment 21.

According to OP here, #2412 relies on this ticket, so making this one a child.

comment:5 Changed 9 months ago by Zlatin Balevsky

I haven't analyzed the patch as thoroughly as I should yet, but I did put it on my busy router and the udp.sendBps metric is way, way up. Overall traffic however is about the same, which leads me to think that metric is somehow broken by this patch.

comment:6 Changed 9 months ago by Zlatin Balevsky

I reverted the line that does the sendBps calculation to

_sendBps = (int)(0.9 * _sendBps + 0.1* _sendBytes * 1000.0 / duration);

and this restored the udp.sendBps metric to it's previous range. Whether that's correct or incorrect is a different question.

You are allocating too much bandwidth in the following logic:

if (_sendBytes > 0 && duration > 0 || duration >= 1000) {
                _sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + (_sendWindowBytes * duration + 500) / 1000, _sendWindowBytes);

To see what I mean, imagine the initial available bytes are X. They get used up immediately, in less than 1ms (not likely but possible). 1ms elapses and you allocate another X/1000 + 0.5, and so on - total bandwidth used for the second interval will be 2X + 500.

Version 0, edited 9 months ago by Zlatin Balevsky (next)

comment:7 Changed 9 months ago by jogger

Correct sendBps calculation now found in the combined patch within #2412.

My bandwidth calculation is correct. The current logic hands out too little bw when not run exactly every 1000 ms. It might hand out too much if X is transmitted twice within a second when an interval boundary falls in between.

In my logic using a sliding window, if X is available at any given point in time, this means there has been no traffic over the past second. So X can be used up immediately, beginning a new interval with bandwidth building up to X again over the netxt 1000 ms. The 500 mentioned statistically vanish through integer truncation.

Changed 9 months ago by Zlatin Balevsky

Attachment: udp_sendBps.png added

comment:8 Changed 9 months ago by Zlatin Balevsky

The attachment udp_sendBps.png is with the patch from comment 32 from ticket 2412. Doesn't look fixed at all. Are you sure about that multiplication by 1000?

comment:9 Changed 9 months ago by jogger

absolutely sure. To see it is correct just assume duration = 1000,

comment:10 Changed 4 months ago by jogger

Sensitive: unset

I am continuing here as zzz suggested. Full overhauled Patch below including necessary mods to the debug code. Questions raised by zab to solve: Are my bandwidth calcs correct?

sendBps is calculated as an sliding average with integer rounding:

_sendBps = (99 * _sendBps + _sendBytes * 1000 / duration + 50) / 100;

Question: Does the term "_sendBytes * 1000 / duration" deliver correct current bandwidth?
2,000 bytes sent within 50 ms: Result 40,000 - correct
100 bytes sent within 500 ms: Result 200 - correct

_sendWindowBytesRemaining is refilled up to the max using:

sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + (_sendWindowBytes * duration + 500) / 1000, _sendWindowBytes);

The term "(_sendWindowBytes * duration + 500) / 1000" is the integer rounded number of bytes to be sent within "duration" ms. Since "duration" has elapsed, this is the correct refill.

Question raised by zab: What if the full amount is used within the first ms?
It is true that we then hand out a small number of "_sendWindowBytes / 1000" in the next ms. This can happen only in the first second directly after the peer is initialized. Afterwards a full window means zero traffic in the past second, so such a send can be attributed to the past interval and it is completely legal to gradually refill.

If someome does not want this behaviour, _sendWindowBytesRemaining could be initialized to some lower value, even 0. Please note that the current code allows 100% overdraft anytime by sending the full amount at the end and the beginning of two consecutive intervals. There are also gaps if the code is not called every ms.

comment:11 in reply to:  10 Changed 4 months ago by Zlatin Balevsky

Replying to jogger:

Full overhauled Patch below

Can you attach a patch against current mtn trunk so I can test whether the issue with the metric is still there?

comment:12 Changed 4 months ago by jogger

Never worked with mtn. Patch against stock 0.9.41:

--- ~/i2p/i2p-0.9.41/router/java/src/net/i2p/router/transport/udp/PeerState.java	2019-07-03 14:27:37.000000000 +0200
+++ ~/i2p/41p/router/java/src/net/i2p/router/transport/udp/PeerState.java	2019-08-06 20:24:32.000000000 +0200
@@ -491,7 +491,18 @@
 
     /** how many bytes can we send to the peer in the current second */
     public int getSendWindowBytesRemaining() {
-        synchronized(_outboundMessages) {
+        synchronized(_outboundMessages) { // possibly reentrant
+            long now = _context.clock().now();
+            int duration;
+            if ((duration = (int)(now - _lastSendRefill)) <= 0)
+                return _sendWindowBytesRemaining;
+            _sendBps = (99 * _sendBps + _sendBytes * 1000 / duration + 50) / 100;
+            _lastSendRefill = now;
+            _sendBytes = 0;
+            if (duration < 1000)
+                _sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + (_sendWindowBytes * duration + 500) / 1000, _sendWindowBytes);
+            else
+                _sendWindowBytesRemaining = _sendWindowBytes;
             return _sendWindowBytesRemaining;
         }
     }
@@ -702,20 +713,7 @@
      *  Caller should synch
      */
     private boolean allocateSendingBytes(int size, boolean isForACK, int messagePushCount) { 
-        long now = _context.clock().now();
-        long duration = now - _lastSendRefill;
-        if (duration >= 1000) {
-            _sendWindowBytesRemaining = _sendWindowBytes;
-            _sendBytes += size;
-            _sendBps = (int)(0.9f*_sendBps + 0.1f*(_sendBytes * (1000f/duration)));
-            //if (isForACK) {
-            //    _sendACKBytes += size;
-            //    _sendACKBps = (int)(0.9f*(float)_sendACKBps + 0.1f*((float)_sendACKBytes * (1000f/(float)duration)));
-            //}
-            _sendBytes = 0;
-            //_sendACKBytes = 0;
-            _lastSendRefill = now;
-        }
+        int sendWindowBytesRemaining = getSendWindowBytesRemaining();
 
         // Ticket 2505
         // We always send all unacked fragments for a message,
@@ -741,7 +739,7 @@
             if (_sendWindowBytesRemaining < 0)
                 _sendWindowBytesRemaining = 0; 
             _sendBytes += size;
-            _lastSendTime = now;
+            _lastSendTime = _context.clock().now();
             //if (isForACK) 
             //    _sendACKBytes += size;
             return true;
@@ -1848,7 +1846,7 @@
             if (allocateSendingBytes(size, state.getPushCount())) {
                 if (_log.shouldLog(Log.DEBUG))
                     _log.debug("Allocation of " + size + " allowed with " 
-                              + getSendWindowBytesRemaining() 
+                              + _sendWindowBytesRemaining
                               + "/" + getSendWindowBytes() 
                               + " remaining"
                               + " for message " + state.getMessageId() + ": " + state);
@@ -1873,7 +1871,7 @@
                 //    state.getMessage().timestamp("send rejected, available=" + getSendWindowBytesRemaining());
                 if (_log.shouldLog(Log.INFO))
                     _log.info("Allocation of " + size + " rejected w/ wsize=" + getSendWindowBytes()
-                              + " available=" + getSendWindowBytesRemaining()
+                              + " available=" + _sendWindowBytesRemaining
                               + " for message " + state.getMessageId() + ": " + state);
                 state.setNextSendTime(now + (ACKSender.ACK_FREQUENCY / 2) +
                                       _context.random().nextInt(ACKSender.ACK_FREQUENCY)); //(now + 1024) & ~SECOND_MASK);

Changed 4 months ago by Zlatin Balevsky

Attachment: sendBps_graph_2.png added

Stat still broken

comment:13 Changed 4 months ago by jogger

Got it! Another decade old bug. To see current code also overstating sendBps, just monitor a dying connecting. I just converted the logic from floating point to integer, overlooking the false underlying assumption of all intervals being of equal length.

Now using a moving 10 sec average which gets reset if traffic drops down to one packet within 10 sec or less. Should work much better.

--- ~/i2p/i2p-0.9.41/router/java/src/net/i2p/router/transport/udp/PeerState.java	2019-07-03 14:27:37.000000000 +0200
+++ ~/i2p/41p/router/java/src/net/i2p/router/transport/udp/PeerState.java	2019-08-08 08:42:36.000000000 +0200
@@ -491,7 +491,21 @@
 
     /** how many bytes can we send to the peer in the current second */
     public int getSendWindowBytesRemaining() {
-        synchronized(_outboundMessages) {
+        synchronized(_outboundMessages) { // possibly reentrant
+            long now = _context.clock().now();
+            int duration;
+            if ((duration = (int)(now - _lastSendRefill)) <= 0)
+                return _sendWindowBytesRemaining;
+            int oldBps = _sendBps;
+            _sendBps = (_sendBytes + 5) / 10; // sendrate for 10 sec interval
+            if (duration < 10000) // add earlier traffic from rest of 10 sec
+                _sendBps += ((10000 - duration) * oldBps + 5000) / 10000;
+            _lastSendRefill = now;
+            _sendBytes = 0;
+            if (duration < 1000)
+                _sendWindowBytesRemaining = Math.min(_sendWindowBytesRemaining + (_sendWindowBytes * duration + 500) / 1000, _sendWindowBytes);
+            else
+                _sendWindowBytesRemaining = _sendWindowBytes;
             return _sendWindowBytesRemaining;
         }
     }
@@ -702,20 +716,7 @@
      *  Caller should synch
      */
     private boolean allocateSendingBytes(int size, boolean isForACK, int messagePushCount) { 
-        long now = _context.clock().now();
-        long duration = now - _lastSendRefill;
-        if (duration >= 1000) {
-            _sendWindowBytesRemaining = _sendWindowBytes;
-            _sendBytes += size;
-            _sendBps = (int)(0.9f*_sendBps + 0.1f*(_sendBytes * (1000f/duration)));
-            //if (isForACK) {
-            //    _sendACKBytes += size;
-            //    _sendACKBps = (int)(0.9f*(float)_sendACKBps + 0.1f*((float)_sendACKBytes * (1000f/(float)duration)));
-            //}
-            _sendBytes = 0;
-            //_sendACKBytes = 0;
-            _lastSendRefill = now;
-        }
+        int sendWindowBytesRemaining = getSendWindowBytesRemaining();
 
         // Ticket 2505
         // We always send all unacked fragments for a message,
@@ -741,7 +742,7 @@
             if (_sendWindowBytesRemaining < 0)
                 _sendWindowBytesRemaining = 0; 
             _sendBytes += size;
-            _lastSendTime = now;
+            _lastSendTime = _context.clock().now();
             //if (isForACK) 
             //    _sendACKBytes += size;
             return true;
@@ -1848,7 +1849,7 @@
             if (allocateSendingBytes(size, state.getPushCount())) {
                 if (_log.shouldLog(Log.DEBUG))
                     _log.debug("Allocation of " + size + " allowed with " 
-                              + getSendWindowBytesRemaining() 
+                              + _sendWindowBytesRemaining
                               + "/" + getSendWindowBytes() 
                               + " remaining"
                               + " for message " + state.getMessageId() + ": " + state);
@@ -1873,7 +1874,7 @@
                 //    state.getMessage().timestamp("send rejected, available=" + getSendWindowBytesRemaining());
                 if (_log.shouldLog(Log.INFO))
                     _log.info("Allocation of " + size + " rejected w/ wsize=" + getSendWindowBytes()
-                              + " available=" + getSendWindowBytesRemaining()
+                              + " available=" + _sendWindowBytesRemaining
                               + " for message " + state.getMessageId() + ": " + state);
                 state.setNextSendTime(now + (ACKSender.ACK_FREQUENCY / 2) +
                                       _context.random().nextInt(ACKSender.ACK_FREQUENCY)); //(now + 1024) & ~SECOND_MASK);

comment:14 Changed 3 months ago by zzz

There's a lot above over the six months. Would you please summarize how the current code "overstates", or point to one of the above comments if it already says it? Thanks!

comment:15 Changed 3 months ago by jogger

The overstating occurs in the stats calculation

_sendBps = (int)(0.9f*_sendBps + 0.1f*(_sendBytes * (1000f/duration)));

Each interval gets the same weight, regardless of duration. Imagine a long series of alternating intervals of 1000 and 10000 ms with 1k transferred each. Actual bandwidth used is 2k/11000ms = 182 Bps. The formula will give you the average of 1 KBps and 100 Bps = 550 Bps long time. That is the pitfall that zab noticed and I overlooked in my first patch.

The actual bandwidth handed out is too small of course, since there are gaps if duration > 1000.

comment:16 Changed 3 months ago by zzz

Parent Tickets: 24122412, 2506

Thank you for the explanation.
Note: #2506 now depends on this ticket.

Two things about _sendBps:

  • It's currently a smoothed average. In your example, with two data points, yes it is not exact. It's never exact, it's an approximation.
  • _sendBps is NOT used for any accept/reject logic. It's for display only, on the /peers page. Your patches above do not use _sendBps for any decision making either. So changing the calculation doesn't change anything.

There may be changes to make on the measurement window, but the _sendBps calculation is not the root cause of anything.

Note: See TracTickets for help on using tickets.