Public bug reported:

Dear Ubuntu D-ITG maintainers,

I am writing to report a bug in D-ITG 2.8.1 (r1023) that causes
incorrect per-packet RTT values to be written to the binary log when
ITGSend is run in Round-Trip Time Meter mode (-m rttm).


── AFFECTED FILE AND LINES ──────────────────────────────────────

File: src/ITGSend/ITGSend.cpp
Lines: 3420 (local log path) and 3426 (remote log path)


── ENVIRONMENT USED TO REPRODUCE ────────────────────────────────

OS : Ubuntu 22.04.5 LTS
D-ITG : 2.8.1-r1023-4
Platform:  Mininet 6eb8973
ITGSend host: 10.0.0.8
ITGRecv host: 172.16.0.1
Link delay (each dir): 10 ms (configured via tc netem)
Expected RTT: 20 ms
Packet rate: 1 000 pkt/s (-C 1000)
Payload size: 512 bytes (-c 512)
Duration: 20 s (-t 20000)
Files : itgsend_logs.zip: itgsend_before_fix.log; itgsend_before_fix.txt; 
itgsend_after_fix.log; itgsend_after_fix.txt.


── ROOT CAUSE ───────────────────────────────────────────────────

At the top of each iteration of the flowSender send loop, the current
wall-clock time is captured (lines 3147–3148):

time = Ticker.lastTime.tv_sec % 86400L;
timeUsec = Ticker.lastTime.tv_usec; // scope too wide

Both values are embedded into the outgoing packet's payload (fields
ptrTimeSec and ptrTimeUsec).

When ITGSend later receives the echoed packet from ITGRecv, it correctly
reads the seconds part of txTime back from the echo payload (line 3409):

time1 = ntohl((*(uint32_t *) ptrTimeSec)); // from payload

However, the microseconds part is NOT read from the payload. Instead,
the stale timeUsec variable, which now holds the microseconds of the
currently-being-sent packet, not the echoed one, is passed directly to
writeInBufferStandard:

// line 3417–3420 (local log path)
writeInBufferStandard(&infos[count], ...,
time1, time2, timeUsec, RcvTime.tv_usec, size_r);
//            ^^^^^^^^
//            WRONG: microseconds from the current send
//                   iteration, not from the echo payload

// lines 3423-3426 (remote log path - identical issue)
writeInBufferStandard(&infos[count], ...,
time1, time2, timeUsec, RcvTime.tv_usec, size_r);

At 1 000 pkt/s with a 20 ms RTT, the echo of packet k arrives ~20
iterations later. At that point, timeUsec holds the microseconds of
packet k+20, i.e. approximately txTime_k_µs + 20 000 µs. Consequently:

txTime (logged) = floor(t_k) + (t_k_µs + 20 000) / 1e6
                = t_k + 20 ms // <- wrong, it is shifted by one RTT

rxTime (logged) ≈ t_k + 20 ms // <- correct

logged RTT = rxTime − txTime ≈ 0 ms

At 1 000 pkt/s with a 20 ms RTT, 20 packets are in flight at any given
moment. Those 20 packets per second whose echo crosses a whole-second
boundary are logged with timeUsec and time1 belonging to different
calendar seconds, introducing an error of +1 000 ms:

logged RTT ≈ 1 000 ms (for boundary-crossing packets)

The resulting per-packet RTT distribution is bimodal (itgsend_before_fix.txt):
~98 % of values -> near 0 ms (18 440 packets)
~2 % of values -> near 1 000 ms (360 packets)

── WHY ITGDec -v / -c N STILL REPORTS THE CORRECT AVERAGE ──────

The overall weighted mean across all 18 800 packets is:

mean = (18 440 × 0 ms  +  360 × 1 000 ms) / 18 800
     = 360 000 / 18 800
     ≈ 20 ms

making the aggregate statistics appear plausible whilst the per-packet
data are wrong.


── THE CORRECT PATTERN (already present in the same file) ───────

A second RTTM code path at lines 3533-3553 handles this correctly by
reading the microseconds from the echo payload:

// lines 3533-3535
time1 = ntohl((*(uint32_t *) ptrTimeSec)); // OK
int net_TimeUsec = ntohl((*(uint32_t *) ptrTimeUsec)); // OK

writeInBufferStandard(&infos[count], ...,
time1, time2, net_TimeUsec, RcvTime.tv_usec, size_r);


── FIX ──────────────────────────────────────────────────────────

Immediately after line 3409, read the microseconds from the echo payload
and use it in both writeInBufferStandard calls:

diff
  time1 = ntohl((*(uint32_t *) ptrTimeSec));
  time2 = RcvTime.tv_sec % 86400L;
+ long int rttmTxUsec = ntohl((*(uint32_t *) ptrTimeUsec));
  recvPkts++;

  if ((logging) && (size_r > 0) && (meter == METER_RTTM)) {
      if (logremoto == 0) {
          writeInBufferStandard(&infos[count], ...,
-                 time1, time2, timeUsec, RcvTime.tv_usec, size_r);
+                 time1, time2, rttmTxUsec, RcvTime.tv_usec, size_r);
      } else {
          writeInBufferStandard(&infos[count], ...,
-                 time1, time2, timeUsec, RcvTime.tv_usec, size_r);
+                 time1, time2, rttmTxUsec, RcvTime.tv_usec, size_r);
          infosHostToNet(&infos[count]);
      }


Best regards,

Guillaume Nibert

** Affects: d-itg (Ubuntu)
     Importance: Undecided
         Status: New

** Attachment added: "itgsend_before_fix.log; itgsend_before_fix.txt; 
itgsend_after_fix.log; itgsend_after_fix.txt"
   
https://bugs.launchpad.net/bugs/2152652/+attachment/5970364/+files/itgsend_logs.zip

-- 
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/2152652

Title:
  Incorrect per-packet RTT in RTTM mode

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/d-itg/+bug/2152652/+subscriptions


-- 
ubuntu-bugs mailing list
[email protected]
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs

Reply via email to