Regression on rt kernel while using POSIX timers

Hi,

The results for the POSIX timers were not as I expected. The latency for real-time kernel (v4.9.4-rt2) was worse compared to the mainline kernel (v4.9.4). In almost all the cases, the latency is almost doubled with the max value reaching about 10 times when performing the tests under load.

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Quoted 2 lines · Vedang

Hi,

Hi,

Quoted 10 lines

The results for the POSIX timers were not as I expected. The latency
for real-time kernel (v4.9.4-rt2) was worse compared to the mainline
kernel (v4.9.4). In almost all the cases, the latency is almost doubled
 with the max value reaching about 10 times when performing the tests
under load.

Is it also the case if you boost the priority of ktimersoftd/X threads?
For clock_nanosleep, the wake-ups happen directly from hard-timer interrupt. For the posix-timer we have to delay those to the ktimersoftd
thread which runs usually RT prio 1.

Quoted 5 lines

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Sebastian

I am getting very similar results even if I change the priority of ktimersoftd to 99. Are there any recent rt patches which might have changed the behaviour of POSIX timers?

From tracing it doesn't look too good either. The -m option should be

Also, are POSIX timers really suited for "real-time" applications?I believe a similar question was raised by Ran Shalit a few days back:
http://www.spinics.net/lists/linux-rt-users/msg16249.html

Thanks,
Vedang

Quoted 3 lines · Vedang

I am getting very similar results even if I change the priority of ktimersoftd to 99. Are there any recent rt patches which might have changed the behaviour of POSIX timers?

I had this running

|~# cyclictest -t1 -p 80 -i 500 -l 100000
|# /dev/cpu_dma_latency set to 0us
|policy: fifo: loadavg: 627.48 661.98 543.65 406/2254 18149          
|
|T: 0 (16148) P:80 I:500 C: 100000 Min:      5 Act:   11 Avg:   11 Max: 23

on a AMD-A10 box and the latest v4.9-RT. This does not look that bad. From tracing it doesn't look too good either. The -m option should be your friend. Since the cyclictest isn't pinned to a CPU and I have four of them, the scheduler decides to migrate cyclictest on each wake up. yay. cyclictest itself gets woken up via a signal from the ktimersoftirq.

Quoted 18 lines · On Wed, Feb 15, 2017 at 05:54:47PM +0100, [email protected] wrote:

Quoted 6 lines · Vedang

I am getting very similar results even if I change the priority of
ktimersoftd to 99. Are there any recent rt patches which might have
changed the behaviour of POSIX timers?

I had this running

Quoted 8 lines

~# cyclictest -t1 -p 80 -i 500 -l 100000

# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 627.48 661.98 543.65 406/2254
18149          

T: 0 (16148) P:80 I:500 C: 100000 Min:      5 Act:   11 Avg:   11
Max: 23

Quoted 10 lines

on a AMD-A10 box and the latest v4.9-RT. This does not look that bad.
From tracing it doesn't look too good either. The -m option should be
your friend. Since the cyclictest isn't pinned to a CPU and I have four
of them, the scheduler decides to migrate cyclictest on each wake up.
yay. cyclictest itself gets woken up via a signal from the ktimersoftirq.

Perhaps a separate off-shoot topic, but has there been significant changes in v4.9 upstream (or v4.9-rt) which impact how often migration
is performed?  We've seen what appears to be much more aggressive migration of SCHED_FAIR tasks, (aggressive in the sense that more threads are migrated more often), which appears to cause contention on
rq-locks impacting latencies in the wake_up paths.

We're still working to further characterize at this point....hopefully
more information forthcoming.

   Julia

Quoted 46 lines · Julia Cartwright

Quoted 22 lines · On Wed, Feb 15, 2017 at 05:54:47PM +0100, [email protected] wrote:

Quoted 7 lines · Vedang

I am getting very similar results even if I change the priority of
ktimersoftd to 99. Are there any recent rt patches which might have
changed the behaviour of POSIX timers?

I had this running

Quoted 10 lines

~# cyclictest -t1 -p 80 -i 500 -l 100000

# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 627.48 661.98 543.65 406/2254
18149          

T: 0 (16148) P:80 I:500 C: 100000 Min:      5 Act:   11 Avg:   11
Max: 23

Quoted 12 lines

on a AMD-A10 box and the latest v4.9-RT. This does not look that bad.
From tracing it doesn't look too good either. The -m option should
be
your friend. Since the cyclictest isn't pinned to a CPU and I have
four
of them, the scheduler decides to migrate cyclictest on each wake up.
yay. cyclictest itself gets woken up via a signal from the ktimersoftirq.

Perhaps a separate off-shoot topic, but has there been significant changes in v4.9 upstream (or v4.9-rt) which impact how often migration
is performed?  We've seen what appears to be much more aggressive migration of SCHED_FAIR tasks, (aggressive in the sense that more threads are migrated more often), which appears to cause contention on
rq-locks impacting latencies in the wake_up paths.

