[Bug] Tcpreplay ceases to sleep between packets when executed with -M 10

[blaa]

Describe the bug
I try to replay a 5GB pcap file for application tests. It contains about 22 million packets. I want to use specific speed, -M 10 or -M 30 for a slow pace.

Since Debian Trixie (tcpreplay 4.5.1) at the end of the file the tcpreplay speeds up. This didn't happen on bookworm (tcpreplay 4.4.3). I've build master branch today with the same result

To Reproduce
Steps to reproduce the behavior:

1. I tested only with one PCAP file. It might be broken but worked before with different tcpreplay. It was cut and prepared (macs changed) using tcprewrite.
2. I use local dummy type interface for sending packets.
3. I tested with: tcpreplay -d 3 -M 30 -T nano --stats=1 --no-flow-stats somelarge.pcap. But originally without -T, -d and --stats behaves the same.
4. ifstat and application see the rise of speed.

Expected behavior
Tcpreplay should sleep between packets until the end to keep the pace.

I observe instead:

      inter                eth0                eth1                                                                                                                                            
 KB/s in  KB/s out   KB/s in  KB/s out   KB/s in  KB/s out
    0.00   3661.93      0.70      1.55      0.00      0.00   
    0.00   3662.15      1.11      2.58      0.00      0.00  
    0.00   3661.99      1.82      3.46      0.00      0.00  
    0.00   3662.17      1.02      3.77      0.00      0.00             
    0.00   3662.15      0.86      4.28      0.00      0.00                                                                                                                                     
    0.00   3662.16      1.04      2.82      0.00      0.00
    0.00  80680.24      7.22     14.66      0.00      0.00
    0.00  83083.16      7.49     12.36      0.00      0.00
    0.00  83659.08      8.91     24.20      0.00      0.00
    0.00  80100.35     11.37     32.20      0.00      0.00       
    0.00  80349.06      8.90     26.05      0.00      0.00                                                                                                                                     
    0.00  77820.65      7.50     28.72      0.00      0.00
    0.00  76222.75      1.68     15.24      0.00      0.00
    0.00  78465.22      0.47     11.27      0.00      0.00
    0.00  78210.75      0.06      2.27      0.00      0.00
    0.00  81536.45      0.06      0.46      0.00      0.00
    0.00  81650.00      0.13      0.58      0.00      0.00
    0.00  78374.31      1.99      2.56      0.00      0.00
    0.00  75183.51      0.00      0.00      0.00      0.00
    0.00  80901.15      0.32      4.88      0.00      0.00
    0.00  77221.99      0.00      0.00      0.00      0.00
    0.00  75452.95      0.06      0.17      0.00      0.00
    0.00  75474.68      6.78     12.86      0.00      0.00
    0.00  71521.27      0.29      0.29      0.00      0.00
    0.00  80867.65      1.42     12.61      0.00      0.00
    0.00  81216.17      0.06      0.91      0.00      0.00
    0.00  78079.23      0.40      0.79      0.00      0.00
    0.00  85597.87      0.06      0.36      0.00      0.00
    0.00  84288.10     11.01     16.59      0.00      0.00
    0.00  79981.52      8.38     12.90      0.00      0.00
    0.00  78126.55     11.10     38.87      0.00      0.00
    0.00  83119.79      8.06     24.77      0.00      0.00
    0.00  82222.70      6.39     26.32      0.00      0.00
    0.00  78328.55      0.26     14.29      0.00      0.00

