Excessive network latency when using Realtek R8168/R8111 et al NIC

Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

Hi guys,
I hope this is the right place to report an issue

We are linuxcnc users and as such we are long term users of PREEMPT_RT
on x86 (and some other platforms)

A number of PC's in use by our members have recently been experiencing
excessive Real Time network latency since the 5.10 kernel and above.

We are excited to see this seems to have been mostly resolved with the
6.3 kernel compiled from patched kernel.org source.

But we are also experiencing excessive Real time network latency on
some NIC hardware, mostly with  Realtek NIC's in this list.

https://www.realtek.com/en/component/zoo/category/network-interface-controllers-10-100-1000m-gigabit-ethernet-pci-express-software
Many modern industrial PC's are using Realtek NIC drivers that cannot
be changed out so this is a problem for us.

It's our understanding that the R8169 kernel driver module should
provide support for this hardware. It does indeed do this but real
time network latency is unacceptable. Debian offers  a R8168-dkms
driver.  I understand it is being deprecated in favor of the R8169
kernel module driver.

Installing the R8168-dkms driver on the 6.3 kernel improves RT network
latency/jitter by 400% over the R8169 driver.

We are users not kernel developers. How can we escalate this issue so
acceptable RT performance is restored?

end
-Regards
-Rod Webster

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Sebastian Andrzej Siewior]

On 2023-04-18 13:23:12 [+1000], Rod Webster wrote:
> Hi guys,
Hi,

> A number of PC's in use by our members have recently been experiencing
> excessive Real Time network latency since the 5.10 kernel and above.

Are you using the Preempt-RT patches?

> We are excited to see this seems to have been mostly resolved with the
> 6.3 kernel compiled from patched kernel.org source.

This would suggest you do not.

> But we are also experiencing excessive Real time network latency on
> some NIC hardware, mostly with  Realtek NIC's in this list.
> 
> https://www.realtek.com/en/component/zoo/category/network-interface-controllers-10-100-1000m-gigabit-ethernet-pci-express-software
> Many modern industrial PC's are using Realtek NIC drivers that cannot
> be changed out so this is a problem for us.
> 
> It's our understanding that the R8169 kernel driver module should
> provide support for this hardware. It does indeed do this but real
> time network latency is unacceptable. Debian offers  a R8168-dkms
> driver.  I understand it is being deprecated in favor of the R8169
> kernel module driver.
> 
> Installing the R8168-dkms driver on the 6.3 kernel improves RT network
> latency/jitter by 400% over the R8169 driver.
> 
> We are users not kernel developers. How can we escalate this issue so
> acceptable RT performance is restored?

First we need to figure out if you are using PREEMPT_RT patchset and if
the problem is related to that. Depending on that we can try to analyse
it further.
If you do not use them and you started to experience the problem
starting v5.10 and only with that NIC it might be related to some
optimisations that this NIC is doing and the driver might have enabled
in v5.10 for instance. This might be batching of RX packets which can be
configured with ethtool (look for "coalesce").

> end
> -Regards
> -Rod Webster

Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Sebastian Andrzej Siewior]

On 2023-04-28 20:46:17 [+1000], Rod Webster wrote:
> Sebastian
Hi Rod,

please keep list in Cc: Avoiding top-posting is a quite nice.

> Thanks, the Real TIme PREEMPT_RT kernel is a prerequisite for
> Linuxcnc. Note in this discussion, I am only referring to X86 machines

Okay. Then it could be related to softirq rework which started in
v5.0.19-rt11 and updated in v5.9-rc6-rt9. 

Are you able to recompile a kernel?

> although we also install our software on ARM and others.
> linuxcnc-uspace is included in the debian Bookworm repositories and
> linux-image-rt  is one of its dependencies..
> There are really two issues we have experienced. These have only
> become a factor since the 5.X kernels. Only one seems to be relevant
> to the RT project.
> 1. Excessive real time latency/jitter in the Debian RT images. I have
> escalated this to them on their Bug 1034550. Ref
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1034550

As mentioned, the images are provided for convince. Depending one the
problem, the bugs are forwarded sometimes here.

However as per you Debian bug report v4.19-RT is fine, v5.10-RT isn't
and v6.1-RT is better or is it fine?

> 2. Excessive real time network latency/jitter when using the
> PREEMPT_RT kernel when communicating with Intel ethernet hardware in
> an RT environment.

Where is the Intel ethernet coming from? You were saying it is the
realtek nic.

> It is the second issue I wish to bring to your attention.  eg.
> Excessive network latency. This appears to be more prevalent on
> Realtek hardware.
> Note that we document setting hardware-irq-coalesce-rx-usecs 0 on
> Intel NIC's is required. This setting has no effect on other makes of
> NIC's.
> 
> In relation to Realtek NIC's, I can only speak for Debian but by
> default they use the R8169 Kernel module. (CONFIG_R8169?) They also
> offer the R8168-dkms and R8125-dkms drivers. We have many data points
> from our users that the R8169 driver offers very poor  RT performance.
> But just installing a dkms driver is not enough on Debian to resolve
> the issue.

Is the vendor driver better than in the tree? This is not obvious from
what you are writing.

> We need to also build a RT kernel from the upstream sources and apply
> your RT patches.
> 
> So aside from the awful high latency/jitter implementation of  RT by
> Debian since the 5.10 kernel (Bookworm), the current strategy to use
> the R8169 as a generic driver is flawed. Debian says to report any use
> of the R8168-dkms driver and they will fix it.
> 
> A lot of small industrial PC's use Realtek NIC and with the pending
> release of Bookworm now Linuxcnc is in its repos, there will be a wide
> ranging impact.
> 
> Our FGPA ethernet hardware is capable of reporting maximum ethernet
> read and write times in timer ticks and is used in a point to point
> connection (no routers).
> 
> I hope you can investigate this matter.

I am surprised to hear the vendor driver is doing fine while the in-tree
driver is bad.

Two things you could do:
- enabling tracing to see what is causing the delays/ latency spike. You
  will need a trigger to notice the latency and then stop the trace at
  this point. If so, I could provide additional steps unless you can do
  it yourself.

- You could try to isolate the realtek driver on one CPU and moving
  everything else to another.

> end
> -Rod Webster
> 
> 
> 
> Rod Webster
> 
> VMN®
> 
> www.vmn.com.au

Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

