ec_SDOwrite ec_SDOread from non-rt-thread disturb the latency in rt-thread

[tecodrive]

The latencies with my simple system ( i5-6600T @ 2.70GHz, NIC I211 or ZBOX CI547 RT8169) with dc are lower than 50us at a ec_frame rate of 250us - simple while poll .

while ( ( cpu_time_next_ts.tv_sec >  poll_time_ts.tv_sec ) ||
      ( ( cpu_time_next_ts.tv_sec == poll_time_ts.tv_sec ) && ( cpu_time_next_ts.tv_nsec > poll_time_ts.tv_nsec ) ) ) {
      poll_loops++; // important local variable, faster than PlcData.PLC_calc_latencies.poll_loops++
      clock_gettime( CLOCK_MONOTONIC , &poll_time_ts );
}

The rt-thread run on a isolated cpu core 3. There is used ec_send_overlap_processdata() , ec_receive_processdata(). On cpu 0-2 run the non-rt-thread.

Since I use ec_SDOread() & ec_SDOwrite() I get very high latency (~2000us). Only one ec_SDOxx() used per 100ms. I figured out, the NIC receive a high frame rate because of the while loop in ecx_srconfirm(). There is no delay between ecx_outframe_red() and ecx_waitinframe().

My fix is currently insert a usleep. I would like ec_SDOxx to be extended with a parameter for a delay. At the startup-phase used delay 0 and when the rt pdo thread is running and all slaves are sync, then a delay can be inserted when ec_SDOxxx() is used.

int ecx_srconfirm(ecx_portt *port, int idx, int timeout)
{
   int wkc = EC_NOFRAME;
   osal_timert timer1, timer2;

   osal_timer_start (&timer1, timeout);
   do
   {
      /* tx frame on primary and if in redundant mode a dummy on secondary */
      ecx_outframe_red(port, idx);

       /* fix latency spikes in nic send() insert usleep( 2000 ) */
      usleep( 2000 );

      if (timeout < EC_TIMEOUTRET)
      {
         osal_timer_start (&timer2, timeout);
      }
      else
      {
         /* normally use partial timout for rx */
         osal_timer_start (&timer2, EC_TIMEOUTRET);
      }
      /* get frame from primary or if in redundant mode possibly from secondary */
      wkc = ecx_waitinframe_red(port, idx, &timer2);
   /* wait for answer with WKC>=0 or otherwise retry until timeout */
   } while ((wkc <= EC_NOFRAME) && !osal_timer_is_expired (&timer1));
   /* if nothing received, clear buffer index status so it can be used again */
   if (wkc <= EC_NOFRAME)
   {
      ecx_setbufstat(port, idx, EC_BUF_EMPTY);
   }

   return wkc;
}

At the moment I try to extend soem to use netmap (userspace) and the new socket protokoll AF_XDP in the mainline kernel since 4.12. Both allows direct access with mmap to the frame of nic copied it with dma from hardware to the ring buffer. Very nice feature and reduces massive the latency between receiving and accessing from userpace the frame.

For interested => my NIC , IRQ , System Configuration

# ubuntu1710 4.13.0-38-lowlatency
# I211 , driver=igb , fast receive duration 20us => enp3s0
# I219-V , driver=e1000e , slow receive duration 70us...130us
# R8169 , driver=r8169 , fast receive duration 20us

# ----------------------------
# sudo gedit /etc/default/grub => add
# GRUB_CMDLINE_LINUX_DEFAULT="isolcpus=3 nohz_full=3 rcu_nocbs=3 rcu_nocb_poll elevator=noop nosmap  i915.enable_rc6=0 i915.enable_dc=0"

# ----------------------------
service irqbalance stop

# ----------------------------
ifname="enp3s0"
ethtool -L $ifname combined 1
ethtool -C $ifname rx-usecs 0 # default 3
ethtool -C $ifname tx-usecs 0 # default 3
sudo ethtool -K $ifname gso off gro off # generic-segmentation-offload , generic-receive-offload

