按照kcp风格增加了debug log

KCP/KCP.cs

@@ -241,8 +241,26 @@ internal struct ackItem
  // internal time.
  public UInt32 CurrentMS { get { return currentMS(); } }
 
- // create a new kcp control object, 'conv' must equal in two endpoint
- // from the same connection.
+ // log
+ Action<string> writelog = null;
+
+ public const Int32 IKCP_LOG_OUTPUT = 1;
+ public const Int32 IKCP_LOG_INPUT = 2;
+ public const Int32 IKCP_LOG_SEND = 4;
+ public const Int32 IKCP_LOG_RECV = 8;
+ public const Int32 IKCP_LOG_IN_DATA = 16;
+ public const Int32 IKCP_LOG_IN_ACK = 32;
+ public const Int32 IKCP_LOG_IN_PROBE = 64;
+ public const Int32 IKCP_LOG_IN_WINS = 128;
+ public const Int32 IKCP_LOG_OUT_DATA = 256;
+ public const Int32 IKCP_LOG_OUT_ACK = 512;
+ public const Int32 IKCP_LOG_OUT_PROBE = 1024;
+ public const Int32 IKCP_LOG_OUT_WINS = 2048;
+ public const Int32 IKCP_LOG_FLUSH_TIME = 4096;
+ public Int32 logmask;
+
+ // create a new kcp control object, 'conv' must equal in two endpoint
+ // from the same connection.
  public KCP(UInt32 conv_, Action<byte[], int> output_)
  {
  conv = conv_;
@@ -321,7 +339,13 @@ public int Recv(byte[] buffer, int index, int length)
  n += seg.data.ReadableBytes;
 
  count++;
- var fragment = seg.frg;
+ var fragment = seg.frg;
+
+ if (ikcp_canlog(IKCP_LOG_RECV))
+ {
+ ikcp_log($"recv sn={seg.sn}");
+ }
+
  Segment.Put(seg);
  if (0 == fragment) break;
  }