[-- Attachment #1: Type: text/plain, Size: 2338 bytes --]

> Okay. Then it could be related to softirq rework which started in
> v5.0.19-rt11 and updated in v5.9-rc6-rt9.
v5.9 could also be significant as the R8125 driver support was added
in that version
I upgraded from Debian Buster to Bullseye (v5.10) on one PC for this reason.

> Are you able to recompile a kernel?
Yes,
I have attached a text file containing my 6.3 build steps.
Note we had to git pull the kernel source as it was not available via
http at that time
I have not tried with your 6.3-rc11 patch yet.

> However as per you Debian bug report v4.19-RT is fine, v5.10-RT isn't
> and v6.1-RT is better or is it fine?
I built v6.1-rc7-rt5 before Debian advanced to v6.1
It was reported to be an improvement and it solved the Debian latency
issue for some users.
v6.3 was reported as being as good as the 4.x kernes by our hardware vendor

> Where is the Intel ethernet coming from? You were saying it is the
> realtek nic.
Sorry, you mentioned coalesce but that's an Intel feature and does not
exist with Realtek.

> Is the vendor driver better than in the tree? This is not obvious from
> what you are writing.
I have been unable to compile the R8168 driver from source on the
Realtek website.
They are behind with supported kernels and the build process is
invariably broken for me.
On the Hardkernel Odroid forum, it has been reported that compilng the
R8125 from Realtek source offers 15-35% improvement over the in-tree
driver.
 I have one of their  PC's (H2+). It's currently running v5.10 and the
in-tree R8168 driver (which must be the Debian default).
 It is affected and I plan to upgrade to v6.3 with the R8125-dkms driver

> Two things you could do:
> - enabling tracing to see what is causing the delays/ latency spike. You
>   will need a trigger to notice the latency and then stop the trace at
>   this point. If so, I could provide additional steps unless you can do
>   it yourself.
Please advise additional steps to do this.
We might  be able to modify our hardware device driver to stop the
trace as it reports latency incursions if they occur.

> - You could try to isolate the realtek driver on one CPU and moving
>   everything else to another.
This sounds interesting. Please advise how.
On a 4 core machine we typically add isolcpus=2,3 for best RT performance.

Thanks for your support.

-end
-Rod Webster

[-- Attachment #2: Instructions.txt --]
[-- Type: text/plain, Size: 1046 bytes --]

apt update 
sudo apt install -y build-essential bin86 libncurses5-dev pkg-config libssl-dev dwarves bison flex gnupg libelf-dev libssl-dev wget qtbase5-dev debhelper rsync git
mkdir rtlinux 
cd rtlinux 
git clone -b v6.3-rc5 --depth 1 https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git linux-6.3-rc5 
wget https://mirrors.edge.kernel.org/pub/linux/kernel/projects/rt/6.3/patch-6.3-rc5-rt8.patch.gz gunzip patch-6.3-rc5-rt8.patch.gz 
cp patch-6.3-rc5-rt8.patch linux-6.3-rc5 
cd linux-6.3-rc5 
cat patch-6.3-rc5-rt8.patch | patch -p1 
make xconfig 
#Set the following: General Settings/Preemption model = Fully Preemptible Kernel
#Save then exit (Click on General settings and select option on the right side.


# These keys override security and key settings to allow .debs to be built
scripts/config --disable SYSTEM_REVOCATION_KEYS 
scripts/config --disable DEBUG_INFO 
scripts/config --enable DEBUG_INFO_NONE 
scripts/config --set-str SYSTEM_TRUSTED_KEYS "" 
make -j$(nproc) deb-pkg LOCALVERSION=-linuxcnc

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

I've had some feedback from a hardware supplier.
The Linuxcnc RT ethernet driver has a pin that reports ethernet packet
error count.
This increments when the ethernet response exceeds our real time servo
thread period (typically 1 ms)
We should be able to monitor this pin and stop the trace if it is >  0
without too much effort.
So let me know the next steps and I'll try and implement a trace test.

- Rod



Rod Webster

VMN®

www.vmn.com.au

Ph: 1300 896 832

Mob: +61 435 765 611




On Sat, 29 Apr 2023 at 07:37, Rod Webster <rod@vmn.com.au> wrote:
>
> > Okay. Then it could be related to softirq rework which started in
> > v5.0.19-rt11 and updated in v5.9-rc6-rt9.
> v5.9 could also be significant as the R8125 driver support was added
> in that version
> I upgraded from Debian Buster to Bullseye (v5.10) on one PC for this reason.
>
> > Are you able to recompile a kernel?
> Yes,
> I have attached a text file containing my 6.3 build steps.
> Note we had to git pull the kernel source as it was not available via
> http at that time
> I have not tried with your 6.3-rc11 patch yet.
>
> > However as per you Debian bug report v4.19-RT is fine, v5.10-RT isn't
> > and v6.1-RT is better or is it fine?
> I built v6.1-rc7-rt5 before Debian advanced to v6.1
> It was reported to be an improvement and it solved the Debian latency
> issue for some users.
> v6.3 was reported as being as good as the 4.x kernes by our hardware vendor
>
> > Where is the Intel ethernet coming from? You were saying it is the
> > realtek nic.
> Sorry, you mentioned coalesce but that's an Intel feature and does not
> exist with Realtek.
>
> > Is the vendor driver better than in the tree? This is not obvious from
> > what you are writing.
> I have been unable to compile the R8168 driver from source on the
> Realtek website.
> They are behind with supported kernels and the build process is
> invariably broken for me.
> On the Hardkernel Odroid forum, it has been reported that compilng the
> R8125 from Realtek source offers 15-35% improvement over the in-tree
> driver.
>  I have one of their  PC's (H2+). It's currently running v5.10 and the
> in-tree R8168 driver (which must be the Debian default).
>  It is affected and I plan to upgrade to v6.3 with the R8125-dkms driver
>
> > Two things you could do:
> > - enabling tracing to see what is causing the delays/ latency spike. You
> >   will need a trigger to notice the latency and then stop the trace at
> >   this point. If so, I could provide additional steps unless you can do
> >   it yourself.
> Please advise additional steps to do this.
> We might  be able to modify our hardware device driver to stop the
> trace as it reports latency incursions if they occur.
>
> > - You could try to isolate the realtek driver on one CPU and moving
> >   everything else to another.
> This sounds interesting. Please advise how.
> On a 4 core machine we typically add isolcpus=2,3 for best RT performance.
>
> Thanks for your support.
>
> -end
> -Rod Webster

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Sebastian Andrzej Siewior]

On 2023-04-29 07:37:25 [+1000], Rod Webster wrote:
Sorry for the break.

> > Is the vendor driver better than in the tree? This is not obvious from
> > what you are writing.
> I have been unable to compile the R8168 driver from source on the
> Realtek website.
> They are behind with supported kernels and the build process is
> invariably broken for me.
> On the Hardkernel Odroid forum, it has been reported that compilng the
> R8125 from Realtek source offers 15-35% improvement over the in-tree
> driver.
>  I have one of their  PC's (H2+). It's currently running v5.10 and the
> in-tree R8168 driver (which must be the Debian default).
>  It is affected and I plan to upgrade to v6.3 with the R8125-dkms driver

That is interesting. 15%-35% improvement for the in-tree driver would be
certainly welcomed. :)

> > Two things you could do:
> > - enabling tracing to see what is causing the delays/ latency spike. You
> >   will need a trigger to notice the latency and then stop the trace at
> >   this point. If so, I could provide additional steps unless you can do
> >   it yourself.
> Please advise additional steps to do this.
> We might  be able to modify our hardware device driver to stop the
> trace as it reports latency incursions if they occur.

Either with a tool like trace-cmd or manual.
- trace-cmd
  - Enable events:
    trace-cmd start -e sched:* -e irq:* -e irq_vectors:*
  - Start the test
  - Once the error happens, stop the trace
    trace-cmd stop
  - Extract the trace
    trace-cmd extract
  - The command produces a trace.dat file. It can viewed in text via
    "trace-cmd report" or kernelshark.
  - Disable the events
    trace-cmd reset

- Manual
  - Enable events
    cd /sys/kernel/debug/tracing/
    echo 1 > events/sched/enable
    echo 1 > events/irq/enable
    echo 1 > events/irq_vectors/enable
  - Start the test
  - Once the error happens, stop the trace (assume you are still in the
    previous folder)
    echo 0 > tracing_on
  - Extract the trace
    cat trace > ~/trace.txt
  - The average editor can be used.
  - Disable the events (and reset).
    echo 0 > events/enable
    echo 1 > tracing_on

> > - You could try to isolate the realtek driver on one CPU and moving
> >   everything else to another.
> This sounds interesting. Please advise how.
> On a 4 core machine we typically add isolcpus=2,3 for best RT performance.

So this isolcpus CPU thingy is already going in that direction. If you
have two NICs, say one with RT traffic and one without, then the RT
traffic should go the RT CPUs while the non-RT traffic to the non-RT
CPUs. The isolcpus option works only for tasks. You should do the same
interrupts. See the irqaffinity option.
Lets first look at the trace and what the problem is and what can be
done…