Quoted 3 lines

We're still working to further characterize at this point....hopefully
more information forthcoming.

I tried conducting similar experiments on v4.4.47-rt59. But, the results are same as v4.9 kernel.

My machine also has 8 cores and migration might cause regressions. Let
me try pinning the processes to a single CPU and see if that is making
any difference.

More information to follow soon...

Thanks for all the inputs,
Vedang Patel
Software Engineer
Intel Corporation

Quoted 3 lines

   Julia�{.n�+�������+%��lzwm��b�맲��r��zX���ǫ�)���w*jg��������ݢ j/���z�ޖ��2�ޙ���&�)ߡ�a�����G���h��j:+v���w�٥

Also, I checked the number of cpu migrations and context switches using perf stat. Following are the results for both the cases:

cyclictest not pinned to CPU: the number of CPU migrations and context switches are equal to the number of loops I am running for cyclictest. Here, there are a lot of context switches with the ktimersoftd process.

cyclictest pinned to a CPU: there are very few CPU migrations. But, the number of context switches are approximately 3 times the number of loops. Most of the context switches are with the swapper (idle) process.

In both the cases, the number of page faults are pretty low (~65).

I also tried similar experiments with mainline kernel (v4.4.47). The number of CPU migrations were pretty low (single digits) for both the cases described above. Also, the number of context switches were equal to the number of loops provided as an argument to cyclictest.

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Quoted 14 lines · Vedang

Also, I checked the number of cpu migrations and context switches using perf stat. Following are the results for both the cases:

cyclictest not pinned to CPU: the number of CPU migrations and context switches are equal to the number of loops I am running for cyclictest. Here, there are a lot of context switches with the ktimersoftd process.

cyclictest pinned to a CPU: there are very few CPU migrations. But, the number of context switches are approximately 3 times the number of loops. Most of the context switches are with the swapper (idle) process.

Quoted 6 lines

In both the cases, the number of page faults are pretty low (~65).

I also tried similar experiments with mainline kernel (v4.4.47). The number of CPU migrations were pretty low (single digits) for both the cases described above. Also, the number of context switches were equal to the number of loops provided as an argument to cyclictest.

The hardware interrupt wakes the "timer-softirq" thread. This RT-thread in turn will wake up your application / cyclictest which uses the posix-timers. So the priority of this thread is also important. After the wakeup it is possible that the newer kernel tries migrate the RT task if possible in order to keep it running as soon as possible. If it does not migrate it, then either the cyclictest task has to wait or the "timer-softirq" thread.

Quoted 4 lines

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Sebastian
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Pleaee isolate the specific release where latency regression occurred if the community has not already done so. Possibly backing out changes specific to timers and posix threads for that release to see what impacted latency.  This is crucial for NXP and others as they migrate to later releases of the kernel.

Also please share your latency numbers while testing for regression for each release if possible.

Using:

taskset -c 2 cyclictest -m -n -P -p 99 -t 1 -i 10000-136000000 taskset -c 3 cyclictest -m -n -P -p 99 -t  1 -i 10000000 -l 0

On an ARM-8 Cortex-A53 NXP LS1043ARDB 4x core the latency was approx 3 us min/avg and max 7 with no latency spikes on 4.1.30-rt34+g667e6ba SMP PREEMPT RT NXP SDK 2.0-1609.  Used sar, iperf, and stress for load.

Tracy Smith
Software Engineer
DSC

Quoted 58 lines

Quoted 23 lines · On Mar 1, 2017, at 9:22 AM, "[email protected]" <[email protected]>…

On 2017-02-22 01:43:09 [+0000], Patel, Vedang wrote:
Also, I checked the number of cpu migrations and context switches using
perf stat. Following are the results for both the cases:

cyclictest not pinned to CPU: the number of CPU migrations and context
switches are equal to the number of loops I am running for cyclictest.
Here, there are a lot of context switches with the ktimersoftd process.

cyclictest pinned to a CPU: there are very few CPU migrations. But, the
number of context switches are approximately 3 times the number of
loops. Most of the context switches are with the swapper (idle) process.

In both the cases, the number of page faults are pretty low (~65).

Quoted 7 lines

I also tried similar experiments with mainline kernel (v4.4.47). The
number of CPU migrations were pretty low (single digits) for both the
cases described above. Also, the number of context switches were equal
to the number of loops provided as an argument to cyclictest.

The hardware interrupt wakes the "timer-softirq" thread. This RT- thread
in turn will wake up your application / cyclictest which uses the posix-timers. So the priority of this thread is also important. After
the wakeup it is possible that the newer kernel tries migrate the RT
task if possible in order to keep it running as soon as possible. If it
does not migrate it, then either the cyclictest task has to wait or the
"timer-softirq" thread.