# ----------------------------
device="enp3s0-"
cpu_num=3
for irq_num in $(cat /proc/interrupts | grep $device | cut -d: -f1 | sed "s/ //g") ; do
        echo device: $device , irq: $irq_num map to cpu: $cpu_num
    echo $cpu_num >/proc/irq/$irq_num/smp_affinity_list
done

# ----------------------------
device="xhci_hcd"
cpu_num=1
irq_num=$(cat /proc/interrupts | grep $device | cut -d: -f1 | sed "s/ //g")
echo device: $device , irq: $irq_num map to cpu: $cpu_num
echo $cpu_num > /proc/irq/$irq_num/smp_affinity_list

# ----------------------------
device="i915"
cpu_num=2

irq_num=$(cat /proc/interrupts | grep $device | cut -d: -f1 | sed "s/ //g")
echo device: $device , irq: $irq_num map to cpu: $cpu_num
echo $cpu_num > /proc/irq/$irq_num/smp_affinity_list

# ----------------------------
echo 0 > /proc/sys/kernel/watchdog

[nakarlsson]

Assuming your RT thread can pre-empt the non rt-thread, what is it that cause the jitter?

[tecodrive]

The real-time process runs on an isolated cpu and does not need to interrupt the non-real-time process. The kernel (lowlatency) allows irq threading, so tasks are prioritized interruptible.

The problem is in the kernel at high interrupt rate.

Achieving a low latency in the real-time thread using ethtool rx-usecs = 0. Otherwise, NAPI intervenes in the network driver => if an NIC interrupt comes, all further NIC interrupts are blocked and the driver polls for a short time for further frames. The result are high latencies.

With rx-usecs 0 NAPI is disabled and you get the minimum latency (Copy: Frame => NIC RAM => Reserve Kernel skb Buffer and Copy Frame => Copy Frame to Userspace RAM). But at now, with rx-usecs 0, this process is fired on every receiving frame. Otherwise, the process is used for multiple frames and reduce processing time.

If multiple frames are received within a few microseconds, the kernel get a high interrupt rate and block up to 2ms all nic access. This is not a problem when booting and configuring the EtherCAT bus.

-------- Weitergeleitete Nachricht --------

