Intel I350 IGB, Zero Copy Timestamps deviate on ports on the same card.

[TIE1996]

Hi!

We are observing a strange behaviour with the Intel I350 card with four ports using the igb driver and PF_Ring 9.0.0-stable.

We are using two ports at the receiver side and two ports on the sender side. We set up all structures needed for PF_Ring (queues etc.) and wait till the user wants to start a recording using the zc burst API. We then start the sender (before! the receiver) to send 3 packets on each interface. Then we start the receiver with a time difference between the two ports. Afterwards the sender sends packets alternately on both ports.
What we then observe is a time difference between the two ports (the ports are synchronized using phc2sys, we observe the clock deviation during the test). The files to reproduce this are attached shown below.

To recreate, run the receiver till the prompt, then the sender till the prompt. Now press enter on the receiver (you will already notice that the timestamps are not as expected (they correlate with the usleep)). Now press enter on the sender.

A resulting log is also shown below. The packages do arrive alternately on the receiver, which we can assume through the print statements, but the timestamps are off.

If you need more info just let me know.

Cheers!

Sender

# run this file on the tester and check the time diff between the recordings
# of the oppsing ports

import socket
import util.udp
import time
import os

byte_buffers1 = []
byte_buffers2 = []

for i in range(100):
    byte_buffers1.append(util.udp.create_udp_packet(os.urandom(72)))
    byte_buffers2.append(util.udp.create_udp_packet(os.urandom(800)))

with socket.socket(socket.AF_PACKET, socket.SOCK_RAW) as s1:
    s1.bind(("enp1s0f0", 0))
    with socket.socket(socket.AF_PACKET, socket.SOCK_RAW) as s2:
        s2.bind(("enp1s0f1", 0))

        s1.send(byte_buffers1[0])
        time.sleep(1)
        s1.send(byte_buffers1[1])
        time.sleep(1)
        s1.send(byte_buffers1[2])
        time.sleep(1)

        s2.send(byte_buffers2[0])
        time.sleep(0.005)
        s2.send(byte_buffers2[1])
        time.sleep(0.005)
        s2.send(byte_buffers2[2])
        time.sleep(0.005)

input("Start recording and press enter to continue")

with socket.socket(socket.AF_PACKET, socket.SOCK_RAW) as s1:
    s1.bind(("enp1s0f0", 0))
    with socket.socket(socket.AF_PACKET, socket.SOCK_RAW) as s2:
        s2.bind(("enp1s0f1", 0))
        for i in range(100):
            s1.send(byte_buffers1[i])
            time.sleep(0.00002)
            s2.send(byte_buffers2[i])
            time.sleep(0.005)

Receiver:

/*
 * (C) 2003-23 - ntop
 *
 * Permission is hereby granted, free of charge, to any person obtaining a copy
 * of this software and associated documentation files (the "Software"), to deal
 * in the Software without restriction, including without limitation the rights
 * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 * copies of the Software, and to permit persons to whom the Software is
 * furnished to do so, subject to the following conditions:
 *
 * The above copyright notice and this permission notice shall be included in
 * all copies or substantial portions of the Software.
 *
 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
 * THE SOFTWARE.
 */

#define _GNU_SOURCE
#include <signal.h>
#include <sched.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <string.h>
#include <unistd.h>
#include <sys/mman.h>
#include <errno.h>
#include <sys/time.h>
#include <time.h>
#include <pthread.h>
#include <sched.h>
#include <stdio.h>

#include "pfring.h"
#include "pfring_zc.h"

#include "zutils.c"

#define ALARM_SLEEP 1
#define MAX_CARD_SLOTS 32768
#define CACHE_LINE_LEN 64

// #define USE_BURST_API
#define BURST_LEN 32

pfring_zc_cluster *zc;
pfring_zc_cluster *zc2;
pfring_zc_queue *zq;
pfring_zc_queue *zq2;
pfring_zc_pkt_buff *buffers[BURST_LEN];
pfring_zc_pkt_buff *buffers2[BURST_LEN];

struct timeval startTime;
unsigned long long numPkts = 0, numBytes = 0;
int bind_core = -1;
int bind_time_pulse_core = -1;
int buffer_len;
u_int8_t wait_for_packet = 1, do_shutdown = 0, verbose = 0, add_filtering_rule = 0;
u_int8_t high_stats_refresh = 0, time_pulse = 0, touch_payload = 0;

