Regression on rt kernel while using POSIX timers

Regression on rt kernel while using POSIX timers

[Patel, Vedang]

Hi, 

I am trying to reproduce results in the Expected Results section on htt
ps://rt.wiki.kernel.org/index.php/Cyclictest

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.

I was using a system with Intel® Atom processor C2758 and running the
following commands with no load and 100% load:
* cyclictest -t1 -p 80 -i 10000 -l 10000
* cyclictest -t1 -p 80 -i 500 -l 100000

I was using hackbench for generating the loads as follows:

./hackbench -p -s 100 -l 10000 -f 100 -P &

Does anyone have know of any known bugs which might be causing this
regression? 

Thanks,
Vedang Patel
Software Engineer
Intel Corporation

Re: Regression on rt kernel while using POSIX timers

[Sebastian Andrzej Siewior]

On 2017-02-08 18:41:25 [+0000], Patel, Vedang wrote:
> Hi, 
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.

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.

> Thanks,
> Vedang Patel
> Software Engineer
> Intel Corporation

Sebastian

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

On Fri, 2017-02-10 at 20:07 +0100, Sebastian Andrzej Siewior wrote:
> On 2017-02-08 18:41:25 [+0000], Patel, Vedang wrote:
> > 
> > Hi, 
> 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.
> 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.
> 
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? 

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
> > 
> > Thanks,
> > Vedang Patel
> > Software Engineer
> > Intel Corporation
> Sebastian

Re: Regression on rt kernel while using POSIX timers

[bigeasy]

On 2017-02-13 18:48:33 [+0000], Patel, Vedang wrote:
> 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.

> 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

So it seems to work with no regression as far as I can tell. Due to the
timersoftirq context switch I would suggest to use clock_nanosleep if
possible.

> Thanks,
> Vedang

Sebastian

Re: Regression on rt kernel while using POSIX timers

[Julia Cartwright]

On Wed, Feb 15, 2017 at 05:54:47PM +0100, bigeasy@linutronix.de wrote:
> On 2017-02-13 18:48:33 [+0000], Patel, Vedang wrote:
> > 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.

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

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

On Wed, 2017-02-15 at 20:05 -0600, Julia Cartwright wrote:
> On Wed, Feb 15, 2017 at 05:54:47PM +0100, bigeasy@linutronix.de
> wrote:
> > 
> > On 2017-02-13 18:48:33 [+0000], Patel, Vedang wrote:
> > > 
> > > 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.
> 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.
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
>    Julia

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

On Thu, 2017-02-16 at 02:34 +0000, Patel, Vedang wrote:
> On Wed, 2017-02-15 at 20:05 -0600, Julia Cartwright wrote:
> > 
> > On Wed, Feb 15, 2017 at 05:54:47PM +0100, bigeasy@linutronix.de
> > wrote:
> > > 
> > > 
> > > On 2017-02-13 18:48:33 [+0000], Patel, Vedang wrote:
> > > > 
> > > > 
> > > > 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.
> > 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.
> 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. 
> 
So, I tried pinning the process to a single CPU. But, turns out that
the latency in case of Pinned CPU is worse than the latency when CPU is
not pinned. I tried 2 different ways for pinning the cyclictest task to
a CPU -- -a argument in cyclictest and taskset command to set a CPU. I
got the same results for both the methods. I also tried different CPUs
thinking one of the CPUs might have something else pinned. But, the
result remained the same.

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

> More information to follow soon...
> 
> Thanks for all the inputs, 
> Vedang Patel
> Software Engineer
> Intel Corporation
> > 
> >    Julia\x04�{.n�+�������+%��lzwm��b�맲��r��zX��\x1a�ǫ�)���w*\x1fjg���\x1e�����ݢ
> > j/���z�ޖ��2�ޙ���&�)ߡ�a��\x7f��\x1e�G���h�\x0f�j:+v���w�٥

Re: Regression on rt kernel while using POSIX timers

[bigeasy]

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).
> 
> 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.

> Thanks,
> Vedang Patel
> Software Engineer
> Intel Corporation

Sebastian

Re: Regression on rt kernel while using POSIX timers

[Tracy Smith]

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



> On Mar 1, 2017, at 9:22 AM, "bigeasy@linutronix.de" <bigeasy@linutronix.de> wrote:
> 
>> 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).
>> 
>> 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.
> 
>> 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 majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

Hi Tracy,