> Thanks for your support.
> 
> -end
> -Rod Webster

Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Sebastian Andrzej Siewior]

On 2023-05-18 20:15:20 [+1000], Rod Webster wrote:
> Sebastian,
Hi Rod,

> I have cc'd Marcelo here as he has offered to help.
> 
> I am attaching the last 1000 lines or so of our trace (I hope
> attachments are allowed)
> 
> Our bash script to terminate the trace was called PacketErrorTest. It
> loops until the hardware reports a packet error.
> The script contains:
> #!/usr/bin/bash
> stat=0
> while (($stat < 1))
> do
> stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> done
> trace-cmd stop
> 
> I must say we have no idea what we are looking at but can't see
> anything obvious to a layperson.
> Please advise next steps

I don't see much wrong here. Maybe the trace isn't long enough.
However what I saw is that your networking interrupt isn't threaded and
then all networking is outsourced to ksoftirqrd which might get less
processing time if there is much going on.
It would help if you enable NAPI threads: As root, please do

	echo 1 > /sys/class/net/enp2s0/threaded

This will spawn a few threads named "napi/enp2s0-$napi_id. The
actual number of threads depends on the number of NAPI instances
(usually queues) used by the driver.
Once you identified them, please pin them the right CPU and adjust the
priority:
	taskset -pc 2 $pid
	chrt -p -f 50 $pid

The taskset command will pin the NAPI thread to CPU2. This is what I see
in your trace where the interrupt is active. It is good to have them
(the interrupt and the interrupt thread or the NAPI thread in your
case) running on the same CPU. The chrt will adjust the priority of the
thread from SCHED_OTHER to a SCHED_FIFO priority 50.

By default all interrupt threads run at priority 50 (middle priority).
They get preferred over all tasks with lower priority including
SCHED_OTHER tasks. SCHED_OTHER (the default scheduling class) tasks get
preempted once they used their time slice so that they don't lock up the
system. This isn't the case with SCHED_FIFO.

This realtek/r8169 driver is not using interrupts threads in your
configuration. While I don't see any API breakage I am rethinking the
whole softirq concept and moving to NAPI threads might not be that bad.
Be aware that _now_ you don't have any "overloading" concept. I.e. what
should be done if the system is receiving a lot of packages that it
didn't ask for (say ping flood or so). Before this change, the NAPI
would hand over to ksoftirqd running at SCHED_OTHER so it would be
balanced with other tasks within the system.

An explanation of the trace you sent:
|  PacketErrorTest-2552  [002]   191.050337: irq_handler_entry:    irq=125 name=enp2s0
   Running Task          <CPU>               Interrupt occurred    network card

|  PacketErrorTest-2552  [002]   191.050339: softirq_raise:        vec=3 [action=NET_RX]
|  PacketErrorTest-2552  [002]   191.050339: irq_handler_exit:     irq=125 ret=handled
|  PacketErrorTest-2552  [002]   191.050340: sched_waking:         comm=ksoftirqd/2 pid=37 prio=120 target_cpu=002
|  PacketErrorTest-2552  [002]   191.050343: sched_wakeup:         ksoftirqd/2:37 [120] CPU:002

It scheduled NAPI (NET_RX) which is processed in softirq. Since this
happened in hardirq context ("trace-cmd report -l" would reveal that) it
wakes ksoftirqd for the processing.

|  PacketErrorTest-2552  [002]   191.050344: sched_stat_runtime:   comm=PacketErrorTest pid=2552 runtime=587973 [ns] vruntime=15925574432 [ns]
|  PacketErrorTest-2552  [002]   191.050346: sched_switch:         PacketErrorTest:2552 [120] R ==> ksoftirqd/2:37 [120]
|      ksoftirqd/2-37    [002]   191.050347: softirq_entry:        vec=3 [action=NET_RX]
|      ksoftirqd/2-37    [002]   191.050351: softirq_exit:         vec=3 [action=NET_RX]

Here receiving of network packets is completed. Timing wise,
191.050351 - 191.050337 = 14us after the interrupt triggered. Looking
through the whole file, it ranges from 6us to 14us (17 samples).
So it doesn't look bad. If processing would get preempted and would need
a few millisecond then it would be bad.

> Rod Webster
> 
> VMN®
> 
> www.vmn.com.au

Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

There is something weird going on, I have an i5 PC with R8111 NIC
which was problematic until I installed the R8168-dkms driver and the
6.3 kernel I compiled. It regularly threw packet errors on a RT thread
that fires every 1 ms.
I wanted to revert it so I could do these tests.
So I purged  the R8168-dkms driver to revert to the R8169 and rolled
back to a Debian 6.1 RT kernel. It's still running isolcpus=2,3
The darn thing refused to generate a packet error until I dropped the
thread timing to fire every 0.15 ms.
So it seems the process of installing and uninstalling has changed the
driver environment.
I do recall having something similar accidentally happen to another PC
once before.  I think it was related to the install and uninstall of
the 8168-dkms driver.
Any ideas what could be going on?

I will do some testing tomorrow now I know what's going on but I
wonder how relevant it will be given this turnaround?


Rod Webster





Rod Webster

VMN®

www.vmn.com.au

Ph: 1300 896 832

Mob: +61 435 765 611




On Fri, 19 May 2023 at 18:37, Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
>
> On 2023-05-18 20:15:20 [+1000], Rod Webster wrote:
> > Sebastian,
> Hi Rod,
>
> > I have cc'd Marcelo here as he has offered to help.
> >
> > I am attaching the last 1000 lines or so of our trace (I hope
> > attachments are allowed)
> >
> > Our bash script to terminate the trace was called PacketErrorTest. It
> > loops until the hardware reports a packet error.
> > The script contains:
> > #!/usr/bin/bash
> > stat=0
> > while (($stat < 1))
> > do
> > stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> > done
> > trace-cmd stop
> >
> > I must say we have no idea what we are looking at but can't see
> > anything obvious to a layperson.
> > Please advise next steps
>
> I don't see much wrong here. Maybe the trace isn't long enough.
> However what I saw is that your networking interrupt isn't threaded and
> then all networking is outsourced to ksoftirqrd which might get less
> processing time if there is much going on.
> It would help if you enable NAPI threads: As root, please do
>
>         echo 1 > /sys/class/net/enp2s0/threaded
>
> This will spawn a few threads named "napi/enp2s0-$napi_id. The
> actual number of threads depends on the number of NAPI instances
> (usually queues) used by the driver.
> Once you identified them, please pin them the right CPU and adjust the
> priority:
>         taskset -pc 2 $pid
>         chrt -p -f 50 $pid
>
> The taskset command will pin the NAPI thread to CPU2. This is what I see
> in your trace where the interrupt is active. It is good to have them
> (the interrupt and the interrupt thread or the NAPI thread in your
> case) running on the same CPU. The chrt will adjust the priority of the
> thread from SCHED_OTHER to a SCHED_FIFO priority 50.
>
> By default all interrupt threads run at priority 50 (middle priority).
> They get preferred over all tasks with lower priority including
> SCHED_OTHER tasks. SCHED_OTHER (the default scheduling class) tasks get
> preempted once they used their time slice so that they don't lock up the
> system. This isn't the case with SCHED_FIFO.
>
> This realtek/r8169 driver is not using interrupts threads in your
> configuration. While I don't see any API breakage I am rethinking the
> whole softirq concept and moving to NAPI threads might not be that bad.
> Be aware that _now_ you don't have any "overloading" concept. I.e. what
> should be done if the system is receiving a lot of packages that it
> didn't ask for (say ping flood or so). Before this change, the NAPI
> would hand over to ksoftirqd running at SCHED_OTHER so it would be
> balanced with other tasks within the system.
>
> An explanation of the trace you sent:
> |  PacketErrorTest-2552  [002]   191.050337: irq_handler_entry:    irq=125 name=enp2s0
>    Running Task          <CPU>               Interrupt occurred    network card
>
> |  PacketErrorTest-2552  [002]   191.050339: softirq_raise:        vec=3 [action=NET_RX]
> |  PacketErrorTest-2552  [002]   191.050339: irq_handler_exit:     irq=125 ret=handled
> |  PacketErrorTest-2552  [002]   191.050340: sched_waking:         comm=ksoftirqd/2 pid=37 prio=120 target_cpu=002
> |  PacketErrorTest-2552  [002]   191.050343: sched_wakeup:         ksoftirqd/2:37 [120] CPU:002
>
> It scheduled NAPI (NET_RX) which is processed in softirq. Since this
> happened in hardirq context ("trace-cmd report -l" would reveal that) it
> wakes ksoftirqd for the processing.
>
> |  PacketErrorTest-2552  [002]   191.050344: sched_stat_runtime:   comm=PacketErrorTest pid=2552 runtime=587973 [ns] vruntime=15925574432 [ns]
> |  PacketErrorTest-2552  [002]   191.050346: sched_switch:         PacketErrorTest:2552 [120] R ==> ksoftirqd/2:37 [120]
> |      ksoftirqd/2-37    [002]   191.050347: softirq_entry:        vec=3 [action=NET_RX]
> |      ksoftirqd/2-37    [002]   191.050351: softirq_exit:         vec=3 [action=NET_RX]
>
> Here receiving of network packets is completed. Timing wise,
> 191.050351 - 191.050337 = 14us after the interrupt triggered. Looking
> through the whole file, it ranges from 6us to 14us (17 samples).
> So it doesn't look bad. If processing would get preempted and would need
> a few millisecond then it would be bad.
>
> > Rod Webster
> >
> > VMN®
> >
> > www.vmn.com.au
>
> Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Sebastian Andrzej Siewior]