Aug 07 10:20:03 DEBUG1 in sendpacket.c:sendpacket_open_pf() line 998: sendpacket: using PF_PACKET
Aug 07 10:20:04 DEBUG2 in send_packets.c:send_packets() line 419: packet 1 caplen 134
Aug 07 10:20:04 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #1
Aug 07 10:20:04 DEBUG2 in send_packets.c:send_packets() line 419: packet 2 caplen 134
Aug 07 10:20:04 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=134           nap=0s 12576nsec
Aug 07 10:20:04 DEBUG2 in send_packets.c:tcpr_sleep() line 1198: Sleeping:                   0s 12576nsec
(since beginning it does sleep)
(...)
Aug 07 10:20:05 Test start: 1970-01-02 20:54:09.248116281 ...
Aug 07 10:20:05 Actual: 18062 packets (3750059 bytes) sent in 1.00 seconds
Aug 07 10:20:05 Rated: 3749744.0 Bps, 29.99 Mbps, 18060.48 pps
(...)
Aug 07 10:30:18 Actual: 11462618 packets (2302609947 bytes) sent in 614.02 seconds
Aug 07 10:30:18 Rated: 3750001.9 Bps, 30.00 Mbps, 18667.87 pps
(...)
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478539 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 0nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478539
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478540 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 40546nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:tcpr_sleep() line 1198: Sleeping:                   0s 40546nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478540
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478541 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 0nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478541
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478542 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 43100nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:tcpr_sleep() line 1198: Sleeping:                   0s 43100nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478542
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478543 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 0nsec
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478543
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478544 caplen 214
Aug 07 10:30:18 DEBUG3 in send_packets.c:calc_sleep_time() line 1103: packet size=214           nap=0s 0nsec
(since this point until end of log it doesn't)
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478544
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478545 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478545
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478546 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478546
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478547 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478547
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478548 caplen 91
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478548
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478549 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478549
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478550 caplen 91
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478550
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478551 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478551
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478552 caplen 91
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478552
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478553 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478553
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478554 caplen 294
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478554
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478555 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478555
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 419: packet 11478556 caplen 214
Aug 07 10:30:18 DEBUG2 in send_packets.c:send_packets() line 545: Sending packet #11478556
(...)
Aug 07 10:30:47 Statistics for network device: inter
Aug 07 10:30:47         Successful packets:        22649944
Aug 07 10:30:47         Failed packets:            0
Aug 07 10:30:47         Truncated packets:         0
Aug 07 10:30:47         Retried packets (ENOBUFS): 0
Aug 07 10:30:47         Retried packets (EAGAIN):  0

System (please complete the following information):

• Debian bookworm fine (tcpreplay 4.4.3-1)
• Debian trixie (4.5.1) or master 6fcbf03 - problem.

[fklassen]

I am unable to reproduce. Here is my output.

How long are you waiting before you see an issues?

Also, can you attempt 4.5.2-beta2?

 sudo src/tcpreplay -M 30 --stats=1 --no-flow-stats -i enp0s5 ~/Documents/Captures/bigFlows.pcap
Test start: 1970-01-08 00:53:33.449937825 ...
Actual: 11122 packets (3750412 bytes) sent in 1.00 seconds
Rated: 3749988.2 Bps, 29.99 Mbps, 11120.74 pps
Actual: 18917 packets (7500499 bytes) sent in 2.00 seconds
Rated: 3749990.7 Bps, 29.99 Mbps, 9457.84 pps
Actual: 30990 packets (11251165 bytes) sent in 3.00 seconds
Rated: 3749992.0 Bps, 29.99 Mbps, 10328.90 pps
Actual: 39064 packets (15002153 bytes) sent in 4.00 seconds
Rated: 3749999.1 Bps, 29.99 Mbps, 9764.59 pps
Actual: 47354 packets (18752435 bytes) sent in 5.00 seconds
Rated: 3749995.0 Bps, 29.99 Mbps, 9469.55 pps
Actual: 57268 packets (22503160 bytes) sent in 6.00 seconds
Rated: 3749997.9 Bps, 29.99 Mbps, 9543.32 pps
Actual: 64549 packets (26253972 bytes) sent in 7.00 seconds
Rated: 3749997.4 Bps, 29.99 Mbps, 9219.88 pps
Actual: 72488 packets (30004188 bytes) sent in 8.00 seconds
Rated: 3749998.9 Bps, 29.99 Mbps, 9059.73 pps
Actual: 79473 packets (33755089 bytes) sent in 9.00 seconds
Rated: 3749997.1 Bps, 29.99 Mbps, 8828.99 pps
Actual: 87969 packets (37505703 bytes) sent in 10.00 seconds
Rated: 3749990.5 Bps, 29.99 Mbps, 8795.54 pps
Actual: 95017 packets (41255807 bytes) sent in 11.00 seconds
Rated: 3749998.1 Bps, 29.99 Mbps, 8636.68 pps
Actual: 102624 packets (45006853 bytes) sent in 12.00 seconds
Rated: 3749997.6 Bps, 29.99 Mbps, 8550.69 pps
Actual: 109776 packets (48757710 bytes) sent in 13.00 seconds
Rated: 3749998.8 Bps, 29.99 Mbps, 8442.96 pps
Actual: 117857 packets (52508778 bytes) sent in 14.00 seconds
Rated: 3749999.6 Bps, 29.99 Mbps, 8416.94 pps
Actual: 126042 packets (56259655 bytes) sent in 15.00 seconds
Rated: 3749999.4 Bps, 29.99 Mbps, 8401.35 pps
Actual: 133123 packets (60009777 bytes) sent in 16.00 seconds
Rated: 3749998.4 Bps, 29.99 Mbps, 8318.82 pps
Actual: 142092 packets (63760368 bytes) sent in 17.00 seconds
Rated: 3749999.2 Bps, 29.99 Mbps, 8356.99 pps
Actual: 150355 packets (67510986 bytes) sent in 18.00 seconds

[blaa]

From the log that was Aug 07 10:30:18 - Aug 07 10:20:05 - so curiously close to 10 minutes of running.

I can later try with master, but it so I'll try to add there some breakpoint if I can get to it.

Meh, I didn't intent to close it and I can't reopen it.

[blaa]

master..4.5.2-beta2 has no changes in send_packets.c so it might be the same.

There's certainly confusion in declaration that uses name sleep_us (microseconds) and definition that has start_ns (nanoseconds). In the same file declaration is on top, definition lower. It seems to use nanoseconds and used to use microseconds?

Debugging is rather hard because it depends on the wall clock. Looking at code, I'd suggest that something's wrong with skip_length. It's the only thing I think that can skip calculating time:

        if (skip_length && pktlen < skip_length) {
            skip_length -= pktlen;
        } else if (ctx->skip_packets) {
            --ctx->skip_packets;
        } else {

Since we don't use skip_packets in this mode.

            if (bits_sent > COUNTER_OVERFLOW_RISK)
                next_tx_ns = (bits_sent * 1000) / bps * 1000000;
            else   
                next_tx_ns = (bits_sent * 1000000000) / bps;

            if (next_tx_ns > tx_ns) {
                NANOSEC_TO_TIMESPEC(next_tx_ns - tx_ns, &ctx->nap);
            } else if (tx_ns > next_tx_ns) {
                tx_ns = now_ns - start_ns;
                *skip_length = ((tx_ns - next_tx_ns) * bps) / 8000000000;
            }

skip_length is unsigned long long.
now_ns is time when last packet was sent.

I finally after 20 minutes on GDB (and some modifications to have a breakpoint when something STOPS happening, ie. 100000 packets sent without calculating sleep time) hit this,
and I have:

(gdb) p skip_length
$2 = 2285591989

which seems exceesive.

If the initial next_tx_ns calculation needs COUNTER_OVERFLOW_RISK, the same seems to apply to skip_length calculation.

[blaa]

Caught right after skip_length got suspiciously big:

(gdb) p *skip_length
$2 = 2305842851
(gdb) p bits_sent
$23 = 18446744408
(gdb) p now_ns
$3 = 1198667990779466
(gdb) p start_ns
$4 = 1196823316464500
(gdb) p tx_ns
$5 = 1844674314966
(gdb) p next_tx_ns
$6 = 33429  <-- This is too small. Should be 1844674440800.0
(gdb) p bps
$7 = 10000000
(gdb) 
(gdb) p (tx_ns - next_tx_ns) * bps
$9 = 18446742815370000000
which is 99% of 2^64, type size.

Problem is the shaky 'counter overflow risk'. It seems to be equal to (((unsigned long long)~0) >> 23) -> 2199023255551.
So the if enters the else and calculates too small value because (bits_sent * 1000000000) overflows.

Maybe us was migrated to ns and counter overflow risk wasn't decreased?

So the problem is there since 3b0934e, Sat Mar 4 18:31:14 2023 +0100

             if (bits_sent > COUNTER_OVERFLOW_RISK && bps > 500000)
-                next_tx_us = (bits_sent * 1000) / bps * 1000;
+                next_tx_ns = (bits_sent * 1000) / bps * 1000000;
             else
-                next_tx_us = (bits_sent * 1000000) / bps;
+                next_tx_ns = (bits_sent * 1000000000) / bps;

23 bits in counter should be decreased by 3 to 20 bits?

Update:
It even was 20. Was changed to 23 in december:

commit dda4343d2fe6cb37fec6775a11ccb463d8cac895
Author: Fred Klassen <fred.klassen@broadcom.com>
Date:   Mon Dec 25 09:56:20 2023 -0800

    Feature #796: fix netmap, get_current_time etc.
    
    * macOS was not reading nanosecond timer
    * get time called too often, causing overhead
    * fine tune gettimeofday_sleep()
    * adjusted overflow value to prevent issues with very long running instances
    * fix build/merge issues

diff --git a/src/defines.h.in b/src/defines.h.in
index fe776552..1975f053 100644
--- a/src/defines.h.in
+++ b/src/defines.h.in
@@ -102,7 +102,7 @@ char dummy[0];
 #define COUNTER unsigned long
 #define COUNTER_SPEC "%lu"
 #endif
-#define COUNTER_OVERFLOW_RISK (((COUNTER)~0) >> 20)
+#define COUNTER_OVERFLOW_RISK (((COUNTER)~0) >> 23)
 
 #include <common/cidr.h>
 #include <common/list.h>

So probably the true solution should be to change the arithmetic.

[fklassen]

@plangarbalint can you also look at this? It appears to be a side effect of #796

I may have to defer a fix to 4.5.3.