u_int64_t prev_ns = 0;
u_int64_t threshold_min = 1500, threshold_max = 2500; /* TODO parameters */
u_int64_t threshold_min_count = 0, threshold_max_count = 0;

volatile u_int64_t *pulse_timestamp_ns;
/* ******************************** */

void sigproc(int sig)
{
  static int called = 0;
  fprintf(stderr, "Leaving...\n");
  if (called)
    return;
  else
    called = 1;

  do_shutdown = 1;


  pfring_zc_queue_breakloop(zq);
  pfring_zc_queue_breakloop(zq2);
}

/* *************************************** */

void printHelp(void)
{
  printf("zcount - (C) 2014-23 ntop\n");
  printf("Using PFRING_ZC v.%s\n", pfring_zc_version());
  printf("A simple packet counter application.\n\n");
  printf("Usage:   zcount -i <device> -c <cluster id>\n"
         "                [-h] [-g <core id>] [-R] [-H] [-S <core id>] [-v] [-a] [-t]\n\n");
  printf("-h              Print this help\n");
  printf("-i <device>     Device name\n");
  printf("-c <cluster id> Cluster id\n");
  printf("-g <core id>    Bind this app to a core\n");
  printf("-a              Active packet wait\n");
  printf("-f <bpf>        Set a BPF filter\n");
  printf("-R              Test hw filters adding a rule (Intel 82599)\n");
  printf("-H              High stats refresh rate (workaround for drop counter on 1G Intel cards)\n");
  printf("-X              Enable hardware timestamp (when supported)\n");
  printf("-s <time>       Set hardware timestamp (when supported). Format example: '2022-09-23 14:30:55.123456789'\n");
  printf("-d <nsec>       Adjust hardware timestamp using a signed nsec delta (when supported)'\n");
  printf("-S <core id>    Pulse-time thread for inter-packet time check\n");
  printf("-T              Capture also TX (standard kernel drivers only)\n");
  printf("-t              Touch payload (to force packet load on cache)\n");
  printf("-D              Debug mode\n");
  printf("-C              Check license\n");
  printf("-M              Print maintenance\n");
  printf("-v <level>      Verbose (1 to print packet headers, 2 to print hex)\n");
}

/* *************************************** */

void *packet_consumer_thread(void *user)
{
  int i, n;

  if (bind_core >= 0)
    bind2core(bind_core);

  while (!do_shutdown)
  {
    if ((n = pfring_zc_recv_pkt_burst(zq, buffers, BURST_LEN, wait_for_packet)) > 0)
    {

      for (i = 0; i < n; i++)
      {
        printf("[%u.%u][len=%u]\n", buffers[i]->ts.tv_sec, buffers[i]->ts.tv_nsec, buffers[i]->len);
      }
      pfring_zc_sync_queue(zq, rx_only);
    }
  }

  return NULL;
}

void *packet_consumer_thread2(void *user)
{
  int i, n;

  if (bind_core >= 0)
    bind2core(bind_core);

  while (!do_shutdown)
  {
    if ((n = pfring_zc_recv_pkt_burst(zq2, buffers2, BURST_LEN, wait_for_packet)) > 0)
    {

      for (i = 0; i < n; i++)
      {
        printf("[%u.%u][len=%u]\n", buffers2[i]->ts.tv_sec, buffers2[i]->ts.tv_nsec, buffers2[i]->len);
      }
      pfring_zc_sync_queue(zq, rx_only);
    }
  }

  pfring_zc_sync_queue(zq2, rx_only);

  return NULL;
}

/* *************************************** */