On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> I will do some testing tomorrow now I know what's going on but I
> wonder how relevant it will be given this turnaround?

I'm not going to look at the dkms/OOT driver. If there is an actual
problem or something odd with mainline and RT and I will look into it.
I managed to find an older box which is using the r8169 and I'm going to
boot and see if there the driver is doing something odd what I didn't
see earlier…

Please make sure that you are using the in-tree driver. If you
experience high latencies then I'm willing to help investigate.

> Rod Webster

Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

Yes, I won't be using a DKMS driver and will test with the in-tree driver.
I rolled a PC back to the Debian 6.1 RT kernel and the default in-tree
R8169 driver yesterday with isolcpus=2,3.

I had a shot at it last night with the napi thread but was confused by
the trace results so will try again.
I could not see our PacketErrorTest script appearing in the trace but
it stopped the trace when it should.
Also our RT process did not appear to be on an isolated thread which
seemed odd. I did not get as far as setting the affinity for napi.

I've also installed  Bookworm RC3 on another PC with the default RT
kernel on a Gigabyte Brix N3160 with an R8111/R8168 NIC and the
in-tree R8169 driver.
This PC historically had max latency of about 130000 ns  back with
kernel 4.x and now its reporting 23000 ns with the 6.1 kernel over 24
hours testing with the linuxcnc tools. Quite amazing what you guys
have achieved! It will be a few days before I can lug my hardware to
work to test on it as well for another data point.

I really appreciate your willingness to help. This remains a
frustrating issue for many Linuxcnc users who are using my compiled
6.3 kernel to get out of jail.
Bear with me as I bumble my way through!

Rod Webster





Rod Webster

VMN®

www.vmn.com.au

Ph: 1300 896 832

Mob: +61 435 765 611




On Mon, 22 May 2023 at 19:32, Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
>
> On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> > I will do some testing tomorrow now I know what's going on but I
> > wonder how relevant it will be given this turnaround?
>
> I'm not going to look at the dkms/OOT driver. If there is an actual
> problem or something odd with mainline and RT and I will look into it.
> I managed to find an older box which is using the r8169 and I'm going to
> boot and see if there the driver is doing something odd what I didn't
> see earlier…
>
> Please make sure that you are using the in-tree driver. If you
> experience high latencies then I'm willing to help investigate.
>
> > Rod Webster
>
> Sebastian

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Marcelo Tosatti]

On Mon, May 22, 2023 at 08:06:39PM +1000, Rod Webster wrote:
> Yes, I won't be using a DKMS driver and will test with the in-tree driver.
> I rolled a PC back to the Debian 6.1 RT kernel and the default in-tree
> R8169 driver yesterday with isolcpus=2,3.
> 
> I had a shot at it last night with the napi thread but was confused by
> the trace results so will try again.
> I could not see our PacketErrorTest script appearing in the trace but
> it stopped the trace when it should.

Rod,

Can you describe the PacketErrorTest script and how do you know, from
it, that latency has crossed the threshold? What was confusing about
the traces?

Earlier you wrote:
I've had some feedback from a hardware supplier.
The Linuxcnc RT ethernet driver has a pin that reports ethernet packet
error count.
This increments when the ethernet response exceeds our real time servo
thread period (typically 1 ms)
We should be able to monitor this pin and stop the trace if it is >  0
without too much effort.

So you are seeing that pin increase its value?

When you do, you should write to the "tracing_on" file (a zero):

        /*
         * if we're not tracing and the tracing_on fd is not open,
         * open the tracing_on file so that we can stop the trace
         * if we hit a breaktrace threshold
         */
        if (trace_fd < 0) {
                sprintf(path, "%s/%s", fileprefix, "tracing_on");
                if ((trace_fd = open(path, O_WRONLY)) < 0)
                        warn("unable to open tracing_on file: %s\n", path);
        }

        /* now stop any trace */
        write(trace_fd, "0\n", 2);

The trace file (/sys/kernel/debug/tracing/trace) should now contain
the trace up to the write to tracing_on file.

Sebastian: didnt see anything weird in the traces as well:

"Follows the delta between a list of timestamped events,
where each event is: "TIMESTAMP: rtapi is scheduled IN CPU-3"
(there is at one time only a single process scheduled in cpu-3).

[191.050245, 191.050278]: 0.000033
[191.050278, 191.050293]: 0.000015
[191.050293, 191.050307]: 0.000014
[191.050307, 191.050322]: 0.000015
[191.050322, 191.050336]: 0.000014

rtapi_app goes to sleep for approximately 15us, and is awakened
by a timer.

[191.050336, 191.050350]: 0.000014
[191.050350, 191.050365]: 0.000015
[191.050365, 191.050379]: 0.000014
[191.050379, 191.050393]: 0.000014
[191.050393, 191.050408]: 0.000015
[191.050408, 191.051243]: 0.000835
[191.051243, 191.051272]: 0.000029

It eventually sleeps for 800us (and this pattern repeats)".

Perhaps tracing the system call which sends out the packet would be
useful as well.