@@ -589,6 +613,12 @@ public int Input(byte[] data, int index, int size, bool regular, bool ackNoDelay
  int flag = 0;
  UInt64 inSegs = 0;
  bool windowSlides = false;
+
+ if (ikcp_canlog(IKCP_LOG_INPUT))
+ {
+ ikcp_log($"[RI] {size} bytes");
+ }
+
 
  while (true)
  {
@@ -597,6 +627,7 @@ public int Input(byte[] data, int index, int size, bool regular, bool ackNoDelay
  UInt32 length = 0;
  UInt32 una = 0;
  UInt32 conv_ = 0;
+ UInt32 current = currentMS();
 
  UInt16 wnd = 0;
  byte cmd = 0;
@@ -646,10 +677,20 @@ public int Input(byte[] data, int index, int size, bool regular, bool ackNoDelay
  parse_ack(sn);
  parse_fastack(sn, ts);
  flag |= 1;
- latest = ts;
+ latest = ts;
+
+ if (ikcp_canlog(IKCP_LOG_IN_ACK))
+ {
+ ikcp_log($" input ack: sn={sn} ts={ts} rtt={_itimediff(current, ts)} rto={rx_rto}");
+ }
  }
  else if (IKCP_CMD_PUSH == cmd)
- {
+ {
+ if (ikcp_canlog(IKCP_LOG_IN_DATA))
+ {
+ ikcp_log($" input psh: sn={sn} ts={ts}");
+ }
+
  var repeat = true;
  if (_itimediff(sn, rcv_nxt + rcv_wnd) < 0)
  {
@@ -673,11 +714,20 @@ public int Input(byte[] data, int index, int size, bool regular, bool ackNoDelay
  {
  // ready to send back IKCP_CMD_WINS in Ikcp_flush
  // tell remote my window size
- probe |= IKCP_ASK_TELL;
+ probe |= IKCP_ASK_TELL;
+
+ if (ikcp_canlog(IKCP_LOG_IN_PROBE))
+ {
+ ikcp_log(" input probe");
+ }
  }
  else if (IKCP_CMD_WINS == cmd)
- {
- // do nothing
+ {
+ // do nothing
+ if (ikcp_canlog(IKCP_LOG_IN_WINS))
+ {
+ ikcp_log($" input wins: {wnd}");
+ }
  }
  else
  {
@@ -769,7 +819,11 @@ public UInt32 Flush(bool ackOnly)
  Action<int> makeSpace = (space) =>
  {
  if (writeIndex + space > mtu)
- {
+ {
+ if (ikcp_canlog(IKCP_LOG_OUTPUT))
+ {
+ ikcp_log($"[RO] {writeIndex} bytes");
+ }
  output(buffer, writeIndex);
  writeIndex = reserved;
  }
@@ -778,7 +832,11 @@ public UInt32 Flush(bool ackOnly)
  Action flushBuffer = () =>
  {
  if (writeIndex > reserved)
- {
+ {
+ if (ikcp_canlog(IKCP_LOG_OUTPUT))
+ {
+ ikcp_log($"[RO] {writeIndex} bytes");
+ }
  output(buffer, writeIndex);
  }
  };
@@ -792,8 +850,13 @@ public UInt32 Flush(bool ackOnly)
  {
  seg.sn = ack.sn;
  seg.ts = ack.ts;
- writeIndex += seg.encode(buffer, writeIndex);
- }
+ writeIndex += seg.encode(buffer, writeIndex);
+
+ if (ikcp_canlog(IKCP_LOG_OUT_ACK))
+ {
+ ikcp_log($"output ack: sn={seg.sn}");
+ }
+ }
  }
  acklist.Clear();
 
@@ -945,7 +1008,12 @@ public UInt32 Flush(bool ackOnly)
  if (segment.xmit >= dead_link)
  {
  state = 0xFFFFFFFF;
- }
+ }
+
+ if (ikcp_canlog(IKCP_LOG_OUT_DATA))
+ {
+ ikcp_log($"output psh: sn={segment.sn} ts={segment.ts} resendts={segment.resendts} rto={segment.rto} fastack={segment.fastack}, xmit={segment.xmit}");
+ }
  }
 
  // get the nearest rto
@@ -1020,7 +1088,12 @@ public void Update()
  ts_flush += interval;
  if (_itimediff(current, ts_flush) >= 0)
  ts_flush = current + interval;
- Flush(false);
+ Flush(false);
+
+ if (ikcp_canlog(IKCP_LOG_FLUSH_TIME))
+ {
+ ikcp_log($"flush time: {current}");
+ }
  }
  }
 
@@ -1147,5 +1220,26 @@ public void SetStreamMode(bool enabled)
  {
  stream = enabled ? 1 : 0;
  }
+
+ bool ikcp_canlog(int mask)
+ {
+ if ((mask & logmask) == 0 || writelog == null) return false;
+ return true;
+ }
+
+ public void SetLogger(Action<string> logger)
+ {
+ writelog = logger;
+ }
+
+ public void SetLogMask(int mask)
+ {
+ logmask = mask;
+ }
+
+ void ikcp_log(string logStr)
+ {
+ writelog?.Invoke(logStr);
+ }
  }
 }

KCP/UDPSession.cs

@@ -22,6 +22,9 @@ class UDPSession
  public IPEndPoint RemoteAddress { get; private set; }
  public IPEndPoint LocalAddress { get; private set; }
 
+ private DateTime startDt = DateTime.Now;
+ const int logmask = KCP.IKCP_LOG_IN_ACK | KCP.IKCP_LOG_OUT_ACK | KCP.IKCP_LOG_IN_DATA | KCP.IKCP_LOG_OUT_DATA;
+
  public void Connect(string host, int port)
  {
  IPHostEntry hostEntry = Dns.GetHostEntry(host);
@@ -41,6 +44,11 @@ public void Connect(string host, int port)
  // fast3: 1, 10, 2, 1
  mKCP.NoDelay(0, 30, 2, 1);
  mKCP.SetStreamMode(true);
+
+ // Log
+ //mKCP.SetLogger(Log);
+ //mKCP.SetLogMask(logmask);
+
  mRecvBuffer.Clear();
  }
 
@@ -157,5 +165,12 @@ public void Update()
  mNextUpdateTime = mKCP.Check();
  }
  }
+
+ public void Log(string str)
+ {
+ DateTime now = DateTime.Now;
+ int t = (int)(now - startDt).TotalMilliseconds;
+ Console.WriteLine($"[{t.ToString().PadLeft(10, ' ')}] {str}");
+ }
  }
 }