The tests below include '-n' argument which mean they will use
clock_nanosleep. I don't face any problems with this scenario. I face
problems when I do not provide the '-n' argument and POSIX timers are
used. But, for your information, I see average of 10us and max 18us
when I am running the tests that you provided. Please note that this is
without any workloads and these tests are performed on v4.1.30-rt34 on 
http://www.supermicro.com/products/motherboard/Atom/X10/A1SRi-2758F.cfm
.


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]

Case 2:
	TASK		CPU 	TIMESTAMP	EVENT		 
       cyclictest-2386  [004]  7833.312194: hrtimer_start:        hrtimer=0xffff880463a78198 function=posix_timer_fn/0x0 expires=7827177394186 softexpires=7827177394186
      cyclictest-2386  [004]  7833.312204: sched_switch:         cyclictest:2386 [19] S ==> swapper/4:0 [120]
   ktimersoftd/4-46    [004]  7833.312285: sched_migrate_task:   comm=cyclictest pid=2386 prio=19 orig_cpu=4 dest_cpu=5
   ktimersoftd/4-46    [004]  7833.312288: signal_generate:      sig=14 errno=0 code=131070 comm=cyclictest pid=2386 grp=0 res=0
          <idle>-0     [005]  7833.312289: sched_switch:         swapper/5:0 [120] R ==> cyclictest:2386 [19]
      cyclictest-2386  [005]  7833.312294: hrtimer_start:        hrtimer=0xffff880463a78198 function=posix_timer_fn/0x0 expires=7827177494186 softexpires=7827177494186
      cyclictest-2386  [005]  7833.312303: sched_switch:         cyclictest:2386 [19] S ==> swapper/5:0 [120]
   ktimersoftd/5-53    [005]  7833.312385: sched_migrate_task:   comm=cyclictest pid=2386 prio=19 orig_cpu=5 dest_cpu=4
   ktimersoftd/5-53    [005]  7833.312388: signal_generate:      sig=14 errno=0 code=131070 comm=cyclictest pid=2386 grp=0 res=0
          <idle>-0     [004]  7833.312390: sched_switch:         swapper/4:0 [120] R ==> cyclictest:2386 [19]
(Note: the above events indicate 2 loops of cyclictest.)

The above cases behave according to what Sebastian said in the previous
email.

In Case 1,  I am not sure why the 3 context switches are occuring
before the signal_generate. Also, why is cyclictest is in
TASK_UNINTERRUPTIBLE state (I deduced it by cross-referencing the 'D'
in include/linux/sched.h. Hope I am right.). Also, ktimersoftd seems to
inherit the priority of cyclictest. Is it to run the timer?

Case 2 is much less confusing and I think I am able to follow it.

Thanks,
Vedang

On Wed, 2017-03-01 at 13:03 -0600, Tracy Smith wrote:
> 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
> 
> 
> 
> > 
> > On Mar 1, 2017, at 9:22 AM, "bigeasy@linutronix.de"
> > <bigeasy@linutronix.de> wrote:
> > 
> > > 
> > > 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).
> > > 
> > > 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.
> > 
> > > 
> > > 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 majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regression on rt kernel while using POSIX timers

[Julia Cartwright]

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

Hello Vedang-

On Thu, Mar 02, 2017 at 03:23:02AM +0000, Patel, Vedang wrote:
[..]
> 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]

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).

   Julia

PS: callstack for cyclictest:
      sigwait() (userspace)
      ...
         do_sigtimedwait()

    callstack for ktimersoftd:
       hrtimer_run_pending()
          posix_timer_fn()
            posix_timer_event()
              send_sigqueue(()

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: Regression on rt kernel while using POSIX timers

[Julia Cartwright]

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

On Fri, Mar 03, 2017 at 01:41:59PM -0600, Julia Cartwright wrote:
> On Thu, Mar 02, 2017 at 03:23:02AM +0000, Patel, Vedang wrote:
[..]
> > 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

A corrected diagram below (same codepaths, layed out differently):

    [ktimersoftd]                [cyclictest]
                                  lock task->sighand
                                  while (!pending signal) {
                                    unlock task->sighand
                                    wait for signal (state S)

                   ... after interval ...

      lock task->sighand
      set pending signal
      signal_wake_up(task)  --->    (woken, state R)
                                    lock task->sighand (*blocked*, state D)
                            <---
      trace signal_generate
      unlock task->sighand
                            --->  }
                                  unlock task->sighand
                                  ...

   Julia

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: Regression on rt kernel while using POSIX timers

[Thomas Gleixner]

On Fri, 3 Mar 2017, Julia Cartwright wrote:
> 
> 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).

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

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