> Also our RT process did not appear to be on an isolated thread which
> seemed odd. I did not get as far as setting the affinity for napi.
> 
> I've also installed  Bookworm RC3 on another PC with the default RT
> kernel on a Gigabyte Brix N3160 with an R8111/R8168 NIC and the
> in-tree R8169 driver.
> This PC historically had max latency of about 130000 ns  back with
> kernel 4.x and now its reporting 23000 ns with the 6.1 kernel over 24
> hours testing with the linuxcnc tools. Quite amazing what you guys
> have achieved! It will be a few days before I can lug my hardware to
> work to test on it as well for another data point.
> 
> I really appreciate your willingness to help. This remains a
> frustrating issue for many Linuxcnc users who are using my compiled
> 6.3 kernel to get out of jail.
> Bear with me as I bumble my way through!
> 
> Rod Webster
> 
> 
> 
> 
> 
> Rod Webster
> 
> VMN®
> 
> www.vmn.com.au
> 
> Ph: 1300 896 832
> 
> Mob: +61 435 765 611
> 
> 
> 
> 
> On Mon, 22 May 2023 at 19:32, Sebastian Andrzej Siewior
> <bigeasy@linutronix.de> wrote:
> >
> > On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> > > I will do some testing tomorrow now I know what's going on but I
> > > wonder how relevant it will be given this turnaround?
> >
> > I'm not going to look at the dkms/OOT driver. If there is an actual
> > problem or something odd with mainline and RT and I will look into it.
> > I managed to find an older box which is using the r8169 and I'm going to
> > boot and see if there the driver is doing something odd what I didn't
> > see earlier…
> >
> > Please make sure that you are using the in-tree driver. If you
> > experience high latencies then I'm willing to help investigate.
> >
> > > Rod Webster
> >
> > Sebastian
> 
> 

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

This stuff is hard! I just realised that rtapi_app is a red herring!
rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
is on a 1000us cycle so it seems it gets all its jobs done in 200us
and then sleeps for 800us which makes perfect sense!

The issue we have is deeper than that. I think we should be looking at
the NIC interrupt (but don't trust the novice!).
The network communication is consuming more than the 800us slack from
time to time. When that happens, our hardware sees the timing overrun
and increments an internal packet error count. If too many of these
happen in succession, the hardware decides the RT environment can't be
relied on, disables further communication and returns an "error
finishing read" to Linuxcnc to say it's given up.

Marcelo, we didn't resort to C. We were able to use a bash script and
use a linuxcnc tool called halcmd to query the hardware as shown here.
#!/usr/bin/bash
stat=0
while (($stat < 1))
do
stat=`halcmd getp hm2_7i96s.0.packet-error-total`
done
trace-cmd stop

I think we need to increase the stat threshold  so we get more samples
in our trace before stopping it. The current trace will only have one
instance.
Thanks for letting me see the issue more clearly.


Rod Webster



Rod Webster

VMN®

www.vmn.com.au

Ph: 1300 896 832

Mob: +61 435 765 611




On Tue, 23 May 2023 at 03:13, Marcelo Tosatti <mtosatti@redhat.com> wrote:
>
> On Mon, May 22, 2023 at 08:06:39PM +1000, Rod Webster wrote:
> > Yes, I won't be using a DKMS driver and will test with the in-tree driver.
> > I rolled a PC back to the Debian 6.1 RT kernel and the default in-tree
> > R8169 driver yesterday with isolcpus=2,3.
> >
> > I had a shot at it last night with the napi thread but was confused by
> > the trace results so will try again.
> > I could not see our PacketErrorTest script appearing in the trace but
> > it stopped the trace when it should.
>
> Rod,
>
> Can you describe the PacketErrorTest script and how do you know, from
> it, that latency has crossed the threshold? What was confusing about
> the traces?
>
> Earlier you wrote:
> I've had some feedback from a hardware supplier.
> The Linuxcnc RT ethernet driver has a pin that reports ethernet packet
> error count.
> This increments when the ethernet response exceeds our real time servo
> thread period (typically 1 ms)
> We should be able to monitor this pin and stop the trace if it is >  0
> without too much effort.
>
> So you are seeing that pin increase its value?
>
> When you do, you should write to the "tracing_on" file (a zero):
>
>         /*
>          * if we're not tracing and the tracing_on fd is not open,
>          * open the tracing_on file so that we can stop the trace
>          * if we hit a breaktrace threshold
>          */
>         if (trace_fd < 0) {
>                 sprintf(path, "%s/%s", fileprefix, "tracing_on");
>                 if ((trace_fd = open(path, O_WRONLY)) < 0)
>                         warn("unable to open tracing_on file: %s\n", path);
>         }
>
>         /* now stop any trace */
>         write(trace_fd, "0\n", 2);
>
> The trace file (/sys/kernel/debug/tracing/trace) should now contain
> the trace up to the write to tracing_on file.
>
> Sebastian: didnt see anything weird in the traces as well:
>
> "Follows the delta between a list of timestamped events,
> where each event is: "TIMESTAMP: rtapi is scheduled IN CPU-3"
> (there is at one time only a single process scheduled in cpu-3).
>
> [191.050245, 191.050278]: 0.000033
> [191.050278, 191.050293]: 0.000015
> [191.050293, 191.050307]: 0.000014
> [191.050307, 191.050322]: 0.000015
> [191.050322, 191.050336]: 0.000014
>
> rtapi_app goes to sleep for approximately 15us, and is awakened
> by a timer.
>
> [191.050336, 191.050350]: 0.000014
> [191.050350, 191.050365]: 0.000015
> [191.050365, 191.050379]: 0.000014
> [191.050379, 191.050393]: 0.000014
> [191.050393, 191.050408]: 0.000015
> [191.050408, 191.051243]: 0.000835
> [191.051243, 191.051272]: 0.000029
>
> It eventually sleeps for 800us (and this pattern repeats)".
>
> Perhaps tracing the system call which sends out the packet would be
> useful as well.
>
> > Also our RT process did not appear to be on an isolated thread which
> > seemed odd. I did not get as far as setting the affinity for napi.
> >
> > I've also installed  Bookworm RC3 on another PC with the default RT
> > kernel on a Gigabyte Brix N3160 with an R8111/R8168 NIC and the
> > in-tree R8169 driver.
> > This PC historically had max latency of about 130000 ns  back with
> > kernel 4.x and now its reporting 23000 ns with the 6.1 kernel over 24
> > hours testing with the linuxcnc tools. Quite amazing what you guys
> > have achieved! It will be a few days before I can lug my hardware to
> > work to test on it as well for another data point.
> >
> > I really appreciate your willingness to help. This remains a
> > frustrating issue for many Linuxcnc users who are using my compiled
> > 6.3 kernel to get out of jail.
> > Bear with me as I bumble my way through!
> >
> > Rod Webster
> >
> >
> >
> >
> >
> > Rod Webster
> >
> > VMN®
> >
> > www.vmn.com.au
> >
> > Ph: 1300 896 832
> >
> > Mob: +61 435 765 611
> >
> >
> >
> >
> > On Mon, 22 May 2023 at 19:32, Sebastian Andrzej Siewior
> > <bigeasy@linutronix.de> wrote:
> > >
> > > On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> > > > I will do some testing tomorrow now I know what's going on but I
> > > > wonder how relevant it will be given this turnaround?
> > >
> > > I'm not going to look at the dkms/OOT driver. If there is an actual
> > > problem or something odd with mainline and RT and I will look into it.
> > > I managed to find an older box which is using the r8169 and I'm going to
> > > boot and see if there the driver is doing something odd what I didn't
> > > see earlier…
> > >
> > > Please make sure that you are using the in-tree driver. If you
> > > experience high latencies then I'm willing to help investigate.
> > >
> > > > Rod Webster
> > >
> > > Sebastian
> >
> >
>

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Peter Wallace]

On Tue, 23 May 2023, Rod Webster wrote:

