Re: [ANNOUNCE] 4.4.148-rt165

[Daniel Wagner]

Hi,

> Known issues:
> 
> - 'stress-ng --ptrace 4' is able to trigger a latency spike of
>     several ms. Usually around 2 - 3ms on two different x86_64 boxes I can
>     test on. 4.9-rt seems to have the same problem. 4.14-rt and 4.16-rt
>     work just fine. Still debugging the issue.

I have a good reproducer for this problem. 

- start 'stress-ng --ptrace 4' in the background
- start 'cyclictest -P 80 -n -m -S -b 2000'  (*)
- start 'trace-cmd start -e all -p function -l '*mutex*'

Few observations:
 - Running cyclictest with '-i 1000 -d 0' -> no latency spikes
 - Tracing spinlocks via "-l '*locks'*" -> no latency spikes

In the trace below the latency spike is on CPU0. It looks like it
doesn't make any progress after signal_generate:


stress-n-1931    0d..11  5060.891219: function:             __try_to_take_rt_mutex
stress-n-1931    0d..11  5060.891219: function:                rt_mutex_dequeue
stress-n-1931    0d..21  5060.891220: function:                rt_mutex_enqueue_pi
stress-n-1931    0....2  5060.891220: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1928 grp=1 res=1
stress-n-1931    0d..21  5060.894114: function:             rt_mutex_dequeue_pi
stress-n-1931    0d.h11  5060.894115: local_timer_entry:    vector=239


While on CPU1 at the same time this happens:


stress-n-1928    1....0  5060.891215: sys_enter:            NR 101 (18, 78b, 0, 0, 17, 788)
stress-n-1928    1d..11  5060.891216: function:             __try_to_take_rt_mutex
stress-n-1928    1d..21  5060.891216: function:                rt_mutex_enqueue_pi
stress-n-1928    1d..21  5060.891217: function:             rt_mutex_dequeue_pi
stress-n-1928    1....1  5060.891217: function:             rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891218: function:                __rt_mutex_adjust_prio
stress-n-1928    1d.h10  5060.894114: local_timer_entry:    vector=239


That is what I have at this point. I looks like rt_mutex could be 
involved in this problem. 

Thanks,
Daniel

(*) In the trace below I am using my rewrite of cyclictest called
    jitterdebugger. Does the same thing just without all the
    whistle and bells. For example it doesn't play with the
    tracer, which allows my to write something like

	cnt=0
	while true ; do
	    trace-cmd start -e all -p function -l '*mutex*' > /dev/null
	    ~/jitterdebugger -b 1000 -f jt-$cnt.json -v
	    trace-cmd extract -o trace-$cnt.dat > /dev/null
	    cnt=$(($cnt + 1))
	done




cpu 0: only