int main(int argc, char *argv[])
{
  char *device = NULL, c;
  int i, cluster_id = DEFAULT_CLUSTER_ID, rc = 0, check_license = 0, print_maintenance = 0;
  pthread_t my_thread;
  pthread_t my_thread2;
  struct timeval timeNow, lastTime;
  u_int32_t flags;
  char *filter = NULL;
  char *init_time = NULL;
  long long shift_time = 0;

  lastTime.tv_sec = 0;
  startTime.tv_sec = 0;

  flags = PF_RING_ZC_DEVICE_CAPTURE_INJECTED;

  while ((c = getopt(argc, argv, "ac:d:f:g:hi:v:CDMRHs:S:TtX")) != '?')
  {
    if ((c == 255) || (c == -1))
      break;

    switch (c)
    {
    case 'h':
      printHelp();
      exit(0);
      break;
    case 'a':
      wait_for_packet = 0;
      break;
    case 'c':
      cluster_id = atoi(optarg);
      break;
    case 'd':
      flags |= PF_RING_ZC_DEVICE_HW_TIMESTAMP;
      shift_time = atoll(optarg);
      break;
    case 'f':
      filter = strdup(optarg);
      break;
    case 'i':
      device = strdup(optarg);
      break;
    case 'g':
      bind_core = atoi(optarg);
      break;
    case 'R':
      add_filtering_rule = 1;
      break;
    case 'H':
      high_stats_refresh = 1;
      break;
    case 's':
      flags |= PF_RING_ZC_DEVICE_HW_TIMESTAMP;
      init_time = strdup(optarg);
      break;
    case 'S':
      time_pulse = 1;
      bind_time_pulse_core = atoi(optarg);
      break;
    case 'T':
      flags |= PF_RING_ZC_DEVICE_CAPTURE_TX;
      break;
    case 't':
      touch_payload = 1;
      break;
    case 'v':
      verbose = atoi(optarg);
      break;
    case 'C':
      check_license = 1;
      break;
    case 'D':
      pfring_zc_debug();
      break;
    case 'M':
      print_maintenance = 1;
      break;
    case 'X':
      flags |= PF_RING_ZC_DEVICE_HW_TIMESTAMP | PF_RING_ZC_DEVICE_HW_TIMESTAMP_UNSYNC;
      break;
    }
  }

  if (device == NULL || cluster_id < 0)
  {
    printHelp();
    exit(-1);
  }

  buffer_len = max_packet_len(device);

  zc = pfring_zc_create_cluster(
      cluster_id,
      buffer_len,
      0,
      MAX_CARD_SLOTS + BURST_LEN,
      pfring_zc_numa_get_cpu_node(bind_core),
      NULL /* auto hugetlb mountpoint */,
      0);

  zc2 = pfring_zc_create_cluster(
      cluster_id + 1,
      buffer_len,
      0,
      MAX_CARD_SLOTS + BURST_LEN,
      pfring_zc_numa_get_cpu_node(bind_core),
      NULL /* auto hugetlb mountpoint */,
      0);

  if (zc == NULL)
  {
    fprintf(stderr, "pfring_zc_create_cluster error [%s] Please check that pf_ring.ko is loaded and hugetlb fs is mounted\n",
            strerror(errno));
    return -1;
  }

  if (zc2 == NULL)
  {
    fprintf(stderr, "pfring_zc_create_cluster error [%s] Please check that pf_ring.ko is loaded and hugetlb fs is mounted\n",
            strerror(errno));
    return -1;
  }

  zq = pfring_zc_open_device(zc, "zc:enp1s0f0", rx_only, flags);
  zq2 = pfring_zc_open_device(zc2, "zc:enp1s0f1", rx_only, flags);

  if (zq == NULL)
  {
    fprintf(stderr, "pfring_zc_open_device error [%s] Please check that %s is up and not already used\n",
            strerror(errno), "zc:enp1s0f0");
    rc = -1;
    goto cleanup;
  }

  if (zq2 == NULL)
  {
    fprintf(stderr, "pfring_zc_open_device error [%s] Please check that %s is up and not already used\n",
            strerror(errno), "zc:enp1s0f0");
    rc = -1;
    goto cleanup;
  }

  for (i = 0; i < BURST_LEN; i++)
  {

    buffers[i] = pfring_zc_get_packet_handle(zc);
    buffers2[i] = pfring_zc_get_packet_handle(zc2);

    if (buffers[i] == NULL)
    {
      fprintf(stderr, "pfring_zc_get_packet_handle error\n");
      rc = -1;
      goto cleanup;
    }
  }

  printf("Press enter to start threads\n");
  getchar(); // Wait for a single character input

  pthread_create(&my_thread, NULL, packet_consumer_thread, (void *)NULL);
  usleep(6000000);
  pthread_create(&my_thread2, NULL, packet_consumer_thread2, (void *)NULL);

  if (!verbose)
    while (!do_shutdown)
    {
      if (high_stats_refresh)
      {
        pfring_zc_stat stats;

        pfring_zc_stats(zq, &stats);
        gettimeofday(&timeNow, NULL);

        if (timeNow.tv_sec != lastTime.tv_sec)
        {
          lastTime.tv_sec = timeNow.tv_sec;
        }
        usleep(1);
      }
      else
      {
        sleep(ALARM_SLEEP);
      }
    }

  pthread_join(my_thread, NULL);
  pthread_join(my_thread2, NULL);

  sleep(1);

cleanup:

  pfring_zc_destroy_cluster(zc);
  pfring_zc_destroy_cluster(zc2);

  return rc;
}