Quoted 5 lines

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Sebastian
--
To unsubscribe from this list: send the line "unsubscribe linux-rt- users" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

As for running cyclictest with posix timers, I see the following results with the same hardware and kernel:

Case 1:
~/rt-tests# ./cyclictest -t1 -p 80 -i 500 -l 100000

# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.01 0.02 0.00 2/204 6936

T: 0 ( 6926) P:80 I:500 C: 100000 Min:     11 Act:   16 Avg:   15 Max:      65

Case 2:
~/rt-tests# ./cyclictest -a 3 -t1 -p 80 -i 500 -l 100000

# /dev/cpu_dma_latency set to 0us
policy: fifo: loadavg: 0.15 0.04 0.01 1/204 6954           

T: 0 ( 6943) P:80 I:500 C: 100000 Min:     31 Act:   45 Avg:   43 Max:      59

Note that the first test is without any cpu affinity and the second test by pinning down  the cyclictest process to a CPU by providing the '-a' argument.

I also tried tracing cyclictest using trace-cmd by enabling hrtimer_start, sched_switch, sched_migrate_task, signal_generate and grepping for cyclictest in the logs. I see the following transitions in both the cases:

Case 1:
TASK CPU  TIMESTAMP EVENT
      cyclictest-2351  [003]  7773.130964: hrtimer_start:        hrtimer=0xffff88046b098828 function=posix_timer_fn/0x0 expires=7767043047952 softexpires=7767043047952 cyclictest-2351  [003]  7773.130978: sched_switch:         cyclictest:2351 [19] S ==> ktimersoftd/3:36 [98]
   ktimersoftd/3-36    [003]  7773.130992: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]
      cyclictest-2351  [003]  7773.131003: sched_switch:         cyclictest:2351 [19] D ==> ktimersoftd/3:36 [19] <--- cyclictest is in TASK_UNINTERRUPTIBLE state. ktimersoftd/3-36    [003]  7773.131006: signal_generate:      sig=14 errno=0 code=131070 comm=cyclictest pid=2351 grp=0 res=0 ktimersoftd/3-36    [003]  7773.131018: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]
      cyclictest-2351  [003]  7773.131031: sched_switch:         cyclictest:2351 [19] D ==> ktimersoftd/3:36 [19]
   ktimersoftd/3-36    [003]  7773.131046: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]

On Thu, Mar 02, 2017 at 03:23:02AM +0000, Patel, Vedang wrote:

Quoted 10 lines

Case 1:
TASK CPU  TIMESTAMP EVENT
      cyclictest-2351  [003]  7773.130964: hrtimer_start:        hrtimer=0xffff88046b098828 function=posix_timer_fn/0x0 expires=7767043047952 softexpires=7767043047952 cyclictest-2351  [003]  7773.130978: sched_switch:         cyclictest:2351 [19] S ==> ktimersoftd/3:36 [98]
   ktimersoftd/3-36    [003]  7773.130992: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]
      cyclictest-2351  [003]  7773.131003: sched_switch:         cyclictest:2351 [19] D ==> ktimersoftd/3:36 [19] <--- cyclictest is in TASK_UNINTERRUPTIBLE state. ktimersoftd/3-36    [003]  7773.131006: signal_generate:      sig=14 errno=0 code=131070 comm=cyclictest pid=2351 grp=0 res=0 ktimersoftd/3-36    [003]  7773.131018: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]
      cyclictest-2351  [003]  7773.131031: sched_switch:         cyclictest:2351 [19] D ==> ktimersoftd/3:36 [19]
   ktimersoftd/3-36    [003]  7773.131046: sched_switch:         ktimersoftd/3:36 [98] R ==> cyclictest:2351 [19]

This ktimersoftd -> cyclictest -> ktimersoftd -> cyclictest "bounce" is a result of how the signal completion code for the posix itimers is done.

   [ktimersoftd]                [cyclictest]
     lock task->sighand
     set pending signal
     signal_wake_up(task)  --->
                                 lock task->sighand (*blocked*, state D)
                           <---
     trace signal_generate
     unlock task->sighand
                           --->
                                 while (!pending signal)
                                   unlock task->sighand
                                   wait for signal
                                   lock task->sighand
                                 unlock task->sighand

Without PREEMPT_RT_FULL enabled, the critical section is executed with "raw" spinlocks, and is therefore non-preemptible. However, with RT_FULL, the preemptibility of the section leads to the "bounce".

That should make it clear why ktimersoftd would be PI boosted, as well.

Now, it isn't clear to me why the affinitized scenario appears to make this happen more frequently... Nor do I have a handle on what to do to fix this (if anything).

Quoted 7 lines · Julia Cartwright

