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:
signature.asc
Description: PGP signature