Resulting Print Statement:
[1757339191.795410785][len=114]
[1757339192.796477074][len=114]
[1757339193.797667859][len=114]
[1757339197.795667722][len=842]
[1757339197.800879933][len=842]
[1757339197.805994144][len=842]
[1757339202.26146628][len=114]
[1757339205.23105428][len=842]
[1757339202.31396739][len=114]
[1757339205.28345540][len=842]
[1757339202.36741691][len=114]
[1757339205.33691283][len=842]
[1757339202.42085898][len=114]
[1757339205.39033819][len=842]
[1757339202.47324571][len=114]
[1757339205.44269996][len=842]
[1757339202.52604408][len=114]
[1757339205.49554392][len=842]
[1757339202.57959102][len=114]
[1757339205.54907903][len=842]
[1757339202.63199167][len=114]
[1757339205.60147583][len=842]
[1757339202.68480499][len=114]
[1757339205.65430100][len=842]
[1757339202.73830330][len=114]
[1757339205.70778971][len=842]
[1757339202.79111655][len=114]
[1757339205.76060456][len=842]
[1757339202.84351672][len=114]
[1757339205.81300744][len=842]
[1757339202.89633028][len=114]
[1757339205.86582229][len=842]
[1757339202.95030439][len=114]
[1757339205.91980544][len=842]
[1757339202.100270592][len=114]
[1757339205.97215025][len=842]
[1757339202.105549565][len=114]
[1757339205.102499421][len=842]
[1757339202.110833977][len=114]
[1757339205.107782938][len=842]
[1757339202.116133444][len=114]
[1757339205.113081621][len=842]
[1757339202.121372453][len=114]
[1757339205.118319550][len=842]
[1757339202.126610205][len=114]
[1757339205.123555614][len=842]
[1757339202.131886587][len=114]
[1757339205.128844506][len=842]
[1757339202.137138266][len=114]
[1757339205.134084075][len=842]
[1757339202.142375979][len=114]
[1757339205.139324523][len=842]
[1757339202.147713283][len=114]
[1757339205.144662979][len=842]
[1757339202.153083952][len=114]
[1757339205.150031312][len=842]
[1757339202.158320992][len=114]
[1757339205.155266001][len=842]
[1757339202.163556561][len=114]
[1757339205.160503522][len=842]
[1757339202.168837646][len=114]
[1757339205.165786591][len=842]
[1757339202.174095485][len=114]
[1757339205.171044253][len=842]
[1757339202.179336957][len=114]
[1757339205.176285046][len=842]
[1757339205.181525750][len=842]
[1757339202.184577157][len=114]
[1757339202.189860050][len=114]
[1757339205.186816786][len=842]
[1757339202.195150526][len=114]
[1757339205.192099055][len=842]
[1757339202.200387742][len=114]
[1757339205.197336063][len=842]
[1757339202.205710855][len=114]
[1757339205.202658273][len=842]
[1757339202.211086980][len=114]
[1757339205.208033077][len=842]
[1757339205.213268694][len=842]
[1757339202.216323060][len=114]
[1757339202.221553365][len=114]
[1757339205.218500087][len=842]
[1757339202.226833698][len=114]
[1757339205.223782660][len=842]
[1757339202.232111935][len=114]
[1757339205.229060241][len=842]
[1757339202.237346104][len=114]
[1757339205.234294249][len=842]
[1757339202.242586568][len=114]
[1757339205.239534937][len=842]
[1757339202.247867637][len=114]
[1757339205.244825429][len=842]
[1757339202.253123907][len=114]
[1757339205.250071861][len=842]
[1757339202.258362804][len=114]
[1757339205.255310629][len=842]
[1757339202.263602324][len=114]
[1757339205.260550814][len=842]
[1757339202.268948323][len=114]
[1757339205.265898981][len=842]
[1757339202.274185891][len=114]
[1757339205.271129718][len=842]
[1757339202.279421284][len=114]
[1757339205.276369062][len=842]
[1757339202.284657797][len=114]
[1757339205.281604263][len=842]
[1757339202.290037401][len=114]
[1757339205.286984195][len=842]
[1757339202.295273409][len=114]
[1757339205.292217860][len=842]
[1757339202.300525985][len=114]
[1757339205.297474851][len=842]
[1757339202.305803470][len=114]
[1757339205.302752384][len=842]
[1757339202.311119095][len=114]
[1757339205.308067577][len=842]
[1757339202.316359863][len=114]
[1757339205.313307130][len=842]
[1757339202.321598784][len=114]
[1757339205.318547794][len=842]
[1757339202.326945223][len=114]
[1757339205.323893753][len=842]
[1757339202.332185559][len=114]
[1757339205.329133785][len=842]
[1757339202.337425447][len=114]
[1757339205.334373290][len=842]
[1757339202.342708740][len=114]
[1757339205.339657046][len=842]
[1757339202.348082825][len=114]
[1757339205.345029075][len=842]
[1757339202.353318577][len=114]
[1757339205.350262964][len=842]
[1757339202.358552898][len=114]
[1757339205.355500116][len=842]
[1757339202.363834174][len=114]
[1757339205.360782417][len=842]
[1757339202.369118027][len=114]
[1757339205.366066989][len=842]
[1757339202.374358443][len=114]
[1757339205.371307190][len=842]
[1757339202.379593060][len=114]
[1757339205.376540662][len=842]
[1757339202.384875248][len=114]
[1757339205.381832610][len=842]
[1757339202.390124080][len=114]
[1757339205.387072178][len=842]
[1757339202.395355169][len=114]
[1757339205.392301044][len=842]
[1757339202.400593313][len=114]
[1757339205.397541492][len=842]
[1757339202.405900452][len=114]
[1757339205.402857030][len=842]
[1757339205.408091334][len=842]
[1757339202.411143444][len=114]
[1757339202.416375444][len=114]
[1757339205.413320679][len=842]
[1757339205.418554856][len=842]
[1757339202.421609333][len=114]
[1757339205.423902975][len=842]
[1757339202.426953933][len=114]
[1757339202.432194125][len=114]
[1757339205.429141160][len=842]
[1757339205.434380552][len=842]
[1757339202.437432517][len=114]
[1757339202.442721233][len=114]
[1757339205.439669636][len=842]
[1757339202.448088310][len=114]
[1757339205.445035433][len=842]
[1757339205.450271946][len=842]
[1757339202.453325575][len=114]
[1757339202.458605684][len=114]
[1757339205.455554111][len=842]
[1757339202.463954691][len=114]
[1757339205.460903158][len=842]
[1757339202.469194803][len=114]
[1757339205.466142342][len=842]
[1757339202.474433571][len=114]
[1757339205.471381910][len=842]
[1757339205.476676594][len=842]
[1757339202.479728351][len=114]
[1757339205.482035240][len=842]
[1757339202.485088469][len=114]
[1757339202.490324125][len=114]
[1757339205.487268801][len=842]
[1757339202.495602362][len=114]
[1757339205.492551181][len=842]
[1757339202.500951473][len=114]
[1757339205.497899924][len=842]
[1757339202.506207152][len=114]
[1757339205.503155971][len=842]
[1757339202.511489404][len=114]
[1757339205.508438112][len=842]
[1757339202.516837019][len=114]
[1757339205.513785871][len=842]
[1757339202.522116248][len=114]
[1757339205.519064524][len=842]
[1757339202.527355833][len=114]
[1757339205.524302012][len=842]
[1757339202.532697328][len=114]
[1757339205.529645731][len=842]
[1757339205.535010553][len=842]
[1757339202.538061798][len=114]
[1757339202.543302574][len=114]
[1757339205.540250833][len=842]
[1757339205.545532654][len=842]
[1757339202.548583722][len=114]

[cardigliano]

@TIE1996 if I understand correctly, there is a time difference of 3-4 seconds between interfaces. I ran a few tests to check the behaviour of the timestamp in case of multiple ports, and I do not see the same difference. Please note I wrote a similar tool myself as I cannot run your py script (I miss util.udp at least), and I am not 100% sure I got what you saw (also because there is no interface reference in the output to figure out which interface received which packet).