> Date: Tue, 23 May 2023 06:02:13 +1000
> From: Rod Webster <rod@vmn.com.au>
> To: Marcelo Tosatti <mtosatti@redhat.com>
> Cc: Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
>     linux-rt-users@vger.kernel.org
> Subject: Re: Excessive network latency when using Realtek R8168/R8111 et al
>     NIC
> 
> This stuff is hard! I just realised that rtapi_app is a red herring!
> rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
> is on a 1000us cycle so it seems it gets all its jobs done in 200us
> and then sleeps for 800us which makes perfect sense!
>
> The issue we have is deeper than that. I think we should be looking at
> the NIC interrupt (but don't trust the novice!).
> The network communication is consuming more than the 800us slack from
> time to time. When that happens, our hardware sees the timing overrun
> and increments an internal packet error count. If too many of these
> happen in succession, the hardware decides the RT environment can't be
> relied on, disables further communication and returns an "error
> finishing read" to Linuxcnc to say it's given up.
>
> Marcelo, we didn't resort to C. We were able to use a bash script and
> use a linuxcnc tool called halcmd to query the hardware as shown here.
> #!/usr/bin/bash
> stat=0
> while (($stat < 1))
> do
> stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> done
> trace-cmd stop
>
> I think we need to increase the stat threshold  so we get more samples
> in our trace before stopping it. The current trace will only have one
> instance.
> Thanks for letting me see the issue more clearly.
>
>
> Rod Webster
>


I should note that at least for Intel MACs, the 6.3.1-rt13 and 6.4.0-rc2-rt1 
kernels seem to solve the issue. Not sure what changed but maximum read time 
is now in the 200.. 250 usec peak region (about 100 usec more than average) 
This is the peak read latency after about 3 days of videos, compiling and 
local network activity.

Sadly 6.4.0-rc3-rt2 has regressed slightly in network latency on my test 
systems

My test systems were all Intel CPUs with 4 cores, isolcpus=3 and the Ethernet
IRQ pinned to CPU3


Peter Wallace

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Rod Webster]

Peter, thanks for joining the conversation.
For the benefit of  others, Peter is the manufacturer of the Mesa
network hardware we are working with. it's great to have him on board.

Rod Webster





Rod Webster

VMN®

www.vmn.com.au

Ph: 1300 896 832

Mob: +61 435 765 611




On Tue, 23 May 2023 at 06:38, Peter Wallace <pcw@mesanet.com> wrote:
>
> On Tue, 23 May 2023, Rod Webster wrote:
>
> > Date: Tue, 23 May 2023 06:02:13 +1000
> > From: Rod Webster <rod@vmn.com.au>
> > To: Marcelo Tosatti <mtosatti@redhat.com>
> > Cc: Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
> >     linux-rt-users@vger.kernel.org
> > Subject: Re: Excessive network latency when using Realtek R8168/R8111 et al
> >     NIC
> >
> > This stuff is hard! I just realised that rtapi_app is a red herring!
> > rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
> > is on a 1000us cycle so it seems it gets all its jobs done in 200us
> > and then sleeps for 800us which makes perfect sense!
> >
> > The issue we have is deeper than that. I think we should be looking at
> > the NIC interrupt (but don't trust the novice!).
> > The network communication is consuming more than the 800us slack from
> > time to time. When that happens, our hardware sees the timing overrun
> > and increments an internal packet error count. If too many of these
> > happen in succession, the hardware decides the RT environment can't be
> > relied on, disables further communication and returns an "error
> > finishing read" to Linuxcnc to say it's given up.
> >
> > Marcelo, we didn't resort to C. We were able to use a bash script and
> > use a linuxcnc tool called halcmd to query the hardware as shown here.
> > #!/usr/bin/bash
> > stat=0
> > while (($stat < 1))
> > do
> > stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> > done
> > trace-cmd stop
> >
> > I think we need to increase the stat threshold  so we get more samples
> > in our trace before stopping it. The current trace will only have one
> > instance.
> > Thanks for letting me see the issue more clearly.
> >
> >
> > Rod Webster
> >
>
>
> I should note that at least for Intel MACs, the 6.3.1-rt13 and 6.4.0-rc2-rt1
> kernels seem to solve the issue. Not sure what changed but maximum read time
> is now in the 200.. 250 usec peak region (about 100 usec more than average)
> This is the peak read latency after about 3 days of videos, compiling and
> local network activity.
>
> Sadly 6.4.0-rc3-rt2 has regressed slightly in network latency on my test
> systems
>
> My test systems were all Intel CPUs with 4 cores, isolcpus=3 and the Ethernet
> IRQ pinned to CPU3
>
>
> Peter Wallace

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Marcelo Tosatti]

On Tue, May 23, 2023 at 06:02:13AM +1000, Rod Webster wrote:
> This stuff is hard! I just realised that rtapi_app is a red herring!
> rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
> is on a 1000us cycle so it seems it gets all its jobs done in 200us
> and then sleeps for 800us which makes perfect sense!
> 
> The issue we have is deeper than that. I think we should be looking at
> the NIC interrupt (but don't trust the novice!).
> The network communication is consuming more than the 800us slack from
> time to time. When that happens, our hardware sees the timing overrun
> and increments an internal packet error count. If too many of these
> happen in succession, the hardware decides the RT environment can't be
> relied on, disables further communication and returns an "error
> finishing read" to Linuxcnc to say it's given up.
> 
> Marcelo, we didn't resort to C. We were able to use a bash script and
> use a linuxcnc tool called halcmd to query the hardware as shown here.
> #!/usr/bin/bash
> stat=0
> while (($stat < 1))
> do
> stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> done
> trace-cmd stop

You can also write a value to the trace before stopping it:

echo "pin high, stopping tracing!" > /sys/kernel/debug/tracing/trace_marker

Just to make sure you are seeing the trace up to the correct event.

> I think we need to increase the stat threshold  so we get more samples
> in our trace before stopping it. The current trace will only have one
> instance.
> Thanks for letting me see the issue more clearly.
> 
> 
> Rod Webster
> 
> 
> 
> Rod Webster
> 
> VMN®
> 
> www.vmn.com.au
> 
> Ph: 1300 896 832
> 
> Mob: +61 435 765 611
> 
> 
> 
> 
> On Tue, 23 May 2023 at 03:13, Marcelo Tosatti <mtosatti@redhat.com> wrote:
> >
> > On Mon, May 22, 2023 at 08:06:39PM +1000, Rod Webster wrote:
> > > Yes, I won't be using a DKMS driver and will test with the in-tree driver.
> > > I rolled a PC back to the Debian 6.1 RT kernel and the default in-tree
> > > R8169 driver yesterday with isolcpus=2,3.
> > >
> > > I had a shot at it last night with the napi thread but was confused by
> > > the trace results so will try again.
> > > I could not see our PacketErrorTest script appearing in the trace but
> > > it stopped the trace when it should.
> >
> > Rod,
> >
> > Can you describe the PacketErrorTest script and how do you know, from
> > it, that latency has crossed the threshold? What was confusing about
> > the traces?
> >
> > Earlier you wrote:
> > I've had some feedback from a hardware supplier.
> > The Linuxcnc RT ethernet driver has a pin that reports ethernet packet
> > error count.
> > This increments when the ethernet response exceeds our real time servo
> > thread period (typically 1 ms)
> > We should be able to monitor this pin and stop the trace if it is >  0
> > without too much effort.
> >
> > So you are seeing that pin increase its value?
> >
> > When you do, you should write to the "tracing_on" file (a zero):
> >
> >         /*
> >          * if we're not tracing and the tracing_on fd is not open,
> >          * open the tracing_on file so that we can stop the trace
> >          * if we hit a breaktrace threshold
> >          */
> >         if (trace_fd < 0) {
> >                 sprintf(path, "%s/%s", fileprefix, "tracing_on");
> >                 if ((trace_fd = open(path, O_WRONLY)) < 0)
> >                         warn("unable to open tracing_on file: %s\n", path);
> >         }
> >
> >         /* now stop any trace */
> >         write(trace_fd, "0\n", 2);
> >
> > The trace file (/sys/kernel/debug/tracing/trace) should now contain
> > the trace up to the write to tracing_on file.
> >
> > Sebastian: didnt see anything weird in the traces as well:
> >
> > "Follows the delta between a list of timestamped events,
> > where each event is: "TIMESTAMP: rtapi is scheduled IN CPU-3"
> > (there is at one time only a single process scheduled in cpu-3).
> >
> > [191.050245, 191.050278]: 0.000033
> > [191.050278, 191.050293]: 0.000015
> > [191.050293, 191.050307]: 0.000014
> > [191.050307, 191.050322]: 0.000015
> > [191.050322, 191.050336]: 0.000014
> >
> > rtapi_app goes to sleep for approximately 15us, and is awakened
> > by a timer.
> >
> > [191.050336, 191.050350]: 0.000014
> > [191.050350, 191.050365]: 0.000015
> > [191.050365, 191.050379]: 0.000014
> > [191.050379, 191.050393]: 0.000014
> > [191.050393, 191.050408]: 0.000015
> > [191.050408, 191.051243]: 0.000835
> > [191.051243, 191.051272]: 0.000029
> >
> > It eventually sleeps for 800us (and this pattern repeats)".
> >
> > Perhaps tracing the system call which sends out the packet would be
> > useful as well.
> >
> > > Also our RT process did not appear to be on an isolated thread which
> > > seemed odd. I did not get as far as setting the affinity for napi.
> > >
> > > I've also installed  Bookworm RC3 on another PC with the default RT
> > > kernel on a Gigabyte Brix N3160 with an R8111/R8168 NIC and the
> > > in-tree R8169 driver.
> > > This PC historically had max latency of about 130000 ns  back with
> > > kernel 4.x and now its reporting 23000 ns with the 6.1 kernel over 24
> > > hours testing with the linuxcnc tools. Quite amazing what you guys
> > > have achieved! It will be a few days before I can lug my hardware to
> > > work to test on it as well for another data point.
> > >
> > > I really appreciate your willingness to help. This remains a
> > > frustrating issue for many Linuxcnc users who are using my compiled
> > > 6.3 kernel to get out of jail.
> > > Bear with me as I bumble my way through!
> > >
> > > Rod Webster
> > >
> > >
> > >
> > >
> > >
> > > Rod Webster
> > >
> > > VMN®
> > >
> > > www.vmn.com.au
> > >
> > > Ph: 1300 896 832
> > >
> > > Mob: +61 435 765 611
> > >
> > >
> > >
> > >
> > > On Mon, 22 May 2023 at 19:32, Sebastian Andrzej Siewior
> > > <bigeasy@linutronix.de> wrote:
> > > >
> > > > On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> > > > > I will do some testing tomorrow now I know what's going on but I
> > > > > wonder how relevant it will be given this turnaround?
> > > >
> > > > I'm not going to look at the dkms/OOT driver. If there is an actual
> > > > problem or something odd with mainline and RT and I will look into it.
> > > > I managed to find an older box which is using the r8169 and I'm going to
> > > > boot and see if there the driver is doing something odd what I didn't
> > > > see earlier…
> > > >
> > > > Please make sure that you are using the in-tree driver. If you
> > > > experience high latencies then I'm willing to help investigate.
> > > >
> > > > > Rod Webster
> > > >
> > > > Sebastian
> > >
> > >
> >
> 
> 

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Marcelo Tosatti]