stress-n-1931    0d..20  5060.891195: sched_stat_runtime:   comm=stress-ng-ptrac pid=1931 runtime=6708 [ns] vruntime=1977715609843 [ns]
stress-n-1931    0d..20  5060.891196: sched_stat_wait:      comm=stress-ng-ptrac pid=1927 delay=17045 [ns]
stress-n-1931    0d..20  5060.891196: sched_switch:         stress-ng-ptrac:1931 [120] D ==> stress-ng-ptrac:1927 [120]
stress-n-1931    0d..20  5060.891197: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1927    0d..21  5060.891198: function:             rt_mutex_dequeue_pi
stress-n-1927    0d..11  5060.891199: sched_waking:         comm=stress-ng-ptrac pid=1928 prio=120 target_cpu=001
stress-n-1927    0d..21  5060.891200: sched_stat_runtime:   comm=stress-ng-ptrac pid=1932 runtime=3621 [ns] vruntime=2068053558563 [ns]
stress-n-1927    0d..21  5060.891201: sched_stat_blocked:   comm=stress-ng-ptrac pid=1928 delay=14885 [ns]
stress-n-1927    0d..21  5060.891202: sched_wakeup:         stress-ng-ptrac:1928 [120] success=1 CPU:001
stress-n-1927    0....1  5060.891202: function:             rt_mutex_adjust_prio
stress-n-1927    0d..11  5060.891203: function:                __rt_mutex_adjust_prio
stress-n-1927    0d..20  5060.891203: sched_wait_task:      comm=stress-ng-ptrac pid=1930 prio=120
stress-n-1927    0d..10  5060.891204: sched_waking:         comm=stress-ng-ptrac pid=1930 prio=120 target_cpu=000
stress-n-1927    0d..20  5060.891204: sched_stat_runtime:   comm=stress-ng-ptrac pid=1927 runtime=9515 [ns] vruntime=1977720093354 [ns]
stress-n-1927    0d..20  5060.891205: sched_wakeup:         stress-ng-ptrac:1930 [120] success=1 CPU:000
stress-n-1927    0...10  5060.891205: rcu_utilization:      Start context switch
stress-n-1927    0...10  5060.891206: rcu_utilization:      End context switch
stress-n-1927    0d..20  5060.891206: sched_stat_runtime:   comm=stress-ng-ptrac pid=1927 runtime=2013 [ns] vruntime=1977720095367 [ns]
stress-n-1927    0d..20  5060.891207: sched_stat_wait:      comm=stress-ng-ptrac pid=1930 delay=2013 [ns]
stress-n-1927    0d..20  5060.891207: sched_switch:         stress-ng-ptrac:1927 [120] R ==> stress-ng-ptrac:1930 [120]
stress-n-1927    0d..20  5060.891208: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1930    0d..11  5060.891210: function:             __try_to_take_rt_mutex
stress-n-1930    0d..21  5060.891211: function:                rt_mutex_enqueue_pi
stress-n-1930    0....2  5060.891211: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1927 grp=1 res=1
stress-n-1930    0d..21  5060.891212: function:             rt_mutex_dequeue_pi
stress-n-1930    0....1  5060.891213: function:             rt_mutex_adjust_prio
stress-n-1930    0d..11  5060.891214: function:                __rt_mutex_adjust_prio
stress-n-1930    0...10  5060.891214: rcu_utilization:      Start context switch
stress-n-1930    0...10  5060.891214: rcu_utilization:      End context switch
stress-n-1930    0d..20  5060.891215: sched_stat_runtime:   comm=stress-ng-ptrac pid=1930 runtime=3639 [ns] vruntime=1977714643707 [ns]
stress-n-1930    0d..20  5060.891216: sched_stat_wait:      comm=stress-ng-ptrac pid=1931 delay=3639 [ns]
stress-n-1930    0d..20  5060.891217: sched_switch:         stress-ng-ptrac:1930 [120] t|W ==> stress-ng-ptrac:1931 [120]
stress-n-1930    0d..20  5060.891217: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1931    0d..11  5060.891219: function:             __try_to_take_rt_mutex
stress-n-1931    0d..11  5060.891219: function:                rt_mutex_dequeue
stress-n-1931    0d..21  5060.891220: function:                rt_mutex_enqueue_pi
stress-n-1931    0....2  5060.891220: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1928 grp=1 res=1
stress-n-1931    0d..21  5060.894114: function:             rt_mutex_dequeue_pi
stress-n-1931    0d.h11  5060.894115: local_timer_entry:    vector=239
stress-n-1931    0d.h21  5060.894115: hrtimer_cancel:       hrtimer=0xffff8800c7fabe38
stress-n-1931    0d.h11  5060.894115: hrtimer_expire_entry: hrtimer=0xffff8800c7fabe38 now=5061028001164 function=hrtimer_wakeup/0x0
stress-n-1931    0d.h21  5060.894116: sched_waking:         comm=jitterdebugger pid=2530 prio=19 target_cpu=000
stress-n-1931    0dNh31  5060.894117: sched_wakeup:         jitterdebugger:2530 [19] success=1 CPU:000
stress-n-1931    0dNh11  5060.894117: hrtimer_expire_exit:  hrtimer=0xffff8800c7fabe38
stress-n-1931    0dNh21  5060.894117: hrtimer_cancel:       hrtimer=0xffff88012fc10d80
stress-n-1931    0dNh11  5060.894118: hrtimer_expire_entry: hrtimer=0xffff88012fc10d80 now=5061028001164 function=tick_sched_timer/0x0
stress-n-1931    0dNh21  5060.894119: sched_stat_runtime:   comm=stress-ng-ptrac pid=1931 runtime=2904713 [ns] vruntime=1977718514556 [ns]
stress-n-1931    0dNh11  5060.894121: softirq_raise:        vec=7 [action=SCHED]
stress-n-1931    0dNh11  5060.894121: softirq_raise:        vec=1 [action=TIMER]
stress-n-1931    0dNh11  5060.894122: rcu_utilization:      Start scheduler-tick
stress-n-1931    0dNh11  5060.894122: rcu_utilization:      End scheduler-tick
stress-n-1931    0dNh11  5060.894123: hrtimer_expire_exit:  hrtimer=0xffff88012fc10d80
stress-n-1931    0dNh21  5060.894123: hrtimer_start:        hrtimer=0xffff88012fc10d80 function=tick_sched_timer/0x0 expires=5061032000000 softexpires=5061032000000
stress-n-1931    0dNh11  5060.894124: local_timer_exit:     vector=239
stress-n-1931    0dN.21  5060.894124: sched_waking:         comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
stress-n-1931    0dN.31  5060.894125: sched_stat_sleep:     comm=ksoftirqd/0 pid=3 delay=3977690 [ns]
stress-n-1931    0dN.31  5060.894125: sched_wakeup:         ksoftirqd/0:3 [120] success=1 CPU:000
stress-n-1931    0dN.21  5060.894126: sched_waking:         comm=ktimersoftd/0 pid=4 prio=98 target_cpu=000
stress-n-1931    0dN.31  5060.894127: sched_wakeup:         ktimersoftd/0:4 [98] success=1 CPU:000
stress-n-1931    0.N.11  5060.894127: rcu_utilization:      Start context switch
stress-n-1931    0.N.11  5060.894128: rcu_utilization:      End context switch
stress-n-1931    0dN.21  5060.894128: sched_stat_runtime:   comm=stress-ng-ptrac pid=1931 runtime=7046 [ns] vruntime=1977718521602 [ns]
stress-n-1931    0d..21  5060.894129: sched_switch:         stress-ng-ptrac:1931 [120] R ==> jitterdebugger:2530 [19]
stress-n-1931    0d..21  5060.894130: tlb_flush:            pages=-1 reason=flush on task switch (0)
jitterde-2530    0....0  5060.894131: sys_exit:             NR 230 = 0
jitterde-2530    0....0  5060.894140: sys_enter:            NR 1 (5, 7f25ae652eb0, 10, 75, 1, 10)
jitterde-2530    0....0  5060.894140: function:             _mutex_lock
jitterde-2530    0....0  5060.894141: function:                rt_mutex_lock
jitterde-2530    0....1  5060.894144: print:                tracing_mark_write: Hit latency 2696
jitterde-2530    0....0  5060.894145: function:             _mutex_unlock
jitterde-2530    0....0  5060.894145: function:                rt_mutex_unlock
jitterde-2530    0....0  5060.894145: sys_exit:             NR 1 = 16
jitterde-2530    0....0  5060.894146: sys_enter:            NR 1 (4, 402194, 2, 75, 1, 10)
jitterde-2530    0....0  5060.894147: function:             _mutex_lock
jitterde-2530    0....0  5060.894147: function:                rt_mutex_lock
jitterde-2530    0....0  5060.894149: function:             _mutex_lock
jitterde-2530    0....0  5060.894149: function:                rt_mutex_lock