Without PREEMPT_RT_FULL enabled, the critical section is executed with
"raw" spinlocks, and is therefore non-preemptible.  However, with RT_FULL, the preemptibility of the section leads to the "bounce".

Quoted 8 lines

That should make it clear why ktimersoftd would be PI boosted, as well.

Now, it isn't clear to me why the affinitized scenario appears to make
this happen more frequently...  Nor do I have a handle on what to do to
fix this (if anything).

The point here is:

perf stat taskset 1 cyclictest -t1

will make the control thread of cyclictest affine to cpu 0 and also the
measuring thread. perf stat counts the context switches of both.

CPU 0
cyclictest-control

--> Interrupt

ksoftirqd

cyclictest-measure
  rearm timer
  sleep

cyclictest-control

....

versus a non affine scenario

CPU0              CPU1 CPU2
cyclictest-control  interrupt

		    ksoftirqd	-->	cyclictest-measure
		    			   rearm timer
					   sleep
					
					interrupt
		    cyclicttest <--	ksoftirqd
		    -measure		

Thanks,

tglx

I now have the following concerns and comments:
1. real-time kernel vs. Mainline kernel: The real-time kernel is worse with POSIX timers than the mainline kernel. This is odd. Is this because the softirqs are not the same anymore(Sorry, I am still not familiar with what they have become. I deduced the "not the same" part

from commit messages/comments in code. :))? Also, in https://git.kernel
.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v4.4- rt&id=4aa7cba57f73acf1e3e4998ae1650965317c2de1, it is mentioned:
"
Bring back the softirq split for now, until we fixed the signal delivery problem for real.
"
What signal delivery problem is being referred to?

2. In the case the CPU affinity is set, The CPU is shared between cyclictest thread and the ktimersoftd thread. So, in the end, 1 CPU migration is cheaper than 3 context switches... Is this the right analysis? I know this will vary from application to application.

Quoted 17 lines · Vedang

I now have the following concerns and comments:
1. real-time kernel vs. Mainline kernel: The real-time kernel is worse
with POSIX timers than the mainline kernel. This is odd. Is this because the softirqs are not the same anymore(Sorry, I am still not familiar with what they have become. I deduced the "not the same" part
from commit messages/comments in code. :))? Also, in https://git.ke
rnel .org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v4.4- rt&id=4aa7cba57f73acf1e3e4998ae1650965317c2de1, it is mentioned:
"
Bring back the softirq split for now, until we fixed the signal delivery problem for real.
"
What signal delivery problem is being referred to?

The problem with these timers is that the heavy lifting of signal processing happens in "stolen" context. That means that the work is not
done in the context of the process/thread which armed the timer, but in
softirq context.

What we really want here is the following:

     timer expires()
         mark timer expired in thread/process
   eventually wakeup thread

This is simple to achieve for timers where the signal is directed to a
thread, but it's way more complex for process wide signal delivery.

Quoted 5 lines

2. In the case the CPU affinity is set, The CPU is shared between cyclictest thread and the ktimersoftd thread. So, in the end, 1 CPU migration is cheaper than 3 context switches... Is this the right analysis? I know this will vary from application to application.

No, migration is not generally cheaper, in most cases its more expensive.

Thanks,

tglx

Quoted 3 lines · Thomas Gleixner

This is simple to achieve for timers where the signal is directed to a thread, but it's way more complex for process wide signal delivery.

So, does this mean that we should be asking people not to use POSIX timers until this is corrected?

Also, Is there a way to specify which ktimersoftd thread (essentially selecting a particular CPU)to use while creating a timer? Currently, the ktimersoftd thread corresponding to the thread on which the CPU is running is being used by cyclictest. This would prevent the bounce between ktimersoftd and cyclictest thread when both of them are on the same CPU.

Quoted 9 lines · Vedang

Quoted 6 lines · Thomas Gleixner

This is simple to achieve for timers where the signal is directed to
a thread, but it's way more complex for process wide signal delivery.

Quoted 2 lines

So, does this mean that we should be asking people not to use POSIX timers until this is corrected?

Well, we always recommended clock_nanosleep() to be used and to avoid signal based timers when ever possible.

Quoted 12 lines

Also, Is there a way to specify which ktimersoftd thread (essentially
selecting a particular CPU)to use while creating a timer? Currently,
the ktimersoftd thread corresponding to the thread on which the CPU is
running is being used by cyclictest. This would prevent the bounce between ktimersoftd and cyclictest thread when both of them are on the
same CPU.

Nope. This is even more complex than you describe it and no, we definitely
don't want to think about this in the first place.

Thanks,

tglx

Pleaee isolate the specific release where latency regression occurred if the community has not already done so.

Possibly backing out changes specific to timers and posix threads for that release to see what impacted latency.

This is crucial for NXP and others as they migrate to later releases of the kernel.