On Mon, May 22, 2023 at 01:37:19PM -0700, Peter Wallace wrote:
> On Tue, 23 May 2023, Rod Webster wrote:
> 
> > Date: Tue, 23 May 2023 06:02:13 +1000
> > From: Rod Webster <rod@vmn.com.au>
> > To: Marcelo Tosatti <mtosatti@redhat.com>
> > Cc: Sebastian Andrzej Siewior <bigeasy@linutronix.de>,
> >     linux-rt-users@vger.kernel.org
> > Subject: Re: Excessive network latency when using Realtek R8168/R8111 et al
> >     NIC
> > 
> > This stuff is hard! I just realised that rtapi_app is a red herring!
> > rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
> > is on a 1000us cycle so it seems it gets all its jobs done in 200us
> > and then sleeps for 800us which makes perfect sense!
> > 
> > The issue we have is deeper than that. I think we should be looking at
> > the NIC interrupt (but don't trust the novice!).
> > The network communication is consuming more than the 800us slack from
> > time to time. When that happens, our hardware sees the timing overrun
> > and increments an internal packet error count. If too many of these
> > happen in succession, the hardware decides the RT environment can't be
> > relied on, disables further communication and returns an "error
> > finishing read" to Linuxcnc to say it's given up.
> > 
> > Marcelo, we didn't resort to C. We were able to use a bash script and
> > use a linuxcnc tool called halcmd to query the hardware as shown here.
> > #!/usr/bin/bash
> > stat=0
> > while (($stat < 1))
> > do
> > stat=`halcmd getp hm2_7i96s.0.packet-error-total`
> > done
> > trace-cmd stop
> > 
> > I think we need to increase the stat threshold  so we get more samples
> > in our trace before stopping it. The current trace will only have one
> > instance.
> > Thanks for letting me see the issue more clearly.
> > 
> > 
> > Rod Webster
> > 
> 
> 
> I should note that at least for Intel MACs, the 6.3.1-rt13 and 6.4.0-rc2-rt1
> kernels seem to solve the issue. Not sure what changed but maximum read time
> is now in the 200.. 250 usec peak region (about 100 usec more than average)
> This is the peak read latency after about 3 days of videos, compiling and
> local network activity.
> 
> Sadly 6.4.0-rc3-rt2 has regressed slightly in network latency on my test
> systems
> 
> My test systems were all Intel CPUs with 4 cores, isolcpus=3 and the Ethernet
> IRQ pinned to CPU3
> 
> 
> Peter Wallace

Are you guys using the realtime profiles from Tuned?

Edit /etc/tuned/realtime-virtual-host-variables.conf,

Then run

tuned-adm profile realtime-virtual-host

Note this will perform steps to isolate the configured CPU's,
including unpinning all IRQs from the isolated CPUs,
(which you can fix after applying the profile).
enabling nohz_full=, rcu_nocbs=, etc (can check 
/usr/lib/tuned/realtime-virtual-host/tuned.conf and script.sh 
to see what what it (and its parent profiles) do).

RE: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Stephane ANCELOT]

Hi,


Hi,

I worked on realtime realtek chips drivers in the past.
I remember there was a delay register to trigg the interrupt  in the realtek component.

This may be a similar problem with this chip.

Refs https://patchwork.ozlabs.org/project/netdev/patch/20121127224605.GA10228@electric-eye.fr.zoreil.com/

Stéphane ANCELOT