Datum: Tue, 24 Apr 2018 05:14:10 -0700 Betreff: Re: [OpenEtherCATsociety/SOEM] ec_SDOwrite ec_SDOread from non-rt-thread disturb the latency in rt-thread (#171) Kopie: tecodrive marthiens@tecodrive.com, Author <author@noreply.gith ub.com> An: OpenEtherCATsociety/SOEM SOEM@noreply.github.com Reply-to: OpenEtherCATsociety/SOEM <reply+0180287588713c8ba299f16b7cd6c 3078b2b12a05b2d94e292cf0000000116f6e19292a169ce12df4deb@reply.github.co m> Von: nakarlsson notifications@github.com Assuming your RT thread can pre-empt the non rt-thread, what is it that cause the jitter?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or mute the thread.

{"api_version":"1.0","publisher":{"api_key":"05dde50f1d1a384dd78767c554 93e4bb","name":"GitHub"},"entity":{"external_key":"github/OpenEtherCATs ociety/SOEM","title":"OpenEtherCATsociety/SOEM","subtitle":"GitHub repository","main_image_url":"https://cloud.githubusercontent.com/asset s/143418/17495839/a5054eac-5d88-11e6-95fc- 7290892c7bb5.png","avatar_image_url":"https://cloud.githubusercontent.c om/assets/143418/15842166/7c72db34-2c0b-11e6-9aed- b52498112777.png","action":{"name":"Open in GitHub","url":"https://gith ub.com/OpenEtherCATsociety/SOEM"}},"updates":{"snippets":[{"icon":"PERS ON","message":"@nakarlsson in #171: Assuming your RT thread can pre- empt the non rt-thread, what is it that cause the jitter?"}],"action":{"name":"View Issue","url":"https://github.com/Open EtherCATsociety/SOEM/issues/171#issuecomment-383908217"}}}

[nakarlsson]

Do you have a fork or something?

[tecodrive]

Unfortunately, nothing

⁣Gesendet mit TypeApp ​

Am 29. Apr. 2018, 21:29, um 21:29, nakarlsson notifications@github.com schrieb:

Do you have a fork or something?

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/OpenEtherCATsociety/SOEM/issues/171#issuecomment-385275209

[nakarlsson]

I see your point, what do you think @ArthurKetels? I guess It is possible via an API extensions or making it a config parameter. The later would always delay the send/recv polling with the same delay time.

Than it is a question if it should be added at all.

[ArthurKetels]

First, thanks tecodrive for your in depth explanation of the observed behavior. It shows good knowledge about the intricacies of multi processor programming and the linux network stack.

If have not seen any behavior int the linux network stack that prevents sending packets at a fast rate. At the point that it should not be possible to create bottlenecks at rated line speeds of 100mb/s. At most you create interrupts at a rate of 200kirq/s.

I think there is another mechanism that prevents the cooperation between the rt and non-rt task.

First I must note that the SDO_xxx functions are not intended to be used in operational state. On the to-do list is this functionality that will interweave and schedule SDO traffic with PDO traffic.

If SDO_xxx is used in operational context is must be on a rt-task (either the PDO rt-task or a separate rt-task). And on the same CPU. Also all NIC-irqs must reside on the same CPU as the PDO rt-task.

For a reminder how complex the Tx and Rx path for the NIC are see: https://blog.packagecloud.io/eng/2016/06/22/monitoring-tuning-linux-networking-stack-receiving-data https://blog.packagecloud.io/eng/2017/02/06/monitoring-tuning-linux-networking-stack-sending-data

The fact you set a parameter with ethtool does not mean the NIC driver will comply. So double check the behavior in the NIC driver.

At least I want to see an explanation why the system would delay by 2000us before committing any solution to SOEM.

[nakarlsson]

Second that last statment, 2ms is a long time, like the non-rt task would mutually exclusive lock the NIC until it is finished.

[tecodrive]

Disable iqr throttling in nic is important to receive frame with lowest latency and get stable rt-task.

i use ubuntu 18.04 with one isolated cpu, move the nic irqs to the isolated cpu and trim the nic with ethtool.

Wireshark=> SDO_xxx send minimum 5 frames (4x FPRD, 1xFPWR)

Time between send and receive of one pdo frame ~25us (timestamp). In rt-task measured ~ 34us.

The rt-cylcetime 250us.

Every frame trigger one irq with disabled irq throttling. Every single frame is transferred separately by the kernel network stack (DMA, skb, ...) with all overhead. The network driver ( igb ) will block by page faults and can lost frames, when the irq flag is not cleared by the driver or by ringbuffer overflow of the nic driver.

The Problem can resolve with a delay of >~25us + ~15us between the frames. But that delay can not be ensured if two tasks access the interface. With a delay of osal_usleep(1000us) in the ecx_srconfirm function between outframe & inframe the problem can solved.

Has anyone tried to use sdo when pdo is running with cycletime of 250us and measure the latency?

Without osal_usleep => use one sdo after one pdo_tx/pdo_rx in the same task on the isolated cpu with a rt-cycletime of 250us was not successfully. One SDO_xxx need ~70us in the rt-task. When start/configure the ethercat in the non-rt-task, the rt-task with included one sdo_xxx after pdo_tx + pdo_rx, the pll's of slaves will not sync. The non-rt-task send sdo_xxx to configure ethercat while pdo transfer is started to sync pll's before op state.

With cycletime of 1000us, latency < 50us all is ok, when running SDO_xxx  and PDO (rt-task) on the same isolated CPU without osal_usleep.

Am 07.05.2018 um 22:47 schrieb ArthurKetels:

First, thanks tecodrive for your in depth explanation of the observed behavior. It shows good knowledge about the intricacies of multi processor programming and the linux network stack.

If have not seen any behavior int the linux network stack that prevents sending packets at a fast rate. At the point that it should not be possible to create bottlenecks at rated line speeds of 100mb/s. At most you create interrupts at a rate of 200kirq/s.

I think there is another mechanism that prevents the cooperation between the rt and non-rt task.

First I must note that the SDO_xxx functions are not intended to be used in operational state. On the to-do list is this functionality that will interweave and schedule SDO traffic with PDO traffic.

If SDO_xxx is used in operational context is must be on a rt-task (either the PDO rt-task or a separate rt-task). And on the same CPU. Also all NIC-irqs must reside on the same CPU as the PDO rt-task.

For a reminder how complex the Tx and Rx path for the NIC are see: https://blog.packagecloud.io/eng/2016/06/22/monitoring-tuning-linux-networking-stack-receiving-data https://blog.packagecloud.io/eng/2017/02/06/monitoring-tuning-linux-networking-stack-sending-data

The fact you set a parameter with ethtool does not mean the NIC driver will comply. So double check the behavior in the NIC driver.

At least I want to see an explanation why the system would delay by 2000us before committing any solution to SOEM.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/OpenEtherCATsociety/SOEM/issues/171#issuecomment-387201247, or mute the thread https://github.com/notifications/unsubscribe-auth/AYAodeDLTT46_MX05Z-hFL9NSu86R5iyks5twLLLgaJpZM4TfFGz.

[tecodrive]

The problem / block time lies in the kernel => rcu (read copy update).

Von: nakarlsson notifications@github.com Gesendet: Dienstag, 8. Mai 2018 20:34 An: OpenEtherCATsociety/SOEM SOEM@noreply.github.com Cc: tecodrive marthiens@tecodrive.com; Author author@noreply.github.com Betreff: Re: [OpenEtherCATsociety/SOEM] ec_SDOwrite ec_SDOread from non-rt-thread disturb the latency in rt-thread (#171)

Second that last statment, 2ms is a long time, like the non-rt task would mutually exclusive lock the NIC until it is finished.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/OpenEtherCATsociety/SOEM/issues/171#issuecomment-387499730 , or mute the thread https://github.com/notifications/unsubscribe-auth/AYAodRb5Zn0R1haGLKVlPy13n2d36Ju7ks5tweUugaJpZM4TfFGz . https://github.com/notifications/beacon/AYAodfa76HuuHMrJeshVcnDfNxuj_OSTks5tweUugaJpZM4TfFGz.gif

[nakarlsson]

@ArthurKetels have the final call here. My main concern is the big API change of a new parameter to ecx_srconfirm and it is not a lot of bang for the buck on most systems. Also, the parts affected is in the oshw, perhaps a fix can be made in a separate oshw layer?

[ArthurKetels]

Looking at commit #194 I wonder if this solves your problem? The 2000us seems like one schedule jiffy on a stock linux kernel (500Hz). There are three mutexes used in the low level SOEM code. The one most likely to hit is the Rx mutex. If ecx_srconfirm is triggered in the SDO function and at that moment the high priority SDO transfer kicks in it is blocked by this mutex. It only resolves after a new schedule event (taking up to 2+ms). The patch mentioned above should solve this priority inversion problem.

[tecodrive]

I've tested, but after some seconds I got a wkc error. Unfortunately, it does not solve the problem.

[Wanga]

I got similar issue, the network setting and task isolating mentioned in this thread are applied. When only task A calls send/receive process data every 1ms, timing is perfect. But after task B join and call ec_readstate every 500ms, sometimes ec_receive_processdata() in task A doesn't return for 0.4~1ms.

The result of some time measurements show the function doesn't return is recv() in ecx_recvpkt(). It seems that SO_RCVTIMEO got some extra delay in this case (multiple recv()?.

Linux kernel uses schedule_timeout() for timeout in recv(), which has lower resolution. But select() uses schedule_hrtimeout(), so I change recv to select()->recv(). Then the the latency in recv improved.

Related discussion: Nano/Microsecond resolution for select() and poll() [enable high resolution timer mode to timeout datagram sockets]()

diff --git a/oshw/linux/nicdrv.c b/oshw/linux/nicdrv.c
index c58a9a1..52cf066 100644
--- a/oshw/linux/nicdrv.c
+++ b/oshw/linux/nicdrv.c

@@ -145,10 +144,9 @@ int ecx_setupnic(ecx_portt *port, const char *ifname, int secondary)
    /* we use RAW packet socket, with packet type ETH_P_ECAT */
    *psock = socket(PF_PACKET, SOCK_RAW, htons(ETH_P_ECAT));

-   timeout.tv_sec =  0;
-   timeout.tv_usec = 1;
-   r = setsockopt(*psock, SOL_SOCKET, SO_RCVTIMEO, &timeout, sizeof(timeout));
-   r = setsockopt(*psock, SOL_SOCKET, SO_SNDTIMEO, &timeout, sizeof(timeout));
+   int flags = 0;
+   fcntl(*psock, F_SETFL, flags | O_NONBLOCK);
+
    i = 1;
    r = setsockopt(*psock, SOL_SOCKET, SO_DONTROUTE, &i, sizeof(i));
    /* connect socket to NIC by name */
@@ -329,8 +327,11 @@ int ecx_outframe_red(ecx_portt *port, int idx)
  */
 static int ecx_recvpkt(ecx_portt *port, int stacknumber)
 {
-   int lp, bytesrx;
+   int lp, bytesrx = 0;
    ec_stackT *stack;
+   struct timeval tv;
+   fd_set readfds;
+   int rv = 0;

    if (!stacknumber)
    {
@@ -341,7 +342,26 @@ static int ecx_recvpkt(ecx_portt *port, int stacknumber)
       stack = &(port->redport->stack);
    }
    lp = sizeof(port->tempinbuf);
-   bytesrx = recv(*stack->sock, (*stack->tempbuf), lp, 0);
+
+   FD_ZERO(&readfds);
+   FD_SET(*stack->sock, &readfds);
+   tv.tv_sec = 0;
+   tv.tv_usec = 1;
+
+   rv = select(*stack->sock+1, &readfds, NULL, NULL, &tv);
+   if( rv < 0 )
+   {
+      printf ("NG!!!\n");
+   }
+   else if ( rv == 0 )
+   {
+      /* Polling... */
+   }
+   else
+   {
+      bytesrx = recv(*stack->sock, (*stack->tempbuf), lp, MSG_DONTWAIT );
+   }
+

[ArthurKetels]

I have made a test setup according to your specs. The only difference is that I adapted red_test in the SOEM test suite. 250us cycle time for the PDO at real time priority (but lower than system interrupts). 10ms cycle time for SDOread in a non real time thread at default priority. Ubuntu 18.04 with 4.16 preempt-rt kernel. Latest SOEM. Instead of busy waiting using clock_nanosleep.

First thing noted is that setting ethtool rx-usecs 0 rx-usecs 0 does not work any-more. With my nic driver the minimum working values are 2 for each of them. I could reproduce the 0.4 to 2.5ms latency peaks. Removing the 10ms SDOread also gets rid of the latency spikes. Average latency around 20us.

Adding above patch with select() does not change the behaviour. Adding patch #199 also makes no noticeable difference.

Then I changed the order of transmit and receivepdo in the 250us task. For efficiency the standard approach is to do the receivepdo first and at the end of the cycle do transmitpdo. The idea is that the real time task does not have to spend time waiting for the frame to be received.

However when the order is reversed and at the start of the 250us task first the transmitpdo and directly after the receivepdo is placed the latency spikes are gone. It seems like when the real-time task ends the frame is not yet send by the nic driver, and somehow the priority is lowered.

[Wanga]

Isn't using rx-tx instead of tx-rx lost the benefit of using EtherCAT...? For the assumption "when the real-time task ends the frame is not yet send by the nic driver", could you confirm by"perf sched timehist"?

In my case, net-irq-rx happens just like normal case when latency on PDO task occur, it just doesn't wake up the correct task. But if this is related to #200, we should always have a PDO frame timeout and get wkc = -1, but the weird part is it just have extra latency.

Another thing maybe might be useful is, if the application uses realtime thread, it's better to check net-irq's priority, the priority inversion could happen when threaded interpreter's priority is relatively low in the system.

ps -eo rtprio,comm
    50 irq/28-net0-rx-
    50 irq/29-net0-tx-
    50 irq/30-net0

    1828.145811 [0000]  pdo_updating_task      0.672      0.005      0.028  next: swapper/0[0]            
    1828.145861 [0000]  irq/40-net0-tx-[619]   0.956      0.003      0.006  next: swapper/1[0]            
    1828.145937 [0000]  swapper                                             awakened: irq/39-net0-rx-[618]
    1828.145943 [0000]  <idle>                 0.042      0.000      0.131  next: irq/39-net0-rx-[618]    
    1828.145955 [0000]  irq/39-net0-rx-[618]                                awakened: ec_readstate_task
    1828.145965 [0000]  irq/39-net0-rx-[618]   0.843      0.005      0.022          
    1828.145981 [0000]  ec_readstate_task                                   
    ...
    1828.147016 [0000]  ktimersoftd/0[4]                                    awakened: pdo_updating_task
    1828.147019 [0000]  ktimersoftd/0[4]       0.873      0.004      0.009  next: pdo_updating_task        
    1828.147026 [0000]  pdo_updating_task      0.997      0.002      0.006         

[tecodrive]

what does your hardware look like? CPU Type, CPU Cache Size, NIC Chip Type, Motherboard, Video Card, Ubuntu Server or Desktop, Headless or Monitor, Preempt Patch Applied to Kernel Sources of Linus or Ubuntu (Mainline Kernel or Ubuntu Patched Kernel), Hyperthreading on / off

Am 22. August 2018 12:10:20 MESZ schrieb ArthurKetels notifications@github.com:

I have made a test setup according to your specs. The only difference is that I adapted red_test in the SOEM test suite. 250us cycle time for the PDO at real time priority (but lower than system interrupts). 10ms cycle time for SDOread in a non real time thread at default priority. Ubuntu 18.04 with 4.16 preempt-rt kernel. Latest SOEM. Instead of busy waiting using clock_nanosleep.

First thing noted is that setting ethtool rx-usecs 0 rx-usecs 0 does not work any-more. With my nic driver the minimum working values are 2 for each of them. I could reproduce the 0.4 to 2.5ms latency peaks. Removing the 10ms SDOread also gets rid of the latency spikes. Average latency around 20us.

Adding above patch with select() does not change the behaviour. Adding patch #199 also makes no noticeable difference.

Then I changed the order of transmit and receivepdo in the 250us task. For efficiency the standard approach is to do the receivepdo first and at the end of the cycle do transmitpdo. The idea is that the real time task does not have to spend time waiting for the frame to be received.

However when the order is reversed and at the start of the 250us task first the transmitpdo and directly after the receivepdo is placed the latency spikes are gone. It seems like when the real-time task ends the frame is not yet send by the nic driver, and somehow the priority is lowered.

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/OpenEtherCATsociety/SOEM/issues/171#issuecomment-414982618

-- Diese Nachricht wurde von meinem Android-Gerät mit K-9 Mail gesendet.

[mwh-newtec]

One SDO_xxx need ~70us in the rt-task.

@tecodrive: Could you please elaborate on this part? Can you perform a SDO_write/SDO_read in 70µs?

[nakarlsson]

can we close this?

[tecodrive]

Yes

Am 9. März 2020 08:44:35 MEZ schrieb nakarlsson notifications@github.com:

can we close this?

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/OpenEtherCATsociety/SOEM/issues/171#issuecomment-596376157

-- Diese Nachricht wurde von meinem Android-Gerät mit K-9 Mail gesendet.