cpu 1 only

stress-n-1929    1d..20  5060.891169: sched_stat_runtime:   comm=stress-ng-ptrac pid=1929 runtime=5688 [ns] vruntime=2068054001980 [ns]
stress-n-1929    1d..20  5060.891170: sched_stat_wait:      comm=stress-ng-ptrac pid=1928 delay=5688 [ns]
stress-n-1929    1d..20  5060.891170: sched_switch:         stress-ng-ptrac:1929 [120] R ==> stress-ng-ptrac:1928 [120]
stress-n-1929    1d..20  5060.891171: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1928    1....0  5060.891172: sys_exit:             NR 61 = 1931
stress-n-1928    1....0  5060.891173: sys_enter:            NR 101 (18, 78b, 0, 0, 17, 788)
stress-n-1928    1d..20  5060.891174: sched_wait_task:      comm=stress-ng-ptrac pid=1931 prio=120
stress-n-1928    1d..10  5060.891175: sched_waking:         comm=stress-ng-ptrac pid=1931 prio=120 target_cpu=000
stress-n-1928    1d..20  5060.891176: sched_stat_runtime:   comm=stress-ng-ptrac pid=1927 runtime=7937 [ns] vruntime=1977720081607 [ns]
stress-n-1928    1d..20  5060.891177: sched_wakeup:         stress-ng-ptrac:1931 [120] success=1 CPU:000
stress-n-1928    1....0  5060.891178: sys_exit:             NR 101 = 0
stress-n-1928    1....0  5060.891178: sys_enter:            NR 61 (78b, 7fff38c319f4, 0, 0, 17, 788)
stress-n-1928    1....0  5060.891179: sched_process_wait:   comm=stress-ng-ptrac pid=1931 prio=120
stress-n-1928    1d..11  5060.891179: function:             __try_to_take_rt_mutex
stress-n-1928    1d..11  5060.891180: function:             task_blocks_on_rt_mutex
stress-n-1928    1d..21  5060.891180: function:                __rt_mutex_adjust_prio
stress-n-1928    1d..21  5060.891180: function:                rt_mutex_enqueue
stress-n-1928    1d..21  5060.891180: function:                rt_mutex_dequeue_pi
stress-n-1928    1d..21  5060.891181: function:                rt_mutex_enqueue_pi
stress-n-1928    1d..21  5060.891181: function:                __rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891181: function:             __try_to_take_rt_mutex
stress-n-1928    1...10  5060.891184: rcu_utilization:      Start context switch
stress-n-1928    1...10  5060.891184: rcu_utilization:      End context switch
stress-n-1928    1d..20  5060.891185: sched_stat_runtime:   comm=stress-ng-ptrac pid=1928 runtime=16814 [ns] vruntime=2068049707094 [ns]
stress-n-1928    1d..20  5060.891186: sched_stat_wait:      comm=stress-ng-ptrac pid=1929 delay=16814 [ns]
stress-n-1928    1d..20  5060.891187: sched_switch:         stress-ng-ptrac:1928 [120] D ==> stress-ng-ptrac:1929 [120]
stress-n-1928    1d..20  5060.891187: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1929    1d..20  5060.891188: sched_wait_task:      comm=stress-ng-ptrac pid=1932 prio=120
stress-n-1929    1d..10  5060.891188: sched_waking:         comm=stress-ng-ptrac pid=1932 prio=120 target_cpu=001
stress-n-1929    1d..20  5060.891189: sched_stat_runtime:   comm=stress-ng-ptrac pid=1929 runtime=4262 [ns] vruntime=2068054006242 [ns]
stress-n-1929    1d..20  5060.891190: sched_wakeup:         stress-ng-ptrac:1932 [120] success=1 CPU:001
stress-n-1929    1....0  5060.891191: sys_exit:             NR 101 = 0
stress-n-1929    1....0  5060.891192: sys_enter:            NR 61 (78c, 7fff38c319f4, 0, 0, 17, 789)
stress-n-1929    1....0  5060.891192: sched_process_wait:   comm=stress-ng-ptrac pid=1932 prio=120
stress-n-1929    1d..11  5060.891194: function:             __try_to_take_rt_mutex
stress-n-1929    1d..11  5060.891194: function:             task_blocks_on_rt_mutex
stress-n-1929    1d..21  5060.891194: function:                __rt_mutex_adjust_prio
stress-n-1929    1d..21  5060.891195: function:                rt_mutex_enqueue
stress-n-1929    1d..11  5060.891195: function:             __try_to_take_rt_mutex
stress-n-1929    1...10  5060.891195: rcu_utilization:      Start context switch
stress-n-1929    1...10  5060.891196: rcu_utilization:      End context switch
stress-n-1929    1d..20  5060.891196: sched_stat_runtime:   comm=stress-ng-ptrac pid=1929 runtime=7002 [ns] vruntime=2068054013244 [ns]
stress-n-1929    1d..20  5060.891197: sched_stat_wait:      comm=stress-ng-ptrac pid=1932 delay=7002 [ns]
stress-n-1929    1d..20  5060.891198: sched_switch:         stress-ng-ptrac:1929 [120] D ==> stress-ng-ptrac:1932 [120]
stress-n-1929    1d..20  5060.891198: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1932    1d..11  5060.891200: function:             __try_to_take_rt_mutex
stress-n-1932    1d..21  5060.891201: function:                rt_mutex_enqueue_pi
stress-n-1932    1....2  5060.891201: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1929 grp=1 res=1
stress-n-1932    1d.h.3  5060.891202: reschedule_entry:     vector=253
stress-n-1932    1d.h.3  5060.891202: reschedule_exit:      vector=253
stress-n-1932    1d..21  5060.891203: function:             rt_mutex_dequeue_pi
stress-n-1932    1....1  5060.891204: function:             rt_mutex_adjust_prio
stress-n-1932    1d..11  5060.891204: function:                __rt_mutex_adjust_prio
stress-n-1932    1...10  5060.891204: rcu_utilization:      Start context switch
stress-n-1932    1...10  5060.891205: rcu_utilization:      End context switch
stress-n-1932    1d..20  5060.891206: sched_stat_runtime:   comm=stress-ng-ptrac pid=1932 runtime=5495 [ns] vruntime=2068053564058 [ns]
stress-n-1932    1d..20  5060.891206: sched_stat_wait:      comm=stress-ng-ptrac pid=1928 delay=5495 [ns]
stress-n-1932    1d..20  5060.891207: sched_switch:         stress-ng-ptrac:1932 [120] R ==> stress-ng-ptrac:1928 [120]
stress-n-1932    1d..20  5060.891207: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1928    1d..11  5060.891208: function:             __try_to_take_rt_mutex
stress-n-1928    1d..11  5060.891208: function:                rt_mutex_dequeue
stress-n-1928    1d..21  5060.891209: function:                rt_mutex_enqueue_pi
stress-n-1928    1d..21  5060.891210: function:             rt_mutex_dequeue_pi
stress-n-1928    1d..11  5060.891210: sched_waking:         comm=stress-ng-ptrac pid=1931 prio=120 target_cpu=000
stress-n-1928    1d..21  5060.891211: sched_stat_runtime:   comm=stress-ng-ptrac pid=1930 runtime=4893 [ns] vruntime=1977714640068 [ns]
stress-n-1928    1d..21  5060.891212: sched_stat_blocked:   comm=stress-ng-ptrac pid=1931 delay=16421 [ns]
stress-n-1928    1d..21  5060.891213: sched_wakeup:         stress-ng-ptrac:1931 [120] success=1 CPU:000
stress-n-1928    1....1  5060.891213: function:             rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891214: function:                __rt_mutex_adjust_prio
stress-n-1928    1....0  5060.891214: sys_exit:             NR 61 = 1931
stress-n-1928    1....0  5060.891215: sys_enter:            NR 101 (18, 78b, 0, 0, 17, 788)
stress-n-1928    1d..11  5060.891216: function:             __try_to_take_rt_mutex
stress-n-1928    1d..21  5060.891216: function:                rt_mutex_enqueue_pi
stress-n-1928    1d..21  5060.891217: function:             rt_mutex_dequeue_pi
stress-n-1928    1....1  5060.891217: function:             rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891218: function:                __rt_mutex_adjust_prio
stress-n-1928    1d.h10  5060.894114: local_timer_entry:    vector=239
stress-n-1928    1d.h20  5060.894115: hrtimer_cancel:       hrtimer=0xffff88012fc90d80
stress-n-1928    1d.h10  5060.894115: hrtimer_expire_entry: hrtimer=0xffff88012fc90d80 now=5061028000906 function=tick_sched_timer/0x0
stress-n-1928    1d.h20  5060.894116: sched_stat_runtime:   comm=stress-ng-ptrac pid=1928 runtime=2911118 [ns] vruntime=2068052618212 [ns]
stress-n-1928    1d.h10  5060.894118: softirq_raise:        vec=7 [action=SCHED]
stress-n-1928    1d.h10  5060.894118: softirq_raise:        vec=1 [action=TIMER]
stress-n-1928    1d.h10  5060.894119: rcu_utilization:      Start scheduler-tick
stress-n-1928    1d.h10  5060.894119: rcu_utilization:      End scheduler-tick
stress-n-1928    1d.h10  5060.894120: hrtimer_expire_exit:  hrtimer=0xffff88012fc90d80
stress-n-1928    1d.h20  5060.894120: hrtimer_start:        hrtimer=0xffff88012fc90d80 function=tick_sched_timer/0x0 expires=5061032000000 softexpires=5061032000000
stress-n-1928    1d.h10  5060.894121: local_timer_exit:     vector=239
stress-n-1928    1d..20  5060.894121: sched_waking:         comm=ksoftirqd/1 pid=18 prio=120 target_cpu=001
stress-n-1928    1d..30  5060.894122: sched_stat_sleep:     comm=ksoftirqd/1 pid=18 delay=3989353 [ns]
stress-n-1928    1d..30  5060.894123: sched_wakeup:         ksoftirqd/1:18 [120] success=1 CPU:001
stress-n-1928    1d..20  5060.894123: sched_waking:         comm=ktimersoftd/1 pid=17 prio=98 target_cpu=001
stress-n-1928    1dN.30  5060.894124: sched_wakeup:         ktimersoftd/1:17 [98] success=1 CPU:001
stress-n-1928    1.N.10  5060.894125: rcu_utilization:      Start context switch
stress-n-1928    1.N.10  5060.894125: rcu_utilization:      End context switch
stress-n-1928    1dN.20  5060.894126: sched_stat_runtime:   comm=stress-ng-ptrac pid=1928 runtime=7454 [ns] vruntime=2068052625666 [ns]
stress-n-1928    1d..20  5060.894127: sched_switch:         stress-ng-ptrac:1928 [120] R ==> ktimersoftd/1:17 [98]
ktimerso-17      1....1  5060.894128: softirq_entry:        vec=1 [action=TIMER]
ktimerso-17      1....1  5060.894129: softirq_exit:         vec=1 [action=TIMER]
ktimerso-17      1...10  5060.894129: rcu_utilization:      Start context switch
ktimerso-17      1...10  5060.894130: rcu_utilization:      End context switch
ktimerso-17      1d..20  5060.894131: sched_stat_wait:      comm=ksoftirqd/1 pid=18 delay=8463 [ns]
ktimerso-17      1d..20  5060.894131: sched_switch:         ktimersoftd/1:17 [98] S ==> ksoftirqd/1:18 [120]
ksoftirq-18      1....1  5060.894132: softirq_entry:        vec=7 [action=SCHED]
ksoftirq-18      1....1  5060.894133: softirq_exit:         vec=7 [action=SCHED]
ksoftirq-18      1...10  5060.894134: rcu_utilization:      Start context switch
ksoftirq-18      1...10  5060.894134: rcu_utilization:      End context switch
ksoftirq-18      1d..20  5060.894134: sched_stat_runtime:   comm=ksoftirqd/1 pid=18 runtime=4140 [ns] vruntime=8977334018960 [ns]
ksoftirq-18      1d..20  5060.894135: sched_stat_wait:      comm=stress-ng-ptrac pid=1928 delay=10680 [ns]
ksoftirq-18      1d..20  5060.894136: sched_switch:         ksoftirqd/1:18 [120] S ==> stress-ng-ptrac:1928 [120]
stress-n-1928    1d..20  5060.894137: sched_wait_task:      comm=stress-ng-ptrac pid=1931 prio=120
stress-n-1928    1....0  5060.894137: hrtimer_init:         hrtimer=0xffff8800c8043dc0 clockid=CLOCK_MONOTONIC mode=0x1
stress-n-1928    1d..10  5060.894137: hrtimer_start:        hrtimer=0xffff8800c8043dc0 function=hrtimer_wakeup/0x0 expires=5061032023604 softexpires=5061032023604
stress-n-1928    1...10  5060.894138: rcu_utilization:      Start context switch
stress-n-1928    1...10  5060.894138: rcu_utilization:      End context switch
stress-n-1928    1d..20  5060.894139: sched_stat_runtime:   comm=stress-ng-ptrac pid=1928 runtime=4271 [ns] vruntime=2068052629937 [ns]
stress-n-1928    1d..20  5060.894140: sched_stat_wait:      comm=stress-ng-ptrac pid=1932 delay=2933523 [ns]
stress-n-1928    1d..20  5060.894140: sched_switch:         stress-ng-ptrac:1928 [120] D ==> stress-ng-ptrac:1932 [120]
stress-n-1928    1d..20  5060.894141: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1932    1...10  5060.894142: rcu_utilization:      Start context switch
stress-n-1932    1...10  5060.894142: rcu_utilization:      End context switch
stress-n-1932    1d..20  5060.894142: sched_stat_runtime:   comm=stress-ng-ptrac pid=1932 runtime=3690 [ns] vruntime=2068053567748 [ns]
stress-n-1932    1d..20  5060.894143: sched_switch:         stress-ng-ptrac:1932 [120] t|W ==> swapper/1:0 [120]
  <idle>-0       1d..10  5060.894145: cpu_idle:             state=1 cpu_id=1