> -----Message d'origine-----
> De : Marcelo Tosatti <mtosatti@redhat.com>
> Envoyé : mercredi 24 mai 2023 01:04
> À : Rod Webster <rod@vmn.com.au>
> Cc : Sebastian Andrzej Siewior <bigeasy@linutronix.de>; linux-rt-
> users@vger.kernel.org
> Objet : Re: Excessive network latency when using Realtek R8168/R8111 et al
> NIC
> 
>         External Sender: Use caution with links/attachments.
> Expediteur externe : Soyez prudent avec les liens/pieces jointes.
> 
> On Tue, May 23, 2023 at 06:02:13AM +1000, Rod Webster wrote:
> > This stuff is hard! I just realised that rtapi_app is a red herring!
> > rtapi_app is Linuxcnc and there is nothing wrong with it. Its thread
> > is on a 1000us cycle so it seems it gets all its jobs done in 200us
> > and then sleeps for 800us which makes perfect sense!
> >
> > The issue we have is deeper than that. I think we should be looking at
> > the NIC interrupt (but don't trust the novice!).
> > The network communication is consuming more than the 800us slack from
> > time to time. When that happens, our hardware sees the timing overrun
> > and increments an internal packet error count. If too many of these
> > happen in succession, the hardware decides the RT environment can't be
> > relied on, disables further communication and returns an "error
> > finishing read" to Linuxcnc to say it's given up.
> >
> > Marcelo, we didn't resort to C. We were able to use a bash script and
> > use a linuxcnc tool called halcmd to query the hardware as shown here.
> > #!/usr/bin/bash
> > stat=0
> > while (($stat < 1))
> > do
> > stat=`halcmd getp hm2_7i96s.0.packet-error-total` done trace-cmd stop
> 
> You can also write a value to the trace before stopping it:
> 
> echo "pin high, stopping tracing!" > /sys/kernel/debug/tracing/trace_marker
> 
> Just to make sure you are seeing the trace up to the correct event.
> 
> > I think we need to increase the stat threshold  so we get more samples
> > in our trace before stopping it. The current trace will only have one
> > instance.
> > Thanks for letting me see the issue more clearly.
> >
> >
> > Rod Webster
> >
> >
> >
> > Rod Webster
> >
> > VMN®
> >
> > www.vmn.com.au
> >
> > Ph: 1300 896 832
> >
> > Mob: +61 435 765 611
> >
> >
> >
> >
> > On Tue, 23 May 2023 at 03:13, Marcelo Tosatti <mtosatti@redhat.com>
> wrote:
> > >
> > > On Mon, May 22, 2023 at 08:06:39PM +1000, Rod Webster wrote:
> > > > Yes, I won't be using a DKMS driver and will test with the in-tree driver.
> > > > I rolled a PC back to the Debian 6.1 RT kernel and the default
> > > > in-tree
> > > > R8169 driver yesterday with isolcpus=2,3.
> > > >
> > > > I had a shot at it last night with the napi thread but was
> > > > confused by the trace results so will try again.
> > > > I could not see our PacketErrorTest script appearing in the trace
> > > > but it stopped the trace when it should.
> > >
> > > Rod,
> > >
> > > Can you describe the PacketErrorTest script and how do you know,
> > > from it, that latency has crossed the threshold? What was confusing
> > > about the traces?
> > >
> > > Earlier you wrote:
> > > I've had some feedback from a hardware supplier.
> > > The Linuxcnc RT ethernet driver has a pin that reports ethernet
> > > packet error count.
> > > This increments when the ethernet response exceeds our real time
> > > servo thread period (typically 1 ms) We should be able to monitor
> > > this pin and stop the trace if it is >  0 without too much effort.
> > >
> > > So you are seeing that pin increase its value?
> > >
> > > When you do, you should write to the "tracing_on" file (a zero):
> > >
> > >         /*
> > >          * if we're not tracing and the tracing_on fd is not open,
> > >          * open the tracing_on file so that we can stop the trace
> > >          * if we hit a breaktrace threshold
> > >          */
> > >         if (trace_fd < 0) {
> > >                 sprintf(path, "%s/%s", fileprefix, "tracing_on");
> > >                 if ((trace_fd = open(path, O_WRONLY)) < 0)
> > >                         warn("unable to open tracing_on file: %s\n", path);
> > >         }
> > >
> > >         /* now stop any trace */
> > >         write(trace_fd, "0\n", 2);
> > >
> > > The trace file (/sys/kernel/debug/tracing/trace) should now contain
> > > the trace up to the write to tracing_on file.
> > >
> > > Sebastian: didnt see anything weird in the traces as well:
> > >
> > > "Follows the delta between a list of timestamped events, where each
> > > event is: "TIMESTAMP: rtapi is scheduled IN CPU-3"
> > > (there is at one time only a single process scheduled in cpu-3).
> > >
> > > [191.050245, 191.050278]: 0.000033
> > > [191.050278, 191.050293]: 0.000015
> > > [191.050293, 191.050307]: 0.000014
> > > [191.050307, 191.050322]: 0.000015
> > > [191.050322, 191.050336]: 0.000014
> > >
> > > rtapi_app goes to sleep for approximately 15us, and is awakened by a
> > > timer.
> > >
> > > [191.050336, 191.050350]: 0.000014
> > > [191.050350, 191.050365]: 0.000015
> > > [191.050365, 191.050379]: 0.000014
> > > [191.050379, 191.050393]: 0.000014
> > > [191.050393, 191.050408]: 0.000015
> > > [191.050408, 191.051243]: 0.000835
> > > [191.051243, 191.051272]: 0.000029
> > >
> > > It eventually sleeps for 800us (and this pattern repeats)".
> > >
> > > Perhaps tracing the system call which sends out the packet would be
> > > useful as well.
> > >
> > > > Also our RT process did not appear to be on an isolated thread
> > > > which seemed odd. I did not get as far as setting the affinity for napi.
> > > >
> > > > I've also installed  Bookworm RC3 on another PC with the default
> > > > RT kernel on a Gigabyte Brix N3160 with an R8111/R8168 NIC and the
> > > > in-tree R8169 driver.
> > > > This PC historically had max latency of about 130000 ns  back with
> > > > kernel 4.x and now its reporting 23000 ns with the 6.1 kernel over
> > > > 24 hours testing with the linuxcnc tools. Quite amazing what you
> > > > guys have achieved! It will be a few days before I can lug my
> > > > hardware to work to test on it as well for another data point.
> > > >
> > > > I really appreciate your willingness to help. This remains a
> > > > frustrating issue for many Linuxcnc users who are using my
> > > > compiled
> > > > 6.3 kernel to get out of jail.
> > > > Bear with me as I bumble my way through!
> > > >
> > > > Rod Webster
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > Rod Webster
> > > >
> > > > VMN®
> > > >
> > > > www.vmn.com.au
> > > >
> > > > Ph: 1300 896 832
> > > >
> > > > Mob: +61 435 765 611
> > > >
> > > >
> > > >
> > > >
> > > > On Mon, 22 May 2023 at 19:32, Sebastian Andrzej Siewior
> > > > <bigeasy@linutronix.de> wrote:
> > > > >
> > > > > On 2023-05-19 21:41:30 [+1000], Rod Webster wrote:
> > > > > > I will do some testing tomorrow now I know what's going on but
> > > > > > I wonder how relevant it will be given this turnaround?
> > > > >
> > > > > I'm not going to look at the dkms/OOT driver. If there is an
> > > > > actual problem or something odd with mainline and RT and I will look
> into it.
> > > > > I managed to find an older box which is using the r8169 and I'm
> > > > > going to boot and see if there the driver is doing something odd
> > > > > what I didn't see earlier…
> > > > >
> > > > > Please make sure that you are using the in-tree driver. If you
> > > > > experience high latencies then I'm willing to help investigate.
> > > > >
> > > > > > Rod Webster
> > > > >
> > > > > Sebastian
> > > >
> > > >
> > >
> >
> >

Re: Excessive network latency when using Realtek R8168/R8111 et al NIC

[Peter Wallace]

>
> Are you guys using the realtime profiles from Tuned?
>
> Edit /etc/tuned/realtime-virtual-host-variables.conf,
>
> Then run
>
> tuned-adm profile realtime-virtual-host
>
> Note this will perform steps to isolate the configured CPU's,
> including unpinning all IRQs from the isolated CPUs,
> (which you can fix after applying the profile).
> enabling nohz_full=, rcu_nocbs=, etc (can check
> /usr/lib/tuned/realtime-virtual-host/tuned.conf and script.sh
> to see what what it (and its parent profiles) do).
>
>

I will give this a try, thanks!

Peter Wallace
Mesa Electronics