Hi Julia, Thomas, 

Thanks for all the inputs. The information is really helpful in helping
me get a better understanding of the internals. :)

On Fri, 2017-03-03 at 22:09 +0100, Thomas Gleixner wrote:
> On Fri, 3 Mar 2017, Julia Cartwright wrote:
> > 
> > 
> > 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).
> 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.


I believe that it is not manifested in the non-affince scenario because
 the cyclictest process being migrated to another CPU every time it
goes to sleep after calling sigwait(). There are no "additional"
context switches required between ktimersoftd and cyclictest because it
is on a different CPU. 

Also, I am using the '-a' argument  provided by cyclictest to pin the
process to the CPU. This does not pin the main thread. I confirmed it
by using trace-cmd and kernelshark. Also, the number of context
switches for the main thread are pretty low. For example, if I run
100000 loops, there are ~300000 context switches out of which only 1000
are from the main thread. I checked in the mainline kernel and the
softirqs seem to be executing with the interrupts disabled.  Which is
probably why the issue is avoided.

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.

Thanks,
Vedang Patel
Software Engineer
Intel Corporation
> 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

Re: Regression on rt kernel while using POSIX timers

[Thomas Gleixner]

On Fri, 3 Mar 2017, Patel, Vedang wrote:
> 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?

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.

> 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

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

On Mon, 2017-03-06 at 12:29 +0100, Thomas Gleixner wrote:
> On Fri, 3 Mar 2017, Patel, Vedang wrote:
> > 
> > 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.
> 
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. 

Thanks,
Vedang Patel
Software Engineer
Intel Corporation
> > 
> > 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

Re: Regression on rt kernel while using POSIX timers

[Thomas Gleixner]

On Tue, 7 Mar 2017, Patel, Vedang wrote:
> On Mon, 2017-03-06 at 12:29 +0100, Thomas Gleixner wrote:
> 
> > 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?

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

> 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

Re: Regression on rt kernel while using POSIX timers

[Patel, Vedang]

Hi Thomas, 

Thanks for all your input.

On Tue, 2017-03-07 at 18:03 +0100, Thomas Gleixner wrote:
> On Tue, 7 Mar 2017, Patel, Vedang wrote:
> > 
> > On Mon, 2017-03-06 at 12:29 +0100, Thomas Gleixner wrote:
> > 
> > > 
> > > 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?
> Well, we always recommended clock_nanosleep() to be used and to avoid
> signal based timers when ever possible.

I have 2 questions:

1. I see a regression for POSIX timers on real-time kernel from the
mainline kernel for the kernel versions I am using. Has anyone else
seen this? I have tested multiple kernels (4.1, 4.4, 4.9.4) and I am
seeing a regression in all of those. Is this something we expect
because of changes in softirqs?

2. If there is indeed a regression, what is the best way to document
this? I think posting results on https://wiki.linuxfoundation.org/realt
ime/documentation/howto/tools/cyclictest and pointing out regressions
will be one way.

Thanks,
Vedang

> 
> > 
> > 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
> 

Re: Regression on rt kernel while using POSIX timers

[Thomas Gleixner]

On Wed, 1 Mar 2017, Tracy Smith wrote:

First of all, please do not top post and trim your replies.

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

Which regression are you talking about?

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

The issue Vedang and Sebastian are discussing is a configuration
problem. Backing out changes should really solve that.

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

Thanks for the enlightment, we really were unaware about the crucial
importance.

       tglx

Re: Regression on rt kernel while using POSIX timers

[Ran Shalit]

On Mon, Feb 13, 2017 at 8:48 PM, Patel, Vedang <vedang.patel@intel.com> wrote:
> On Fri, 2017-02-10 at 20:07 +0100, Sebastian Andrzej Siewior wrote:
>> On 2017-02-08 18:41:25 [+0000], Patel, Vedang wrote:
>> >
>> > Hi,
>> 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.
>> 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.
>>
> 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?
>
> 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
>

Right.
I did  testing of recent kernels 4.1.15,  with Atom , and the
non-posix timers jitter was obviously better compared to non-posix
(42usec vs 180us),
On trying 4.4.x kernel I seen very strange behavior for both timers
(maybe I applied the patch wrongly or needed to disable some features
in config?) ,

So I decided eventually to use the 4.1.15 with non-posix timers only
with our Atom board. I hope that's a good decision.


> Thanks,
> Vedang
>> >
>> > Thanks,
>> > Vedang Patel
>> > Software Engineer
>> > Intel Corporation
>> Sebastian