cpu 0 and 1:

stress-n-1932    1d..20  5060.891207: sched_switch:         stress-ng-ptrac:1932 [120] R ==> stress-ng-ptrac:1928 [120]
stress-n-1927    0d..20  5060.891207: sched_stat_wait:      comm=stress-ng-ptrac pid=1930 delay=2013 [ns]
stress-n-1927    0d..20  5060.891207b: sched_switch:         stress-ng-ptrac:1927 [120] R ==> stress-ng-ptrac:1930 [120]
stress-n-1932    1d..20  5060.891207: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1927    0d..20  5060.891208: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1928    1d..11  5060.891208: function:             __try_to_take_rt_mutex
stress-n-1928    1d..11  5060.891208: function:                rt_mutex_dequeue
stress-n-1928    1d..21  5060.891209: function:                rt_mutex_enqueue_pi
stress-n-1928    1d..21  5060.891210: function:             rt_mutex_dequeue_pi
stress-n-1930    0d..11  5060.891210: function:             __try_to_take_rt_mutex
stress-n-1928    1d..11  5060.891210: sched_waking:         comm=stress-ng-ptrac pid=1931 prio=120 target_cpu=000
stress-n-1930    0d..21  5060.891211: function:                rt_mutex_enqueue_pi
stress-n-1930    0....2  5060.891211: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1927 grp=1 res=1
stress-n-1928    1d..21  5060.891211: sched_stat_runtime:   comm=stress-ng-ptrac pid=1930 runtime=4893 [ns] vruntime=1977714640068 [ns]
stress-n-1930    0d..21  5060.891212: function:             rt_mutex_dequeue_pi
stress-n-1928    1d..21  5060.891212: sched_stat_blocked:   comm=stress-ng-ptrac pid=1931 delay=16421 [ns]
stress-n-1928    1d..21  5060.891213: sched_wakeup:         stress-ng-ptrac:1931 [120] success=1 CPU:000
stress-n-1928    1....1  5060.891213: function:             rt_mutex_adjust_prio
stress-n-1930    0....1  5060.891213: function:             rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891214: function:                __rt_mutex_adjust_prio
stress-n-1930    0d..11  5060.891214: function:                __rt_mutex_adjust_prio
stress-n-1930    0...10  5060.891214: rcu_utilization:      Start context switch
stress-n-1930    0...10  5060.891214: rcu_utilization:      End context switch
stress-n-1928    1....0  5060.891214: sys_exit:             NR 61 = 1931
stress-n-1930    0d..20  5060.891215: sched_stat_runtime:   comm=stress-ng-ptrac pid=1930 runtime=3639 [ns] vruntime=1977714643707 [ns]
stress-n-1928    1....0  5060.891215: sys_enter:            NR 101 (18, 78b, 0, 0, 17, 788)
stress-n-1928    1d..11  5060.891216: function:             __try_to_take_rt_mutex
stress-n-1930    0d..20  5060.891216: sched_stat_wait:      comm=stress-ng-ptrac pid=1931 delay=3639 [ns]
stress-n-1928    1d..21  5060.891216: function:                rt_mutex_enqueue_pi
stress-n-1930    0d..20  5060.891217: sched_switch:         stress-ng-ptrac:1930 [120] t|W ==> stress-ng-ptrac:1931 [120]
stress-n-1928    1d..21  5060.891217: function:             rt_mutex_dequeue_pi
stress-n-1930    0d..20  5060.891217: tlb_flush:            pages=-1 reason=flush on task switch (0)
stress-n-1928    1....1  5060.891217: function:             rt_mutex_adjust_prio
stress-n-1928    1d..11  5060.891218: function:                __rt_mutex_adjust_prio
stress-n-1931    0d..11  5060.891219: function:             __try_to_take_rt_mutex
stress-n-1931    0d..11  5060.891219: function:                rt_mutex_dequeue
stress-n-1931    0d..21  5060.891220: function:                rt_mutex_enqueue_pi
stress-n-1931    0....2  5060.891220: signal_generate:      sig=17 errno=0 code=262148 comm=stress-ng-ptrac pid=1928 grp=1 res=1
stress-n-1931    0d..21  5060.894114: function:             rt_mutex_dequeue_pi
stress-n-1928    1d.h10  5060.894114: local_timer_entry:    vector=239
stress-n-1931    0d.h11  5060.894115: local_timer_entry:    vector=239
stress-n-1928    1d.h20  5060.894115: hrtimer_cancel:       hrtimer=0xffff88012fc90d80
stress-n-1931    0d.h21  5060.894115: hrtimer_cancel:       hrtimer=0xffff8800c7fabe38
stress-n-1928    1d.h10  5060.894115: hrtimer_expire_entry: hrtimer=0xffff88012fc90d80 now=5061028000906 function=tick_sched_timer/0x0
stress-n-1931    0d.h11  5060.894115: hrtimer_expire_entry: hrtimer=0xffff8800c7fabe38 now=5061028001164 function=hrtimer_wakeup/0x0
stress-n-1931    0d.h21  5060.894116: sched_waking:         comm=jitterdebugger pid=2530 prio=19 target_cpu=000
stress-n-1928    1d.h20  5060.894116: sched_stat_runtime:   comm=stress-ng-ptrac pid=1928 runtime=2911118 [ns] vruntime=2068052618212 [ns]
stress-n-1931    0dNh31  5060.894117: sched_wakeup:         jitterdebugger:2530 [19] success=1 CPU:000
stress-n-1931    0dNh11  5060.894117: hrtimer_expire_exit:  hrtimer=0xffff8800c7fabe38
stress-n-1931    0dNh21  5060.894117: hrtimer_cancel:       hrtimer=0xffff88012fc10d80