* Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
@ 2022-10-05 7:46 Florian Paul Schmidt
2022-10-05 13:31 ` Sebastian Andrzej Siewior
0 siblings, 1 reply; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-05 7:46 UTC (permalink / raw)
To: linux-rt-users
Dear rt-users,
I was happily using kernel version 5.4.84-rt47 on this Celeron j4125
system (all power management and cpu frequency scaling disabled in bios)
and it was working great. Worst case cyclictest latency was around 30 to
40 us depending on system load.
Due to some USB fixes landing in 5.14 I went and tried upgrading my
kernel. I started with 5.19-rt10 but something weird showed up:
cyclictest reported _huge_ latencies on one of the four cores (thread 1
of cyclictest) of around 700 us. So I went back to my old kernel to make
sure it really was the kernel and sure thing. The old kernel still had
the nice 30 to 40 us worst case latencies I determined previously. So I
went through some kernel versions:
5.19-rt10 has the problem
5.17.1-rt17 has the problem
5.16.2-rt19 does not have the problem
So I would guess somewhere between 5.16.2-rt19 and 5.17.1-rt17 something
horrible happened ;)
Maybe interesting fact: It is always thread 1 of cyclictest that shows
the large latency. The other threads are seemingly completely in-line
with the expectation of 30 - 40 us.
Here's my cyclictest command:
sudo ./cyclictest -m -p 95 -S -M
cyclictest at stable/v1.0
I would possibly be willing to git bisect the issue. But I am a little
bit confused about how to go about that. What repo/tree would I
precisely bisect (I am using the the patch tarballs from
https://cdn.kernel.org/pub/linux/kernel/projects/rt/)?
Kind regards,
FPS
--
https://fps.io
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 7:46 Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17 Florian Paul Schmidt
@ 2022-10-05 13:31 ` Sebastian Andrzej Siewior
2022-10-05 14:45 ` Daniel Bristot de Oliveira
2022-10-05 16:20 ` Florian Paul Schmidt
0 siblings, 2 replies; 11+ messages in thread
From: Sebastian Andrzej Siewior @ 2022-10-05 13:31 UTC (permalink / raw)
To: Florian Paul Schmidt; +Cc: linux-rt-users
On 2022-10-05 09:46:30 [+0200], Florian Paul Schmidt wrote:
> 5.19-rt10 has the problem
> 5.17.1-rt17 has the problem
> 5.16.2-rt19 does not have the problem
Could you check v5.17-rc1-rt1? Maybe it was introduced in v5.17 cycle.
> I would possibly be willing to git bisect the issue. But I am a little
> bit confused about how to go about that. What repo/tree would I
> precisely bisect (I am using the the patch tarballs from
> https://cdn.kernel.org/pub/linux/kernel/projects/rt/)?
if it got introduced post v5.17-rc1-rt1 then we could try to bisect it.
Otherwise we would have to trace it. Since the latency spike is huge, it
should be easy to spot.
Sebastian
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 13:31 ` Sebastian Andrzej Siewior
@ 2022-10-05 14:45 ` Daniel Bristot de Oliveira
2022-10-05 16:17 ` Florian Paul Schmidt
2022-10-05 16:20 ` Florian Paul Schmidt
1 sibling, 1 reply; 11+ messages in thread
From: Daniel Bristot de Oliveira @ 2022-10-05 14:45 UTC (permalink / raw)
To: Sebastian Andrzej Siewior, Florian Paul Schmidt; +Cc: linux-rt-users
On 10/5/22 15:31, Sebastian Andrzej Siewior wrote:
> On 2022-10-05 09:46:30 [+0200], Florian Paul Schmidt wrote:
>> 5.19-rt10 has the problem
>> 5.17.1-rt17 has the problem
>> 5.16.2-rt19 does not have the problem
> Could you check v5.17-rc1-rt1? Maybe it was introduced in v5.17 cycle.
>
>> I would possibly be willing to git bisect the issue. But I am a little
>> bit confused about how to go about that. What repo/tree would I
>> precisely bisect (I am using the the patch tarballs from
>> https://cdn.kernel.org/pub/linux/kernel/projects/rt/)?
> if it got introduced post v5.17-rc1-rt1 then we could try to bisect it.
> Otherwise we would have to trace it. Since the latency spike is huge, it
> should be easy to spot.
try:
# timerlat -a 100
wait for it to stop and save the trace. Then see what the trace points out at the
end of the trace.
-- Daniel
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 14:45 ` Daniel Bristot de Oliveira
@ 2022-10-05 16:17 ` Florian Paul Schmidt
2022-10-05 16:23 ` Daniel Bristot de Oliveira
0 siblings, 1 reply; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-05 16:17 UTC (permalink / raw)
To: Daniel Bristot de Oliveira, Sebastian Andrzej Siewior; +Cc: linux-rt-users
Am 05/10/2022 um 16:45 schrieb Daniel Bristot de Oliveira:
> On 10/5/22 15:31, Sebastian Andrzej Siewior wrote:
>> On 2022-10-05 09:46:30 [+0200], Florian Paul Schmidt wrote:
>>> 5.19-rt10 has the problem
>>> 5.17.1-rt17 has the problem
>>> 5.16.2-rt19 does not have the problem
>> Could you check v5.17-rc1-rt1? Maybe it was introduced in v5.17 cycle.
>>
>>> I would possibly be willing to git bisect the issue. But I am a little
>>> bit confused about how to go about that. What repo/tree would I
>>> precisely bisect (I am using the the patch tarballs from
>>> https://cdn.kernel.org/pub/linux/kernel/projects/rt/)?
>> if it got introduced post v5.17-rc1-rt1 then we could try to bisect it.
>> Otherwise we would have to trace it. Since the latency spike is huge, it
>> should be easy to spot.
>
> try:
> # timerlat -a 100
>
> wait for it to stop and save the trace. Then see what the trace points out at the
> end of the trace.
What package contains the timerlat command? I gathered from searching
online for timerlat that it is part of the tracing machinery but I
didn't find the executable itself..
Kind regards,
FPS
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 13:31 ` Sebastian Andrzej Siewior
2022-10-05 14:45 ` Daniel Bristot de Oliveira
@ 2022-10-05 16:20 ` Florian Paul Schmidt
1 sibling, 0 replies; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-05 16:20 UTC (permalink / raw)
To: Sebastian Andrzej Siewior; +Cc: linux-rt-users
Am 05/10/2022 um 15:31 schrieb Sebastian Andrzej Siewior:
> On 2022-10-05 09:46:30 [+0200], Florian Paul Schmidt wrote:
>> 5.19-rt10 has the problem
>> 5.17.1-rt17 has the problem
>> 5.16.2-rt19 does not have the problem
>
> Could you check v5.17-rc1-rt1? Maybe it was introduced in v5.17 cycle.
Will do!
>> I would possibly be willing to git bisect the issue. But I am a little
>> bit confused about how to go about that. What repo/tree would I
>> precisely bisect (I am using the the patch tarballs from
>> https://cdn.kernel.org/pub/linux/kernel/projects/rt/)?
>
> if it got introduced post v5.17-rc1-rt1 then we could try to bisect it.
> Otherwise we would have to trace it. Since the latency spike is huge, it
> should be easy to spot.
Will try and see if I get the tracing working afterwards (will take a
while - slow PC) :)
Kind regards,
FPS
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 16:17 ` Florian Paul Schmidt
@ 2022-10-05 16:23 ` Daniel Bristot de Oliveira
2022-10-06 3:25 ` Florian Paul Schmidt
0 siblings, 1 reply; 11+ messages in thread
From: Daniel Bristot de Oliveira @ 2022-10-05 16:23 UTC (permalink / raw)
To: Florian Paul Schmidt, Sebastian Andrzej Siewior; +Cc: linux-rt-users
On 10/5/22 18:17, Florian Paul Schmidt wrote:
>> try:
>> # timerlat -a 100
>>
>> wait for it to stop and save the trace. Then see what the trace points out at the
>> end of the trace.
>
> What package contains the timerlat command? I gathered from searching
> online for timerlat that it is part of the tracing machinery but I
> didn't find the executable itself..
on fedora it is part of rtla, but you can compile it from the kernel source:
$ cd tools/tracing/rtla/
$ make
$ sudo make install
-- Daniel
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-05 16:23 ` Daniel Bristot de Oliveira
@ 2022-10-06 3:25 ` Florian Paul Schmidt
2022-10-06 6:27 ` Sebastian Andrzej Siewior
0 siblings, 1 reply; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-06 3:25 UTC (permalink / raw)
To: Daniel Bristot de Oliveira, Sebastian Andrzej Siewior; +Cc: linux-rt-users
[-- Attachment #1: Type: text/plain, Size: 1070 bytes --]
On 10/5/22 18:23, Daniel Bristot de Oliveira wrote:
> On 10/5/22 18:17, Florian Paul Schmidt wrote:
>>> try:
>>> # timerlat -a 100
>>>
>>> wait for it to stop and save the trace. Then see what the trace points out at the
>>> end of the trace.
>>
>> What package contains the timerlat command? I gathered from searching
>> online for timerlat that it is part of the tracing machinery but I
>> didn't find the executable itself..
>
> on fedora it is part of rtla, but you can compile it from the kernel source:
>
> $ cd tools/tracing/rtla/
> $ make
> $ sudo make install
$ uname -a Linux ogfx86 5.17.0-rc1-rt1 #1-NixOS SMP PREEMPT_RT Sun Jan
23 08:12:53 UTC 2022 x86_64 GNU/Linux
I ran this command to produce a couple of traces (rtla timerlat from the
5.17-rc1 source didn't have an -a option(
$ for n in 1 2 3 4 5; do sudo ./rtla timerlat -T 100 -s 100 \
-t=trace"$n".txt; done
They are 13M each. Attached are just the tails for a start. Do you want
to see the whole thing?
FPS
[-- Attachment #2: trace1.txt.tail --]
[-- Type: text/plain, Size: 13650 bytes --]
<idle>-0 [002] dp..3.. 1052.612790: thread_noise: swapper/2:0 start 1052.612783310 duration 2426 ns
timerlat/2-5126 [002] .p..... 1052.612790: #10199 context thread timer_latency 9169 ns
<idle>-0 [003] dp.h1.. 1052.613487: #10199 context irq timer_latency 2817 ns
<idle>-0 [003] dN.h2.. 1052.613491: irq_noise: local_timer:236 start 1052.613486553 duration 3924 ns
<idle>-0 [003] dp..3.. 1052.613493: thread_noise: swapper/3:0 start 1052.613486797 duration 2583 ns
timerlat/3-5127 [003] .p..... 1052.613494: #10199 context thread timer_latency 9957 ns
<idle>-0 [000] dp.h1.. 1052.613672: #10200 context irq timer_latency 3153 ns
<idle>-0 [000] dN.h2.. 1052.613676: irq_noise: local_timer:236 start 1052.613671194 duration 4699 ns
<idle>-0 [000] dp..3.. 1052.613678: thread_noise: swapper/0:0 start 1052.613671411 duration 2449 ns
timerlat/0-5124 [000] .p..... 1052.613679: #10200 context thread timer_latency 10908 ns
<idle>-0 [001] dp.h1.. 1052.613727: #10200 context irq timer_latency 2296 ns
<idle>-0 [001] dN.h2.. 1052.613731: irq_noise: local_timer:236 start 1052.613726660 duration 4058 ns
<idle>-0 [001] dp..3.. 1052.613733: thread_noise: swapper/1:0 start 1052.613726886 duration 2255 ns
timerlat/1-5125 [001] .p..... 1052.613734: #10200 context thread timer_latency 9489 ns
<idle>-0 [002] dp.h1.. 1052.613784: #10200 context irq timer_latency 2332 ns
<idle>-0 [002] dN.h2.. 1052.613787: irq_noise: local_timer:236 start 1052.613783127 duration 3902 ns
<idle>-0 [002] dp..3.. 1052.613790: thread_noise: swapper/2:0 start 1052.613783359 duration 2358 ns
timerlat/2-5126 [002] .p..... 1052.613790: #10200 context thread timer_latency 9162 ns
<idle>-0 [003] dp.h1.. 1052.614487: #10200 context irq timer_latency 2748 ns
<idle>-0 [003] dN.h2.. 1052.614491: irq_noise: local_timer:236 start 1052.614486476 duration 3895 ns
<idle>-0 [003] dp..3.. 1052.614493: thread_noise: swapper/3:0 start 1052.614486712 duration 2475 ns
timerlat/3-5127 [003] .p..... 1052.614494: #10200 context thread timer_latency 9743 ns
<idle>-0 [000] dp.h1.. 1052.614671: #10201 context irq timer_latency 2387 ns
<idle>-0 [000] dN.h2.. 1052.614675: irq_noise: local_timer:236 start 1052.614670410 duration 4362 ns
<idle>-0 [000] dp..3.. 1052.614677: thread_noise: swapper/0:0 start 1052.614670629 duration 2428 ns
timerlat/0-5124 [000] .p..... 1052.614678: #10201 context thread timer_latency 9786 ns
<idle>-0 [001] dp.h1.. 1052.614727: #10201 context irq timer_latency 2327 ns
<idle>-0 [001] dN.h2.. 1052.614731: irq_noise: local_timer:236 start 1052.614726667 duration 4058 ns
<idle>-0 [001] dp..3.. 1052.614733: thread_noise: swapper/1:0 start 1052.614726901 duration 2329 ns
timerlat/1-5125 [001] .p..... 1052.614734: #10201 context thread timer_latency 9422 ns
<idle>-0 [002] dp.h1.. 1052.614784: #10201 context irq timer_latency 2351 ns
<idle>-0 [002] dN.h2.. 1052.614787: irq_noise: local_timer:236 start 1052.614783140 duration 3883 ns
<idle>-0 [002] dp..3.. 1052.614790: thread_noise: swapper/2:0 start 1052.614783362 duration 2406 ns
timerlat/2-5126 [002] .p..... 1052.614790: #10201 context thread timer_latency 9214 ns
<idle>-0 [003] dp.h1.. 1052.615487: #10201 context irq timer_latency 2791 ns
<idle>-0 [003] dN.h2.. 1052.615491: irq_noise: local_timer:236 start 1052.615486493 duration 3991 ns
<idle>-0 [003] dp..3.. 1052.615493: thread_noise: swapper/3:0 start 1052.615486739 duration 2535 ns
timerlat/3-5127 [003] .p..... 1052.615494: #10201 context thread timer_latency 9923 ns
<idle>-0 [000] dp.h1.. 1052.615672: #10202 context irq timer_latency 3156 ns
<idle>-0 [000] dN.h2.. 1052.615676: irq_noise: local_timer:236 start 1052.615671170 duration 4943 ns
<idle>-0 [000] dp..3.. 1052.615679: thread_noise: swapper/0:0 start 1052.615671382 duration 2401 ns
timerlat/0-5124 [000] .p..... 1052.615680: #10202 context thread timer_latency 11137 ns
<idle>-0 [001] dp.h1.. 1052.615727: #10202 context irq timer_latency 2314 ns
<idle>-0 [001] dN.h2.. 1052.615731: irq_noise: local_timer:236 start 1052.615726650 duration 3703 ns
<idle>-0 [001] dp..3.. 1052.615733: thread_noise: swapper/1:0 start 1052.615726872 duration 2245 ns
timerlat/1-5125 [001] .p..... 1052.615734: #10202 context thread timer_latency 8973 ns
<idle>-0 [002] dp.h1.. 1052.615784: #10202 context irq timer_latency 2287 ns
<idle>-0 [002] dN.h2.. 1052.615787: irq_noise: local_timer:236 start 1052.615783047 duration 3898 ns
<idle>-0 [002] dp..3.. 1052.615789: thread_noise: swapper/2:0 start 1052.615783282 duration 2378 ns
timerlat/2-5126 [002] .p..... 1052.615790: #10202 context thread timer_latency 9152 ns
<idle>-0 [003] dp.h1.. 1052.616487: #10202 context irq timer_latency 2803 ns
<idle>-0 [003] dN.h2.. 1052.616491: irq_noise: local_timer:236 start 1052.616486482 duration 4117 ns
<idle>-0 [003] dp..3.. 1052.616493: thread_noise: swapper/3:0 start 1052.616486735 duration 2420 ns
timerlat/3-5127 [003] .p..... 1052.616494: #10202 context thread timer_latency 10088 ns
<idle>-0 [000] dp.h1.. 1052.616672: #10203 context irq timer_latency 3202 ns
<idle>-0 [000] dN.h2.. 1052.616676: irq_noise: local_timer:236 start 1052.616671191 duration 4736 ns
<idle>-0 [000] dp..3.. 1052.616679: thread_noise: swapper/0:0 start 1052.616671412 duration 2401 ns
timerlat/0-5124 [000] .p..... 1052.616679: #10203 context thread timer_latency 10996 ns
<idle>-0 [001] dp.h1.. 1052.616727: #10203 context irq timer_latency 2275 ns
<idle>-0 [001] dN.h2.. 1052.616731: irq_noise: local_timer:236 start 1052.616726592 duration 4001 ns
<idle>-0 [001] dp..3.. 1052.616733: thread_noise: swapper/1:0 start 1052.616726817 duration 2240 ns
timerlat/1-5125 [001] .p..... 1052.616734: #10203 context thread timer_latency 9095 ns
<idle>-0 [002] dp.h1.. 1052.616784: #10203 context irq timer_latency 2331 ns
<idle>-0 [002] dN.h2.. 1052.616787: irq_noise: local_timer:236 start 1052.616783086 duration 3878 ns
<idle>-0 [002] dp..3.. 1052.616790: thread_noise: swapper/2:0 start 1052.616783310 duration 2430 ns
timerlat/2-5126 [002] .p..... 1052.616790: #10203 context thread timer_latency 9245 ns
<idle>-0 [003] dp.h1.. 1052.617487: #10203 context irq timer_latency 2746 ns
<idle>-0 [003] dN.h2.. 1052.617491: irq_noise: local_timer:236 start 1052.617486417 duration 3960 ns
<idle>-0 [003] dp..3.. 1052.617493: thread_noise: swapper/3:0 start 1052.617486662 duration 2491 ns
timerlat/3-5127 [003] .p..... 1052.617494: #10203 context thread timer_latency 10042 ns
<idle>-0 [000] dp.h1.. 1052.617672: #10204 context irq timer_latency 3123 ns
<idle>-0 [000] dN.h2.. 1052.617676: irq_noise: local_timer:236 start 1052.617671097 duration 4689 ns
<idle>-0 [000] dp..3.. 1052.617678: thread_noise: swapper/0:0 start 1052.617671317 duration 2471 ns
timerlat/0-5124 [000] .p..... 1052.617679: #10204 context thread timer_latency 10935 ns
<idle>-0 [001] dp.h1.. 1052.617727: #10204 context irq timer_latency 2313 ns
<idle>-0 [001] dN.h2.. 1052.617731: irq_noise: local_timer:236 start 1052.617726609 duration 4024 ns
<idle>-0 [001] dp..3.. 1052.617733: thread_noise: swapper/1:0 start 1052.617726840 duration 2274 ns
timerlat/1-5125 [001] .p..... 1052.617734: #10204 context thread timer_latency 9183 ns
<idle>-0 [002] dp.h1.. 1052.617784: #10204 context irq timer_latency 2320 ns
<idle>-0 [002] dN.h2.. 1052.617787: irq_noise: local_timer:236 start 1052.617783054 duration 3856 ns
<idle>-0 [002] dp..3.. 1052.617789: thread_noise: swapper/2:0 start 1052.617783283 duration 2400 ns
timerlat/2-5126 [002] .p..... 1052.617791: #10204 context thread timer_latency 9457 ns
<idle>-0 [003] dp.h1.. 1052.618487: #10204 context irq timer_latency 2784 ns
<idle>-0 [003] dN.h2.. 1052.618491: irq_noise: local_timer:236 start 1052.618486440 duration 3959 ns
<idle>-0 [003] dp..3.. 1052.618493: thread_noise: swapper/3:0 start 1052.618486684 duration 2487 ns
timerlat/3-5127 [003] .p..... 1052.618494: #10204 context thread timer_latency 9824 ns
<idle>-0 [000] dp.h1.. 1052.618672: #10205 context irq timer_latency 3165 ns
<idle>-0 [000] dN.h2.. 1052.618676: irq_noise: local_timer:236 start 1052.618671120 duration 4875 ns
<idle>-0 [000] dp..3.. 1052.618679: thread_noise: swapper/0:0 start 1052.618671343 duration 2418 ns
timerlat/0-5124 [000] .p..... 1052.618680: #10205 context thread timer_latency 11099 ns
<idle>-0 [001] dp.h1.. 1052.618727: #10205 context irq timer_latency 2308 ns
<idle>-0 [001] dN.h2.. 1052.618731: irq_noise: local_timer:236 start 1052.618726597 duration 3742 ns
<idle>-0 [001] dp..3.. 1052.618733: thread_noise: swapper/1:0 start 1052.618726818 duration 2281 ns
timerlat/1-5125 [001] .p..... 1052.618734: #10205 context thread timer_latency 8917 ns
<idle>-0 [002] dp.h1.. 1052.618784: #10205 context irq timer_latency 2320 ns
<idle>-0 [002] dN.h2.. 1052.618787: irq_noise: local_timer:236 start 1052.618783048 duration 3774 ns
<idle>-0 [002] dp..3.. 1052.618789: thread_noise: swapper/2:0 start 1052.618783267 duration 2437 ns
timerlat/2-5126 [002] .p..... 1052.618790: #10205 context thread timer_latency 9131 ns
<idle>-0 [001] dN.h2.. 1052.619470: irq_noise: local_timer:236 start 1052.619465345 duration 4728 ns
<idle>-0 [003] dp.h1.. 1052.619486: #10205 context irq timer_latency 2337 ns
<idle>-0 [003] dN.h2.. 1052.619490: irq_noise: local_timer:236 start 1052.619485831 duration 4376 ns
<idle>-0 [003] dp..3.. 1052.619493: thread_noise: swapper/3:0 start 1052.619486221 duration 2524 ns
timerlat/3-5127 [003] .p..... 1052.619494: #10205 context thread timer_latency 9793 ns
<idle>-0 [001] dp.h2.. 1052.619601: irq_noise: local_timer:236 start 1052.619600094 duration 571 ns
<idle>-0 [000] dp.h1.. 1052.619671: #10206 context irq timer_latency 2612 ns
<idle>-0 [000] dN.h2.. 1052.619676: irq_noise: local_timer:236 start 1052.619670525 duration 5078 ns
<idle>-0 [000] dp..3.. 1052.619678: thread_noise: swapper/0:0 start 1052.619670778 duration 2419 ns
timerlat/0-5124 [000] .p..... 1052.619679: #10206 context thread timer_latency 10866 ns
kworker/1:1-4654 [001] dp.h1.. 1052.619731: #10206 context irq timer_latency 5951 ns
kworker/1:1-4654 [001] dN.h2.. 1052.619752: irq_noise: local_timer:236 start 1052.619730100 duration 21299 ns
kworker/1:1-4654 [001] dN.h2.. 1052.619755: irq_noise: irq_work:246 start 1052.619752671 duration 1751 ns
<idle>-0 [002] dp.h1.. 1052.619783: #10206 context irq timer_latency 2254 ns
<idle>-0 [002] dN.h2.. 1052.619787: irq_noise: local_timer:236 start 1052.619782951 duration 3891 ns
<idle>-0 [002] dp..3.. 1052.619789: thread_noise: swapper/2:0 start 1052.619783185 duration 2428 ns
timerlat/2-5126 [002] .p..... 1052.619790: #10206 context thread timer_latency 9211 ns
kworker/1:1-4654 [001] dp..3.. 1052.620044: thread_noise: kworker/1:1:4654 start 1052.619730445 duration 290974 ns
timerlat/1-5125 [001] .p..... 1052.620046: #10206 context thread timer_latency 320780 ns
timerlat/1-5125 [001] .p..1.. 1052.620046: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> intel_dmc_load_program
=> intel_display_power_resume
=> intel_runtime_resume
=> pci_pm_runtime_resume
=> __rpm_callback
=> rpm_callback
=> rpm_resume
=> __pm_runtime_resume
=> intel_runtime_pm_get
=> intel_display_power_get
=> intel_digital_port_connected
=> intel_dp_detect
=> drm_helper_probe_detect_ctx
=> output_poll_execute
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
=> 0x00000832
=> 0
=> 0x1100006f08
=> 0x5786130000001405
=> 0x100000a1b
=> 0x219400000000
=> 0x1e5374800000000
=> 0x01090011
[-- Attachment #3: trace2.txt.tail --]
[-- Type: text/plain, Size: 13668 bytes --]
<idle>-0 [003] dN.h2.. 1073.604489: irq_noise: local_timer:236 start 1073.604484424 duration 4206 ns
<idle>-0 [003] dp..3.. 1073.604491: thread_noise: swapper/3:0 start 1073.604484661 duration 2395 ns
timerlat/3-5133 [003] .p..... 1073.604492: #19046 context thread timer_latency 9540 ns
<idle>-0 [000] dp.h1.. 1073.605324: #19047 context irq timer_latency 2750 ns
<idle>-0 [000] dN.h2.. 1073.605328: irq_noise: local_timer:236 start 1073.605323682 duration 4567 ns
<idle>-0 [000] dp..3.. 1073.605331: thread_noise: swapper/0:0 start 1073.605323912 duration 2572 ns
timerlat/0-5130 [000] .p..... 1073.605332: #19047 context thread timer_latency 10811 ns
<idle>-0 [001] dp.h1.. 1073.605380: #19047 context irq timer_latency 2354 ns
<idle>-0 [001] dN.h2.. 1073.605383: irq_noise: local_timer:236 start 1073.605379235 duration 3851 ns
<idle>-0 [001] dp..3.. 1073.605385: thread_noise: swapper/1:0 start 1073.605379455 duration 2256 ns
timerlat/1-5131 [001] .p..... 1073.605386: #19047 context thread timer_latency 9097 ns
<idle>-0 [002] dp.h1.. 1073.605430: #19047 context irq timer_latency 3012 ns
<idle>-0 [002] dN.h2.. 1073.605434: irq_noise: local_timer:236 start 1073.605429717 duration 4049 ns
<idle>-0 [002] dp..3.. 1073.605437: thread_noise: swapper/2:0 start 1073.605429942 duration 3009 ns
timerlat/2-5132 [002] .p..... 1073.605438: #19047 context thread timer_latency 10850 ns
<idle>-0 [003] dp.h1.. 1073.605486: #19047 context irq timer_latency 3092 ns
<idle>-0 [003] dN.h2.. 1073.605489: irq_noise: local_timer:236 start 1073.605485141 duration 3975 ns
<idle>-0 [003] dp..3.. 1073.605492: thread_noise: swapper/3:0 start 1073.605485376 duration 2712 ns
timerlat/3-5133 [003] .p..... 1073.605493: #19047 context thread timer_latency 10348 ns
<idle>-0 [000] dp.h1.. 1073.606324: #19048 context irq timer_latency 2857 ns
<idle>-0 [000] dN.h2.. 1073.606329: irq_noise: local_timer:236 start 1073.606323749 duration 4932 ns
<idle>-0 [000] dp..3.. 1073.606331: thread_noise: swapper/0:0 start 1073.606324007 duration 2655 ns
timerlat/0-5130 [000] .p..... 1073.606333: #19048 context thread timer_latency 11397 ns
<idle>-0 [001] dp.h1.. 1073.606380: #19048 context irq timer_latency 2225 ns
<idle>-0 [001] dN.h2.. 1073.606383: irq_noise: local_timer:236 start 1073.606379089 duration 3937 ns
<idle>-0 [001] dp..3.. 1073.606386: thread_noise: swapper/1:0 start 1073.606379309 duration 2325 ns
timerlat/1-5131 [001] .p..... 1073.606386: #19048 context thread timer_latency 9075 ns
<idle>-0 [002] dp.h1.. 1073.606429: #19048 context irq timer_latency 2265 ns
<idle>-0 [002] dN.h2.. 1073.606433: irq_noise: local_timer:236 start 1073.606428953 duration 3894 ns
<idle>-0 [002] dp..3.. 1073.606435: thread_noise: swapper/2:0 start 1073.606429179 duration 2364 ns
timerlat/2-5132 [002] .p..... 1073.606436: #19048 context thread timer_latency 9130 ns
<idle>-0 [003] dp.h1.. 1073.606485: #19048 context irq timer_latency 2358 ns
<idle>-0 [003] dN.h2.. 1073.606488: irq_noise: local_timer:236 start 1073.606484397 duration 3829 ns
<idle>-0 [003] dp..3.. 1073.606491: thread_noise: swapper/3:0 start 1073.606484624 duration 2409 ns
timerlat/3-5133 [003] .p..... 1073.606492: #19048 context thread timer_latency 9169 ns
<idle>-0 [000] dp.h1.. 1073.607324: #19049 context irq timer_latency 2804 ns
<idle>-0 [000] dN.h2.. 1073.607329: irq_noise: local_timer:236 start 1073.607323670 duration 4729 ns
<idle>-0 [000] dp..3.. 1073.607331: thread_noise: swapper/0:0 start 1073.607323933 duration 2545 ns
timerlat/0-5130 [000] .p..... 1073.607332: #19049 context thread timer_latency 11063 ns
<idle>-0 [001] dp.h1.. 1073.607380: #19049 context irq timer_latency 3056 ns
<idle>-0 [001] dN.h2.. 1073.607384: irq_noise: local_timer:236 start 1073.607379903 duration 3908 ns
<idle>-0 [001] dp..3.. 1073.607386: thread_noise: swapper/1:0 start 1073.607380124 duration 2337 ns
timerlat/1-5131 [001] .p..... 1073.607387: #19049 context thread timer_latency 9874 ns
<idle>-0 [002] dp.h1.. 1073.607429: #19049 context irq timer_latency 2300 ns
<idle>-0 [002] dN.h2.. 1073.607433: irq_noise: local_timer:236 start 1073.607428975 duration 3820 ns
<idle>-0 [002] dp..3.. 1073.607435: thread_noise: swapper/2:0 start 1073.607429198 duration 2419 ns
timerlat/2-5132 [002] .p..... 1073.607436: #19049 context thread timer_latency 9147 ns
<idle>-0 [003] dp.h1.. 1073.607485: #19049 context irq timer_latency 2314 ns
<idle>-0 [003] dN.h2.. 1073.607489: irq_noise: local_timer:236 start 1073.607484348 duration 4225 ns
<idle>-0 [003] dp..3.. 1073.607491: thread_noise: swapper/3:0 start 1073.607484564 duration 2430 ns
timerlat/3-5133 [003] .p..... 1073.607492: #19049 context thread timer_latency 9940 ns
<idle>-0 [000] dp.h1.. 1073.608324: #19050 context irq timer_latency 2817 ns
<idle>-0 [000] dN.h2.. 1073.608329: irq_noise: local_timer:236 start 1073.608323680 duration 4772 ns
<idle>-0 [000] dp..3.. 1073.608331: thread_noise: swapper/0:0 start 1073.608323929 duration 2605 ns
timerlat/0-5130 [000] .p..... 1073.608333: #19050 context thread timer_latency 11153 ns
<idle>-0 [001] dp.h1.. 1073.608380: #19050 context irq timer_latency 3033 ns
<idle>-0 [001] dN.h2.. 1073.608384: irq_noise: local_timer:236 start 1073.608379863 duration 3944 ns
<idle>-0 [001] dp..3.. 1073.608386: thread_noise: swapper/1:0 start 1073.608380084 duration 2325 ns
timerlat/1-5131 [001] .p..... 1073.608387: #19050 context thread timer_latency 9883 ns
<idle>-0 [002] dp.h1.. 1073.608429: #19050 context irq timer_latency 2293 ns
<idle>-0 [002] dN.h2.. 1073.608433: irq_noise: local_timer:236 start 1073.608428953 duration 4164 ns
<idle>-0 [002] dp..3.. 1073.608436: thread_noise: swapper/2:0 start 1073.608429174 duration 2401 ns
timerlat/2-5132 [002] .p..... 1073.608437: #19050 context thread timer_latency 9950 ns
<idle>-0 [003] dp.h1.. 1073.608485: #19050 context irq timer_latency 2331 ns
<idle>-0 [003] dN.h2.. 1073.608488: irq_noise: local_timer:236 start 1073.608484328 duration 3888 ns
<idle>-0 [003] dp..3.. 1073.608491: thread_noise: swapper/3:0 start 1073.608484565 duration 2432 ns
timerlat/3-5133 [003] .p..... 1073.608492: #19050 context thread timer_latency 9230 ns
<idle>-0 [000] dp.h1.. 1073.609324: #19051 context irq timer_latency 2792 ns
<idle>-0 [000] dN.h2.. 1073.609328: irq_noise: local_timer:236 start 1073.609323620 duration 4632 ns
<idle>-0 [000] dp..3.. 1073.609331: thread_noise: swapper/0:0 start 1073.609323888 duration 2922 ns
timerlat/0-5130 [000] .p..... 1073.609332: #19051 context thread timer_latency 11027 ns
<idle>-0 [001] dp.h1.. 1073.609380: #19051 context irq timer_latency 3009 ns
<idle>-0 [001] dN.h2.. 1073.609384: irq_noise: local_timer:236 start 1073.609379823 duration 4016 ns
<idle>-0 [001] dp..3.. 1073.609386: thread_noise: swapper/1:0 start 1073.609380044 duration 2286 ns
timerlat/1-5131 [001] .p..... 1073.609387: #19051 context thread timer_latency 10160 ns
<idle>-0 [002] dp.h1.. 1073.609429: #19051 context irq timer_latency 2349 ns
<idle>-0 [002] dN.h2.. 1073.609433: irq_noise: local_timer:236 start 1073.609428988 duration 3865 ns
<idle>-0 [002] dp..3.. 1073.609435: thread_noise: swapper/2:0 start 1073.609429214 duration 2406 ns
timerlat/2-5132 [002] .p..... 1073.609436: #19051 context thread timer_latency 9220 ns
<idle>-0 [003] dp.h1.. 1073.609485: #19051 context irq timer_latency 2379 ns
<idle>-0 [003] dN.h2.. 1073.609488: irq_noise: local_timer:236 start 1073.609484351 duration 3904 ns
<idle>-0 [003] dp..3.. 1073.609491: thread_noise: swapper/3:0 start 1073.609484596 duration 2432 ns
timerlat/3-5133 [003] .p..... 1073.609492: #19051 context thread timer_latency 9297 ns
<idle>-0 [000] dp.h1.. 1073.610324: #19052 context irq timer_latency 2736 ns
<idle>-0 [000] dN.h2.. 1073.610329: irq_noise: local_timer:236 start 1073.610323569 duration 4980 ns
<idle>-0 [000] dp..3.. 1073.610331: thread_noise: swapper/0:0 start 1073.610323816 duration 2622 ns
timerlat/0-5130 [000] .p..... 1073.610333: #19052 context thread timer_latency 11278 ns
<idle>-0 [001] dp.h1.. 1073.610380: #19052 context irq timer_latency 3043 ns
<idle>-0 [001] dN.h2.. 1073.610384: irq_noise: local_timer:236 start 1073.610379843 duration 3919 ns
<idle>-0 [001] dp..3.. 1073.610386: thread_noise: swapper/1:0 start 1073.610380062 duration 2314 ns
timerlat/1-5131 [001] .p..... 1073.610387: #19052 context thread timer_latency 9858 ns
<idle>-0 [002] dp.h1.. 1073.610429: #19052 context irq timer_latency 2302 ns
<idle>-0 [002] dN.h2.. 1073.610433: irq_noise: local_timer:236 start 1073.610428925 duration 3858 ns
<idle>-0 [002] dp..3.. 1073.610435: thread_noise: swapper/2:0 start 1073.610429150 duration 2425 ns
timerlat/2-5132 [002] .p..... 1073.610436: #19052 context thread timer_latency 9200 ns
<idle>-0 [003] dp.h1.. 1073.610485: #19052 context irq timer_latency 2311 ns
<idle>-0 [003] dN.h2.. 1073.610488: irq_noise: local_timer:236 start 1073.610484286 duration 3847 ns
<idle>-0 [003] dp..3.. 1073.610491: thread_noise: swapper/3:0 start 1073.610484512 duration 2398 ns
timerlat/3-5133 [003] .p..... 1073.610492: #19052 context thread timer_latency 9155 ns
<idle>-0 [001] dN.h2.. 1073.611129: irq_noise: local_timer:236 start 1073.611124279 duration 4745 ns
<idle>-0 [001] dp.h2.. 1073.611258: irq_noise: local_timer:236 start 1073.611257275 duration 577 ns
<idle>-0 [000] dp.h1.. 1073.611324: #19053 context irq timer_latency 2658 ns
<idle>-0 [000] dN.h2.. 1073.611329: irq_noise: local_timer:236 start 1073.611323457 duration 4990 ns
<idle>-0 [000] dp..3.. 1073.611331: thread_noise: swapper/0:0 start 1073.611323726 duration 2560 ns
timerlat/0-5130 [000] .p..... 1073.611332: #19053 context thread timer_latency 10926 ns
kworker/1:2-461 [001] dp.h1.. 1073.611383: #19053 context irq timer_latency 5589 ns
kworker/1:2-461 [001] dN.h2.. 1073.611404: irq_noise: local_timer:236 start 1073.611382286 duration 21070 ns
<idle>-0 [002] dp.h1.. 1073.611429: #19053 context irq timer_latency 2320 ns
<idle>-0 [002] dN.h2.. 1073.611433: irq_noise: local_timer:236 start 1073.611428926 duration 3955 ns
<idle>-0 [002] dp..3.. 1073.611435: thread_noise: swapper/2:0 start 1073.611429152 duration 2432 ns
timerlat/2-5132 [002] .p..... 1073.611437: #19053 context thread timer_latency 9380 ns
<idle>-0 [003] dp.h1.. 1073.611485: #19053 context irq timer_latency 2483 ns
<idle>-0 [003] dN.h2.. 1073.611489: irq_noise: local_timer:236 start 1073.611484439 duration 4040 ns
<idle>-0 [003] dp..3.. 1073.611491: thread_noise: swapper/3:0 start 1073.611484667 duration 2464 ns
timerlat/3-5133 [003] .p..... 1073.611492: #19053 context thread timer_latency 9800 ns
kworker/1:2-461 [001] dp..3.. 1073.611698: thread_noise: kworker/1:2:461 start 1073.611382591 duration 294270 ns
timerlat/1-5131 [001] .p..... 1073.611699: #19053 context thread timer_latency 321993 ns
timerlat/1-5131 [001] .p..1.. 1073.611700: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> intel_dmc_load_program
=> intel_display_power_resume
=> intel_runtime_resume
=> pci_pm_runtime_resume
=> __rpm_callback
=> rpm_callback
=> rpm_resume
=> __pm_runtime_resume
=> intel_runtime_pm_get
=> intel_display_power_get
=> intel_digital_port_connected
=> intel_dp_detect
=> drm_helper_probe_detect_ctx
=> output_poll_execute
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
=> 0x69745f6c61636f6c
=> 0x1084e0072656d
=> 0x030101cd
=> 0x7061777300001400
=> 0x312f726570
=> 0x270000000000
=> 0xf831ce7af2
=> 0x0000085e
[-- Attachment #4: trace3.txt.tail --]
[-- Type: text/plain, Size: 14143 bytes --]
<idle>-0 [002] dp.h1.. 1085.044263: #9350 context irq timer_latency 2308 ns
<idle>-0 [002] dN.h2.. 1085.044267: irq_noise: local_timer:236 start 1085.044262449 duration 3896 ns
<idle>-0 [002] dp..3.. 1085.044269: thread_noise: swapper/2:0 start 1085.044262682 duration 2399 ns
timerlat/2-5138 [002] .p..... 1085.044270: #9350 context thread timer_latency 9472 ns
<idle>-0 [003] dp.h1.. 1085.044313: #9350 context irq timer_latency 2279 ns
<idle>-0 [003] dN.h2.. 1085.044316: irq_noise: local_timer:236 start 1085.044312462 duration 3692 ns
<idle>-0 [003] dp..3.. 1085.044319: thread_noise: swapper/3:0 start 1085.044312685 duration 2233 ns
timerlat/3-5139 [003] .p..... 1085.044319: #9350 context thread timer_latency 8773 ns
<idle>-0 [000] dp.h1.. 1085.045158: #9351 context irq timer_latency 2836 ns
<idle>-0 [000] dN.h2.. 1085.045162: irq_noise: local_timer:236 start 1085.045157549 duration 4689 ns
<idle>-0 [000] dp..3.. 1085.045165: thread_noise: swapper/0:0 start 1085.045157864 duration 2411 ns
timerlat/0-5136 [000] .p..... 1085.045166: #9351 context thread timer_latency 10508 ns
<idle>-0 [001] dp.h1.. 1085.045209: #9351 context irq timer_latency 3017 ns
<idle>-0 [001] dN.h2.. 1085.045213: irq_noise: local_timer:236 start 1085.045208834 duration 4344 ns
<idle>-0 [001] dp..3.. 1085.045215: thread_noise: swapper/1:0 start 1085.045209060 duration 2177 ns
timerlat/1-5137 [001] .p..... 1085.045216: #9351 context thread timer_latency 10135 ns
<idle>-0 [002] dp.h1.. 1085.045263: #9351 context irq timer_latency 2343 ns
<idle>-0 [002] dN.h2.. 1085.045267: irq_noise: local_timer:236 start 1085.045262452 duration 3862 ns
<idle>-0 [002] dp..3.. 1085.045269: thread_noise: swapper/2:0 start 1085.045262701 duration 2428 ns
timerlat/2-5138 [002] .p..... 1085.045270: #9351 context thread timer_latency 9525 ns
<idle>-0 [003] dp.h1.. 1085.045313: #9351 context irq timer_latency 2304 ns
<idle>-0 [003] dN.h2.. 1085.045316: irq_noise: local_timer:236 start 1085.045312470 duration 3671 ns
<idle>-0 [003] dp..3.. 1085.045319: thread_noise: swapper/3:0 start 1085.045312694 duration 2224 ns
timerlat/3-5139 [003] .p..... 1085.045319: #9351 context thread timer_latency 8775 ns
<idle>-0 [000] dp.h1.. 1085.046158: #9352 context irq timer_latency 2858 ns
<idle>-0 [000] dN.h2.. 1085.046162: irq_noise: local_timer:236 start 1085.046157560 duration 4645 ns
<idle>-0 [000] dp..3.. 1085.046165: thread_noise: swapper/0:0 start 1085.046157869 duration 2355 ns
timerlat/0-5136 [000] .p..... 1085.046166: #9352 context thread timer_latency 10412 ns
<idle>-0 [001] dp.h1.. 1085.046209: #9352 context irq timer_latency 3048 ns
<idle>-0 [001] dN.h2.. 1085.046213: irq_noise: local_timer:236 start 1085.046208854 duration 4181 ns
<idle>-0 [001] dp..3.. 1085.046215: thread_noise: swapper/1:0 start 1085.046209075 duration 2223 ns
timerlat/1-5137 [001] .p..... 1085.046216: #9352 context thread timer_latency 10026 ns
<idle>-0 [002] dp.h1.. 1085.046263: #9352 context irq timer_latency 2338 ns
<idle>-0 [002] dN.h2.. 1085.046267: irq_noise: local_timer:236 start 1085.046262452 duration 3914 ns
<idle>-0 [002] dp..3.. 1085.046269: thread_noise: swapper/2:0 start 1085.046262679 duration 2392 ns
timerlat/2-5138 [002] .p..... 1085.046270: #9352 context thread timer_latency 9551 ns
<idle>-0 [003] dp.h1.. 1085.046313: #9352 context irq timer_latency 2250 ns
<idle>-0 [003] dN.h2.. 1085.046316: irq_noise: local_timer:236 start 1085.046312408 duration 3669 ns
<idle>-0 [003] dp..3.. 1085.046319: thread_noise: swapper/3:0 start 1085.046312622 duration 2200 ns
timerlat/3-5139 [003] .p..... 1085.046320: #9352 context thread timer_latency 9155 ns
<idle>-0 [000] dp.h1.. 1085.047158: #9353 context irq timer_latency 3186 ns
<idle>-0 [000] dN.h2.. 1085.047163: irq_noise: local_timer:236 start 1085.047157573 duration 5122 ns
<idle>-0 [000] dp..3.. 1085.047165: thread_noise: swapper/0:0 start 1085.047158180 duration 2482 ns
timerlat/0-5136 [000] .p..... 1085.047167: #9353 context thread timer_latency 11328 ns
<idle>-0 [001] dp.h1.. 1085.047209: #9353 context irq timer_latency 3085 ns
<idle>-0 [001] dN.h2.. 1085.047213: irq_noise: local_timer:236 start 1085.047208872 duration 4089 ns
<idle>-0 [001] dp..3.. 1085.047215: thread_noise: swapper/1:0 start 1085.047209095 duration 2186 ns
timerlat/1-5137 [001] .p..... 1085.047216: #9353 context thread timer_latency 9949 ns
<idle>-0 [002] dp.h1.. 1085.047263: #9353 context irq timer_latency 2249 ns
<idle>-0 [002] dN.h2.. 1085.047267: irq_noise: local_timer:236 start 1085.047262347 duration 4179 ns
<idle>-0 [002] dp..3.. 1085.047269: thread_noise: swapper/2:0 start 1085.047262574 duration 2407 ns
timerlat/2-5138 [002] .p..... 1085.047270: #9353 context thread timer_latency 9941 ns
<idle>-0 [003] dp.h1.. 1085.047313: #9353 context irq timer_latency 2314 ns
<idle>-0 [003] dN.h2.. 1085.047316: irq_noise: local_timer:236 start 1085.047312425 duration 3673 ns
<idle>-0 [003] dp..3.. 1085.047319: thread_noise: swapper/3:0 start 1085.047312672 duration 2251 ns
timerlat/3-5139 [003] .p..... 1085.047319: #9353 context thread timer_latency 8811 ns
<idle>-0 [002] dp.h2.. 1085.047350: irq_noise: iwlwifi:130 start 1085.047349685 duration 63 ns
<idle>-0 [000] dp.h1.. 1085.048158: #9354 context irq timer_latency 2967 ns
<idle>-0 [000] dN.h2.. 1085.048163: irq_noise: local_timer:236 start 1085.048157653 duration 5023 ns
<idle>-0 [000] dp..3.. 1085.048165: thread_noise: swapper/0:0 start 1085.048157945 duration 2388 ns
timerlat/0-5136 [000] .p..... 1085.048166: #9354 context thread timer_latency 11245 ns
<idle>-0 [001] dp.h1.. 1085.048210: #9354 context irq timer_latency 3179 ns
<idle>-0 [001] dN.h2.. 1085.048214: irq_noise: local_timer:236 start 1085.048208820 duration 5044 ns
<idle>-0 [001] dp..3.. 1085.048217: thread_noise: swapper/1:0 start 1085.048209177 duration 2954 ns
timerlat/1-5137 [001] .p..... 1085.048218: #9354 context thread timer_latency 11761 ns
<idle>-0 [002] dp.h1.. 1085.048263: #9354 context irq timer_latency 2460 ns
<idle>-0 [002] dN.h2.. 1085.048267: irq_noise: local_timer:236 start 1085.048262471 duration 4468 ns
<idle>-0 [002] dp..3.. 1085.048270: thread_noise: swapper/2:0 start 1085.048262774 duration 2780 ns
timerlat/2-5138 [002] .p..... 1085.048271: #9354 context thread timer_latency 10316 ns
<idle>-0 [003] dp.h1.. 1085.048313: #9354 context irq timer_latency 2285 ns
<idle>-0 [003] dN.h2.. 1085.048317: irq_noise: local_timer:236 start 1085.048312411 duration 4016 ns
<idle>-0 [003] dp..3.. 1085.048319: thread_noise: swapper/3:0 start 1085.048312625 duration 2240 ns
timerlat/3-5139 [003] .p..... 1085.048320: #9354 context thread timer_latency 9375 ns
<idle>-0 [000] dp.h1.. 1085.049158: #9355 context irq timer_latency 3196 ns
<idle>-0 [000] dN.h2.. 1085.049163: irq_noise: local_timer:236 start 1085.049157552 duration 5009 ns
<idle>-0 [000] dp..3.. 1085.049165: thread_noise: swapper/0:0 start 1085.049158157 duration 2425 ns
timerlat/0-5136 [000] .p..... 1085.049166: #9355 context thread timer_latency 10898 ns
<idle>-0 [001] dp.h1.. 1085.049209: #9355 context irq timer_latency 3050 ns
<idle>-0 [001] dN.h2.. 1085.049213: irq_noise: local_timer:236 start 1085.049208793 duration 4200 ns
<idle>-0 [001] dp..3.. 1085.049215: thread_noise: swapper/1:0 start 1085.049209027 duration 2259 ns
timerlat/1-5137 [001] .p..... 1085.049216: #9355 context thread timer_latency 10118 ns
<idle>-0 [002] dp.h1.. 1085.049263: #9355 context irq timer_latency 2402 ns
<idle>-0 [002] dN.h2.. 1085.049267: irq_noise: local_timer:236 start 1085.049262426 duration 4079 ns
<idle>-0 [002] dp..3.. 1085.049269: thread_noise: swapper/2:0 start 1085.049262693 duration 2405 ns
timerlat/2-5138 [002] .p..... 1085.049270: #9355 context thread timer_latency 9652 ns
<idle>-0 [003] dp.h1.. 1085.049313: #9355 context irq timer_latency 2283 ns
<idle>-0 [003] dN.h2.. 1085.049316: irq_noise: local_timer:236 start 1085.049312382 duration 3820 ns
<idle>-0 [003] dp..3.. 1085.049319: thread_noise: swapper/3:0 start 1085.049312606 duration 2261 ns
timerlat/3-5139 [003] .p..... 1085.049319: #9355 context thread timer_latency 8906 ns
<idle>-0 [000] dp.h1.. 1085.050158: #9356 context irq timer_latency 2857 ns
<idle>-0 [000] dN.h2.. 1085.050162: irq_noise: local_timer:236 start 1085.050157513 duration 4769 ns
<idle>-0 [000] dp..3.. 1085.050165: thread_noise: swapper/0:0 start 1085.050157801 duration 2388 ns
timerlat/0-5136 [000] .p..... 1085.050166: #9356 context thread timer_latency 10614 ns
<idle>-0 [001] dp.h1.. 1085.050209: #9356 context irq timer_latency 3085 ns
<idle>-0 [001] dN.h2.. 1085.050213: irq_noise: local_timer:236 start 1085.050208811 duration 3992 ns
<idle>-0 [001] dp..3.. 1085.050215: thread_noise: swapper/1:0 start 1085.050209045 duration 2107 ns
timerlat/1-5137 [001] .p..... 1085.050216: #9356 context thread timer_latency 9758 ns
<idle>-0 [002] dp.h1.. 1085.050263: #9356 context irq timer_latency 2237 ns
<idle>-0 [002] dN.h2.. 1085.050266: irq_noise: local_timer:236 start 1085.050262287 duration 3964 ns
<idle>-0 [002] dp..3.. 1085.050269: thread_noise: swapper/2:0 start 1085.050262512 duration 2402 ns
timerlat/2-5138 [002] .p..... 1085.050270: #9356 context thread timer_latency 9519 ns
<idle>-0 [003] dp.h1.. 1085.050313: #9356 context irq timer_latency 2266 ns
<idle>-0 [003] dN.h2.. 1085.050316: irq_noise: local_timer:236 start 1085.050312354 duration 3976 ns
<idle>-0 [003] dp..3.. 1085.050319: thread_noise: swapper/3:0 start 1085.050312573 duration 2239 ns
timerlat/3-5139 [003] .p..... 1085.050320: #9356 context thread timer_latency 9060 ns
<idle>-0 [001] dp.h2.. 1085.050937: irq_noise: local_timer:236 start 1085.050935953 duration 486 ns
<idle>-0 [000] dp.h1.. 1085.051157: #9357 context irq timer_latency 2241 ns
<idle>-0 [000] dN.h2.. 1085.051164: irq_noise: local_timer:236 start 1085.051156896 duration 6561 ns
<idle>-0 [000] dp..3.. 1085.051166: thread_noise: swapper/0:0 start 1085.051157168 duration 2346 ns
timerlat/0-5136 [000] .p..... 1085.051167: #9357 context thread timer_latency 11682 ns
<idle>-0 [002] dp.h1.. 1085.051263: #9357 context irq timer_latency 2131 ns
<idle>-0 [002] dN.h2.. 1085.051269: irq_noise: local_timer:236 start 1085.051262173 duration 6284 ns
<idle>-0 [002] dp..3.. 1085.051271: thread_noise: swapper/2:0 start 1085.051262389 duration 2370 ns
timerlat/2-5138 [002] .p..... 1085.051272: #9357 context thread timer_latency 11659 ns
<idle>-0 [003] dp.h1.. 1085.051313: #9357 context irq timer_latency 2241 ns
<idle>-0 [003] dN.h2.. 1085.051317: irq_noise: local_timer:236 start 1085.051312269 duration 4326 ns
<idle>-0 [003] dp..3.. 1085.051319: thread_noise: swapper/3:0 start 1085.051312535 duration 2482 ns
timerlat/3-5139 [003] .p..... 1085.051320: #9357 context thread timer_latency 9638 ns
kworker/1:1-4654 [001] dp.h... 1085.051458: #9357 context irq timer_latency 251709 ns
kworker/1:1-4654 [001] dN.h1.. 1085.051474: irq_noise: local_timer:236 start 1085.051457240 duration 16784 ns
kworker/1:1-4654 [001] dN.h2.. 1085.051478: irq_noise: irq_work:246 start 1085.051475602 duration 1651 ns
kworker/1:1-4654 [001] dp..3.. 1085.051479: thread_noise: kworker/1:1:4654 start 1085.051457657 duration 3600 ns
timerlat/1-5137 [001] .p..... 1085.051481: #9357 context thread timer_latency 274334 ns
timerlat/1-5137 [001] .p..1.. 1085.051481: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> intel_irq_reset
=> intel_runtime_pm_disable_interrupts
=> intel_runtime_suspend
=> pci_pm_runtime_suspend
=> __rpm_callback
=> rpm_callback
=> rpm_suspend
=> pm_runtime_work
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
=> 0x9b4000000fa
=> 0
=> 0x6f480001e12d
=> 0x141100000011
=> 0x6c7569cca00
=> 0x103900000001
=> 0x000027d4
=> 0x109001101e47d08
[-- Attachment #5: trace4.txt.tail --]
[-- Type: text/plain, Size: 13608 bytes --]
<idle>-0 [003] dp..3.. 1095.108138: thread_noise: swapper/3:0 start 1095.108132232 duration 2182 ns
timerlat/3-5145 [003] .p..... 1095.108139: #8280 context thread timer_latency 8931 ns
<idle>-0 [000] dp.h1.. 1095.108970: #8281 context irq timer_latency 2935 ns
<idle>-0 [000] dN.h2.. 1095.108974: irq_noise: local_timer:236 start 1095.108969009 duration 4635 ns
<idle>-0 [000] dp..3.. 1095.108976: thread_noise: swapper/0:0 start 1095.108969364 duration 2413 ns
timerlat/0-5142 [000] .p..... 1095.108977: #8281 context thread timer_latency 10527 ns
<idle>-0 [001] dp.h1.. 1095.109017: #8281 context irq timer_latency 2995 ns
<idle>-0 [001] dN.h2.. 1095.109021: irq_noise: local_timer:236 start 1095.109016579 duration 3910 ns
<idle>-0 [001] dp..3.. 1095.109023: thread_noise: swapper/1:0 start 1095.109016809 duration 2365 ns
timerlat/1-5143 [001] .p..... 1095.109024: #8281 context thread timer_latency 10159 ns
<idle>-0 [002] dp.h1.. 1095.109070: #8281 context irq timer_latency 2271 ns
<idle>-0 [002] dN.h2.. 1095.109074: irq_noise: local_timer:236 start 1095.109069923 duration 3758 ns
<idle>-0 [002] dp..3.. 1095.109076: thread_noise: swapper/2:0 start 1095.109070155 duration 2241 ns
timerlat/2-5144 [002] .p..... 1095.109077: #8281 context thread timer_latency 8835 ns
<idle>-0 [003] dp.h1.. 1095.109132: #8281 context irq timer_latency 2314 ns
<idle>-0 [003] dN.h2.. 1095.109136: irq_noise: local_timer:236 start 1095.109131998 duration 3853 ns
<idle>-0 [003] dp..3.. 1095.109138: thread_noise: swapper/3:0 start 1095.109132223 duration 2212 ns
timerlat/3-5145 [003] .p..... 1095.109139: #8281 context thread timer_latency 8977 ns
<idle>-0 [000] dp.h1.. 1095.109970: #8282 context irq timer_latency 2902 ns
<idle>-0 [000] dN.h2.. 1095.109974: irq_noise: local_timer:236 start 1095.109968978 duration 4608 ns
<idle>-0 [000] dp..3.. 1095.109976: thread_noise: swapper/0:0 start 1095.109969315 duration 2367 ns
timerlat/0-5142 [000] .p..... 1095.109977: #8282 context thread timer_latency 10444 ns
<idle>-0 [001] dp.h1.. 1095.110017: #8282 context irq timer_latency 3032 ns
<idle>-0 [001] dN.h2.. 1095.110021: irq_noise: local_timer:236 start 1095.110016599 duration 4253 ns
<idle>-0 [001] dp..3.. 1095.110023: thread_noise: swapper/1:0 start 1095.110016829 duration 2268 ns
timerlat/1-5143 [001] .p..... 1095.110024: #8282 context thread timer_latency 10432 ns
<idle>-0 [002] dp.h1.. 1095.110070: #8282 context irq timer_latency 2232 ns
<idle>-0 [002] dN.h2.. 1095.110074: irq_noise: local_timer:236 start 1095.110069884 duration 3754 ns
<idle>-0 [002] dp..3.. 1095.110076: thread_noise: swapper/2:0 start 1095.110070100 duration 2201 ns
timerlat/2-5144 [002] .p..... 1095.110077: #8282 context thread timer_latency 8771 ns
<idle>-0 [003] dp.h1.. 1095.110132: #8282 context irq timer_latency 2260 ns
<idle>-0 [003] dN.h2.. 1095.110136: irq_noise: local_timer:236 start 1095.110131935 duration 3820 ns
<idle>-0 [003] dp..3.. 1095.110138: thread_noise: swapper/3:0 start 1095.110132151 duration 2222 ns
timerlat/3-5145 [003] .p..... 1095.110139: #8282 context thread timer_latency 8899 ns
<idle>-0 [000] dp.h1.. 1095.110970: #8283 context irq timer_latency 2855 ns
<idle>-0 [000] dN.h2.. 1095.110974: irq_noise: local_timer:236 start 1095.110968916 duration 4609 ns
<idle>-0 [000] dp..3.. 1095.110976: thread_noise: swapper/0:0 start 1095.110969251 duration 2430 ns
timerlat/0-5142 [000] .p..... 1095.110977: #8283 context thread timer_latency 10433 ns
<idle>-0 [001] dp.h1.. 1095.111016: #8283 context irq timer_latency 2364 ns
<idle>-0 [001] dN.h2.. 1095.111020: irq_noise: local_timer:236 start 1095.111015914 duration 3675 ns
<idle>-0 [001] dp..3.. 1095.111022: thread_noise: swapper/1:0 start 1095.111016144 duration 2246 ns
timerlat/1-5143 [001] .p..... 1095.111023: #8283 context thread timer_latency 8850 ns
<idle>-0 [002] dp.h1.. 1095.111070: #8283 context irq timer_latency 2277 ns
<idle>-0 [002] dN.h2.. 1095.111074: irq_noise: local_timer:236 start 1095.111069911 duration 3679 ns
<idle>-0 [002] dp..3.. 1095.111076: thread_noise: swapper/2:0 start 1095.111070128 duration 2265 ns
timerlat/2-5144 [002] .p..... 1095.111077: #8283 context thread timer_latency 8789 ns
<idle>-0 [003] dp.h1.. 1095.111132: #8283 context irq timer_latency 2317 ns
<idle>-0 [003] dN.h2.. 1095.111136: irq_noise: local_timer:236 start 1095.111131976 duration 4123 ns
<idle>-0 [003] dp..3.. 1095.111138: thread_noise: swapper/3:0 start 1095.111132192 duration 2255 ns
timerlat/3-5145 [003] .p..... 1095.111140: #8283 context thread timer_latency 9401 ns
<idle>-0 [000] dp.h1.. 1095.111970: #8284 context irq timer_latency 2906 ns
<idle>-0 [000] dN.h2.. 1095.111974: irq_noise: local_timer:236 start 1095.111968949 duration 4614 ns
<idle>-0 [000] dp..3.. 1095.111977: thread_noise: swapper/0:0 start 1095.111969285 duration 2349 ns
timerlat/0-5142 [000] .p..... 1095.111978: #8284 context thread timer_latency 10940 ns
<idle>-0 [001] dp.h1.. 1095.112017: #8284 context irq timer_latency 3056 ns
<idle>-0 [001] dN.h2.. 1095.112021: irq_noise: local_timer:236 start 1095.112016590 duration 4181 ns
<idle>-0 [001] dp..3.. 1095.112023: thread_noise: swapper/1:0 start 1095.112016819 duration 2332 ns
timerlat/1-5143 [001] .p..... 1095.112024: #8284 context thread timer_latency 10439 ns
<idle>-0 [002] dp.h1.. 1095.112070: #8284 context irq timer_latency 2349 ns
<idle>-0 [002] dN.h2.. 1095.112074: irq_noise: local_timer:236 start 1095.112069967 duration 3756 ns
<idle>-0 [002] dp..3.. 1095.112076: thread_noise: swapper/2:0 start 1095.112070183 duration 2243 ns
timerlat/2-5144 [002] .p..... 1095.112077: #8284 context thread timer_latency 8930 ns
<idle>-0 [003] dp.h1.. 1095.112132: #8284 context irq timer_latency 2320 ns
<idle>-0 [003] dN.h2.. 1095.112136: irq_noise: local_timer:236 start 1095.112131962 duration 3821 ns
<idle>-0 [003] dp..3.. 1095.112138: thread_noise: swapper/3:0 start 1095.112132178 duration 2184 ns
timerlat/3-5145 [003] .p..... 1095.112139: #8284 context thread timer_latency 8921 ns
<idle>-0 [000] dp.h1.. 1095.112970: #8285 context irq timer_latency 3150 ns
<idle>-0 [000] dN.h2.. 1095.112974: irq_noise: local_timer:236 start 1095.112968888 duration 5086 ns
<idle>-0 [000] dp..3.. 1095.112977: thread_noise: swapper/0:0 start 1095.112969512 duration 2433 ns
timerlat/0-5142 [000] .p..... 1095.112978: #8285 context thread timer_latency 11265 ns
<idle>-0 [001] dp.h1.. 1095.113017: #8285 context irq timer_latency 3032 ns
<idle>-0 [001] dN.h2.. 1095.113021: irq_noise: local_timer:236 start 1095.113016549 duration 3908 ns
<idle>-0 [001] dp..3.. 1095.113023: thread_noise: swapper/1:0 start 1095.113016778 duration 2274 ns
timerlat/1-5143 [001] .p..... 1095.113024: #8285 context thread timer_latency 9767 ns
<idle>-0 [002] dp.h1.. 1095.113070: #8285 context irq timer_latency 2233 ns
<idle>-0 [002] dN.h2.. 1095.113074: irq_noise: local_timer:236 start 1095.113069826 duration 3745 ns
<idle>-0 [002] dp..3.. 1095.113076: thread_noise: swapper/2:0 start 1095.113070050 duration 2283 ns
timerlat/2-5144 [002] .p..... 1095.113077: #8285 context thread timer_latency 8829 ns
<idle>-0 [003] dp.h1.. 1095.113132: #8285 context irq timer_latency 2261 ns
<idle>-0 [003] dN.h2.. 1095.113136: irq_noise: local_timer:236 start 1095.113131877 duration 3839 ns
<idle>-0 [003] dp..3.. 1095.113138: thread_noise: swapper/3:0 start 1095.113132102 duration 2198 ns
timerlat/3-5145 [003] .p..... 1095.113139: #8285 context thread timer_latency 8872 ns
<idle>-0 [000] dp.h1.. 1095.113969: #8286 context irq timer_latency 2857 ns
<idle>-0 [000] dN.h2.. 1095.113974: irq_noise: local_timer:236 start 1095.113968866 duration 4543 ns
<idle>-0 [000] dp..3.. 1095.113976: thread_noise: swapper/0:0 start 1095.113969203 duration 2438 ns
timerlat/0-5142 [000] .p..... 1095.113977: #8286 context thread timer_latency 10404 ns
<idle>-0 [001] dp.h1.. 1095.114016: #8286 context irq timer_latency 2317 ns
<idle>-0 [001] dN.h2.. 1095.114020: irq_noise: local_timer:236 start 1095.114015818 duration 4111 ns
<idle>-0 [001] dp..3.. 1095.114022: thread_noise: swapper/1:0 start 1095.114016048 duration 2316 ns
timerlat/1-5143 [001] .p..... 1095.114024: #8286 context thread timer_latency 9613 ns
<idle>-0 [002] dp.h1.. 1095.114070: #8286 context irq timer_latency 2262 ns
<idle>-0 [002] dN.h2.. 1095.114074: irq_noise: local_timer:236 start 1095.114069838 duration 3675 ns
<idle>-0 [002] dp..3.. 1095.114076: thread_noise: swapper/2:0 start 1095.114070063 duration 2277 ns
timerlat/2-5144 [002] .p..... 1095.114077: #8286 context thread timer_latency 8776 ns
<idle>-0 [003] dp.h1.. 1095.114132: #8286 context irq timer_latency 2267 ns
<idle>-0 [003] dN.h2.. 1095.114136: irq_noise: local_timer:236 start 1095.114131876 duration 3724 ns
<idle>-0 [003] dp..3.. 1095.114138: thread_noise: swapper/3:0 start 1095.114132091 duration 2155 ns
timerlat/3-5145 [003] .p..... 1095.114139: #8286 context thread timer_latency 8741 ns
<idle>-0 [001] dN.h2.. 1095.114772: irq_noise: local_timer:236 start 1095.114767061 duration 5154 ns
<idle>-0 [001] dp.h2.. 1095.114901: irq_noise: local_timer:236 start 1095.114900485 duration 586 ns
<idle>-0 [000] dp.h1.. 1095.114969: #8287 context irq timer_latency 2733 ns
<idle>-0 [000] dN.h2.. 1095.114974: irq_noise: local_timer:236 start 1095.114968653 duration 5169 ns
<idle>-0 [000] dp..3.. 1095.114976: thread_noise: swapper/0:0 start 1095.114969063 duration 2360 ns
timerlat/0-5142 [000] .p..... 1095.114977: #8287 context thread timer_latency 10901 ns
kworker/1:2-461 [001] dp.h1.. 1095.115020: #8287 context irq timer_latency 5596 ns
kworker/1:2-461 [001] dN.h2.. 1095.115041: irq_noise: local_timer:236 start 1095.115018976 duration 21971 ns
kworker/1:2-461 [001] dN.h2.. 1095.115045: irq_noise: irq_work:246 start 1095.115042668 duration 1688 ns
<idle>-0 [002] dp.h1.. 1095.115070: #8287 context irq timer_latency 2291 ns
<idle>-0 [002] dN.h2.. 1095.115074: irq_noise: local_timer:236 start 1095.115069859 duration 4047 ns
<idle>-0 [002] dp..3.. 1095.115076: thread_noise: swapper/2:0 start 1095.115070075 duration 2263 ns
timerlat/2-5144 [002] .p..... 1095.115077: #8287 context thread timer_latency 9254 ns
<idle>-0 [003] dp.h1.. 1095.115132: #8287 context irq timer_latency 2435 ns
<idle>-0 [003] dN.h2.. 1095.115136: irq_noise: local_timer:236 start 1095.115132028 duration 3907 ns
<idle>-0 [003] dp..3.. 1095.115138: thread_noise: swapper/3:0 start 1095.115132243 duration 2221 ns
timerlat/3-5145 [003] .p..... 1095.115139: #8287 context thread timer_latency 9268 ns
kworker/1:2-461 [001] dp..3.. 1095.115347: thread_noise: kworker/1:2:461 start 1095.115019309 duration 304638 ns
timerlat/1-5143 [001] .p..... 1095.115349: #8287 context thread timer_latency 334878 ns
timerlat/1-5143 [001] .p..1.. 1095.115349: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> intel_dmc_load_program
=> intel_display_power_resume
=> intel_runtime_resume
=> pci_pm_runtime_resume
=> __rpm_callback
=> rpm_callback
=> rpm_resume
=> __pm_runtime_resume
=> intel_runtime_pm_get
=> intel_display_power_get
=> intel_digital_port_connected
=> intel_dp_detect
=> drm_helper_probe_detect_ctx
=> output_poll_execute
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
=> 0x76a9248cffff91d0
=> 0x781f3f5b5
=> 0
=> 0
=> 0
=> 0
=> 0
=> 0x6c61c9e000000000
[-- Attachment #6: trace5.txt.tail --]
[-- Type: text/plain, Size: 13669 bytes --]
<idle>-0 [002] dN.h2.. 1117.635734: irq_noise: local_timer:236 start 1117.635730302 duration 3805 ns
<idle>-0 [002] dp..3.. 1117.635736: thread_noise: swapper/2:0 start 1117.635730535 duration 2244 ns
timerlat/2-5150 [002] .p..... 1117.635737: #20676 context thread timer_latency 8956 ns
<idle>-0 [003] dp.h1.. 1117.636412: #20676 context irq timer_latency 2799 ns
<idle>-0 [003] dN.h2.. 1117.636416: irq_noise: local_timer:236 start 1117.636411102 duration 4325 ns
<idle>-0 [003] dp..3.. 1117.636418: thread_noise: swapper/3:0 start 1117.636411343 duration 2596 ns
timerlat/3-5151 [003] .p..... 1117.636419: #20676 context thread timer_latency 10347 ns
<idle>-0 [000] dp.h1.. 1117.636614: #20677 context irq timer_latency 2336 ns
<idle>-0 [000] dN.h2.. 1117.636618: irq_noise: local_timer:236 start 1117.636613430 duration 4488 ns
<idle>-0 [000] dp..3.. 1117.636620: thread_noise: swapper/0:0 start 1117.636613657 duration 2378 ns
timerlat/0-5148 [000] .p..... 1117.636622: #20677 context thread timer_latency 10012 ns
<idle>-0 [001] dp.h1.. 1117.636673: #20677 context irq timer_latency 2330 ns
<idle>-0 [001] dN.h2.. 1117.636677: irq_noise: local_timer:236 start 1117.636672785 duration 3844 ns
<idle>-0 [001] dp..3.. 1117.636679: thread_noise: swapper/1:0 start 1117.636673029 duration 2452 ns
timerlat/1-5149 [001] .p..... 1117.636680: #20677 context thread timer_latency 9195 ns
<idle>-0 [002] dp.h1.. 1117.636731: #20677 context irq timer_latency 2395 ns
<idle>-0 [002] dN.h2.. 1117.636734: irq_noise: local_timer:236 start 1117.636730337 duration 3899 ns
<idle>-0 [002] dp..3.. 1117.636737: thread_noise: swapper/2:0 start 1117.636730594 duration 2273 ns
timerlat/2-5150 [002] .p..... 1117.636738: #20677 context thread timer_latency 9160 ns
<idle>-0 [003] dp.h1.. 1117.637412: #20677 context irq timer_latency 2782 ns
<idle>-0 [003] dN.h2.. 1117.637415: irq_noise: local_timer:236 start 1117.637411038 duration 4118 ns
<idle>-0 [003] dp..3.. 1117.637418: thread_noise: swapper/3:0 start 1117.637411309 duration 2522 ns
timerlat/3-5151 [003] .p..... 1117.637419: #20677 context thread timer_latency 10044 ns
<idle>-0 [000] dp.h1.. 1117.637615: #20678 context irq timer_latency 3369 ns
<idle>-0 [000] dN.h2.. 1117.637619: irq_noise: local_timer:236 start 1117.637614287 duration 4594 ns
<idle>-0 [000] dp..3.. 1117.637621: thread_noise: swapper/0:0 start 1117.637614672 duration 2282 ns
timerlat/0-5148 [000] .p..... 1117.637623: #20678 context thread timer_latency 10975 ns
<idle>-0 [001] dp.h1.. 1117.637673: #20678 context irq timer_latency 2295 ns
<idle>-0 [001] dN.h2.. 1117.637677: irq_noise: local_timer:236 start 1117.637672738 duration 3827 ns
<idle>-0 [001] dp..3.. 1117.637679: thread_noise: swapper/1:0 start 1117.637672977 duration 2443 ns
timerlat/1-5149 [001] .p..... 1117.637680: #20678 context thread timer_latency 9156 ns
<idle>-0 [002] dp.h1.. 1117.637731: #20678 context irq timer_latency 2346 ns
<idle>-0 [002] dN.h2.. 1117.637734: irq_noise: local_timer:236 start 1117.637730295 duration 3863 ns
<idle>-0 [002] dp..3.. 1117.637737: thread_noise: swapper/2:0 start 1117.637730528 duration 2255 ns
timerlat/2-5150 [002] .p..... 1117.637737: #20678 context thread timer_latency 9079 ns
<idle>-0 [003] dp.h1.. 1117.638412: #20678 context irq timer_latency 2824 ns
<idle>-0 [003] dN.h2.. 1117.638415: irq_noise: local_timer:236 start 1117.638411068 duration 4021 ns
<idle>-0 [003] dp..3.. 1117.638418: thread_noise: swapper/3:0 start 1117.638411334 duration 2513 ns
timerlat/3-5151 [003] .p..... 1117.638419: #20678 context thread timer_latency 9979 ns
<idle>-0 [000] dp.h1.. 1117.638615: #20679 context irq timer_latency 3431 ns
<idle>-0 [000] dN.h2.. 1117.638619: irq_noise: local_timer:236 start 1117.638614310 duration 4656 ns
<idle>-0 [000] dp..3.. 1117.638621: thread_noise: swapper/0:0 start 1117.638614717 duration 2325 ns
timerlat/0-5148 [000] .p..... 1117.638623: #20679 context thread timer_latency 11043 ns
<idle>-0 [001] dp.h1.. 1117.638673: #20679 context irq timer_latency 2348 ns
<idle>-0 [001] dN.h2.. 1117.638677: irq_noise: local_timer:236 start 1117.638672772 duration 3882 ns
<idle>-0 [001] dp..3.. 1117.638679: thread_noise: swapper/1:0 start 1117.638673012 duration 2416 ns
timerlat/1-5149 [001] .p..... 1117.638680: #20679 context thread timer_latency 9229 ns
<idle>-0 [002] dp.h1.. 1117.638731: #20679 context irq timer_latency 2329 ns
<idle>-0 [002] dN.h2.. 1117.638734: irq_noise: local_timer:236 start 1117.638730257 duration 3901 ns
<idle>-0 [002] dp..3.. 1117.638737: thread_noise: swapper/2:0 start 1117.638730494 duration 2199 ns
timerlat/2-5150 [002] .p..... 1117.638737: #20679 context thread timer_latency 9029 ns
<idle>-0 [003] dp.h1.. 1117.639412: #20679 context irq timer_latency 2792 ns
<idle>-0 [003] dN.h2.. 1117.639416: irq_noise: local_timer:236 start 1117.639411022 duration 4442 ns
<idle>-0 [003] dp..3.. 1117.639418: thread_noise: swapper/3:0 start 1117.639411285 duration 2585 ns
timerlat/3-5151 [003] .p..... 1117.639419: #20679 context thread timer_latency 10447 ns
<idle>-0 [000] dp.h1.. 1117.639615: #20680 context irq timer_latency 3446 ns
<idle>-0 [000] dN.h2.. 1117.639619: irq_noise: local_timer:236 start 1117.639614333 duration 4796 ns
<idle>-0 [000] dp..3.. 1117.639622: thread_noise: swapper/0:0 start 1117.639614715 duration 2259 ns
timerlat/0-5148 [000] .p..... 1117.639623: #20680 context thread timer_latency 11243 ns
<idle>-0 [001] dp.h1.. 1117.639674: #20680 context irq timer_latency 2331 ns
<idle>-0 [001] dN.h2.. 1117.639677: irq_noise: local_timer:236 start 1117.639672744 duration 4537 ns
<idle>-0 [001] dp..3.. 1117.639680: thread_noise: swapper/1:0 start 1117.639672978 duration 2458 ns
timerlat/1-5149 [001] .p..... 1117.639681: #20680 context thread timer_latency 10236 ns
<idle>-0 [002] dp.h1.. 1117.639731: #20680 context irq timer_latency 2369 ns
<idle>-0 [002] dN.h2.. 1117.639736: irq_noise: local_timer:236 start 1117.639730278 duration 4623 ns
<idle>-0 [002] dp..3.. 1117.639738: thread_noise: swapper/2:0 start 1117.639730516 duration 2894 ns
timerlat/2-5150 [002] .p..... 1117.639739: #20680 context thread timer_latency 10713 ns
<idle>-0 [003] dp.h1.. 1117.640412: #20680 context irq timer_latency 2788 ns
<idle>-0 [003] dN.h2.. 1117.640416: irq_noise: local_timer:236 start 1117.640411013 duration 4884 ns
<idle>-0 [003] dp..3.. 1117.640419: thread_noise: swapper/3:0 start 1117.640411264 duration 2632 ns
timerlat/3-5151 [003] .p..... 1117.640420: #20680 context thread timer_latency 11233 ns
<idle>-0 [000] dp.h1.. 1117.640615: #20681 context irq timer_latency 3428 ns
<idle>-0 [000] dN.h2.. 1117.640619: irq_noise: local_timer:236 start 1117.640614284 duration 4550 ns
<idle>-0 [000] dp..3.. 1117.640621: thread_noise: swapper/0:0 start 1117.640614679 duration 2300 ns
timerlat/0-5148 [000] .p..... 1117.640622: #20681 context thread timer_latency 10682 ns
<idle>-0 [001] dp.h1.. 1117.640673: #20681 context irq timer_latency 2317 ns
<idle>-0 [001] dN.h2.. 1117.640677: irq_noise: local_timer:236 start 1117.640672703 duration 4194 ns
<idle>-0 [001] dp..3.. 1117.640679: thread_noise: swapper/1:0 start 1117.640672947 duration 2409 ns
timerlat/1-5149 [001] .p..... 1117.640681: #20681 context thread timer_latency 9975 ns
<idle>-0 [002] dp.h1.. 1117.640731: #20681 context irq timer_latency 2353 ns
<idle>-0 [002] dN.h2.. 1117.640734: irq_noise: local_timer:236 start 1117.640730249 duration 3953 ns
<idle>-0 [002] dp..3.. 1117.640737: thread_noise: swapper/2:0 start 1117.640730483 duration 2224 ns
timerlat/2-5150 [002] .p..... 1117.640737: #20681 context thread timer_latency 9127 ns
<idle>-0 [003] dp.h1.. 1117.641412: #20681 context irq timer_latency 2779 ns
<idle>-0 [003] dN.h2.. 1117.641415: irq_noise: local_timer:236 start 1117.641411007 duration 4150 ns
<idle>-0 [003] dp..3.. 1117.641418: thread_noise: swapper/3:0 start 1117.641411237 duration 2566 ns
timerlat/3-5151 [003] .p..... 1117.641419: #20681 context thread timer_latency 10115 ns
<idle>-0 [000] dp.h1.. 1117.641615: #20682 context irq timer_latency 3396 ns
<idle>-0 [000] dN.h2.. 1117.641619: irq_noise: local_timer:236 start 1117.641614247 duration 4696 ns
<idle>-0 [000] dp..3.. 1117.641621: thread_noise: swapper/0:0 start 1117.641614630 duration 2358 ns
timerlat/0-5148 [000] .p..... 1117.641623: #20682 context thread timer_latency 11197 ns
<idle>-0 [001] dp.h1.. 1117.641673: #20682 context irq timer_latency 2360 ns
<idle>-0 [001] dN.h2.. 1117.641677: irq_noise: local_timer:236 start 1117.641672735 duration 3854 ns
<idle>-0 [001] dp..3.. 1117.641679: thread_noise: swapper/1:0 start 1117.641672973 duration 2437 ns
timerlat/1-5149 [001] .p..... 1117.641680: #20682 context thread timer_latency 9255 ns
<idle>-0 [002] dp.h1.. 1117.641731: #20682 context irq timer_latency 2352 ns
<idle>-0 [002] dN.h2.. 1117.641734: irq_noise: local_timer:236 start 1117.641730231 duration 3922 ns
<idle>-0 [002] dp..3.. 1117.641737: thread_noise: swapper/2:0 start 1117.641730465 duration 2268 ns
timerlat/2-5150 [002] .p..... 1117.641737: #20682 context thread timer_latency 9150 ns
<idle>-0 [001] dN.h2.. 1117.642390: irq_noise: local_timer:236 start 1117.642384928 duration 5213 ns
<idle>-0 [003] dp.h1.. 1117.642411: #20682 context irq timer_latency 2285 ns
<idle>-0 [003] dN.h2.. 1117.642415: irq_noise: local_timer:236 start 1117.642410379 duration 4198 ns
<idle>-0 [003] dp..3.. 1117.642417: thread_noise: swapper/3:0 start 1117.642410726 duration 2485 ns
timerlat/3-5151 [003] .p..... 1117.642418: #20682 context thread timer_latency 9556 ns
<idle>-0 [001] dp.h2.. 1117.642520: irq_noise: local_timer:236 start 1117.642518932 duration 554 ns
<idle>-0 [000] dp.h1.. 1117.642614: #20683 context irq timer_latency 2440 ns
<idle>-0 [000] dN.h2.. 1117.642618: irq_noise: local_timer:236 start 1117.642613416 duration 4704 ns
<idle>-0 [000] dp..3.. 1117.642621: thread_noise: swapper/0:0 start 1117.642613661 duration 2388 ns
timerlat/0-5148 [000] .p..... 1117.642622: #20683 context thread timer_latency 10243 ns
kworker/1:3-499 [001] dp.h1.. 1117.642677: #20683 context irq timer_latency 5698 ns
kworker/1:3-499 [001] dN.h2.. 1117.642696: irq_noise: local_timer:236 start 1117.642675929 duration 19694 ns
<idle>-0 [002] dp.h1.. 1117.642731: #20683 context irq timer_latency 2447 ns
<idle>-0 [002] dN.h2.. 1117.642735: irq_noise: local_timer:236 start 1117.642730321 duration 4023 ns
<idle>-0 [002] dp..3.. 1117.642737: thread_noise: swapper/2:0 start 1117.642730543 duration 2260 ns
timerlat/2-5150 [002] .p..... 1117.642738: #20683 context thread timer_latency 9450 ns
kworker/1:3-499 [001] dp..3.. 1117.642961: thread_noise: kworker/1:3:499 start 1117.642676294 duration 264853 ns
timerlat/1-5149 [001] .p..... 1117.642962: #20683 context thread timer_latency 291305 ns
timerlat/1-5149 [001] .p..1.. 1117.642963: <stack trace>
=> timerlat_irq
=> __hrtimer_run_queues
=> hrtimer_interrupt
=> __sysvec_apic_timer_interrupt
=> sysvec_apic_timer_interrupt
=> asm_sysvec_apic_timer_interrupt
=> intel_dmc_load_program
=> intel_display_power_resume
=> intel_runtime_resume
=> pci_pm_runtime_resume
=> __rpm_callback
=> rpm_callback
=> rpm_resume
=> __pm_runtime_resume
=> intel_runtime_pm_get
=> intel_display_power_get
=> intel_digital_port_connected
=> intel_dp_detect
=> drm_helper_probe_detect_ctx
=> output_poll_execute
=> process_one_work
=> worker_thread
=> kthread
=> ret_from_fork
=> 0x69745f6c61636f6c
=> 0x130ce0072656d
=> 0x030101cd
=> 0x7061777300001400
=> 0x312f726570
=> 0x24bf00000000
=> 0x102730d21f9
=> 0x000009be
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-06 3:25 ` Florian Paul Schmidt
@ 2022-10-06 6:27 ` Sebastian Andrzej Siewior
2022-10-06 7:16 ` Florian Paul Schmidt
0 siblings, 1 reply; 11+ messages in thread
From: Sebastian Andrzej Siewior @ 2022-10-06 6:27 UTC (permalink / raw)
To: Florian Paul Schmidt; +Cc: Daniel Bristot de Oliveira, linux-rt-users
On 2022-10-06 05:25:26 [+0200], Florian Paul Schmidt wrote:
> They are 13M each. Attached are just the tails for a start. Do you want
> to see the whole thing?
that looks fine to me.
The runtime_resume path points to intel_dmc_load_program(). The
preempt-disable section there was introduced by commit
dff457d74e7ea ("drm/i915: Speed up DMC firmware loading")
and the other thing seems to be intel_irq_reset() not sure where but it
is the runtime_suspend path.
So disabling runtime-suspend should help.
> FPS
Sebastian
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-06 6:27 ` Sebastian Andrzej Siewior
@ 2022-10-06 7:16 ` Florian Paul Schmidt
2022-10-06 7:26 ` Sebastian Andrzej Siewior
2022-10-06 11:22 ` Florian Paul Schmidt
0 siblings, 2 replies; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-06 7:16 UTC (permalink / raw)
To: Sebastian Andrzej Siewior; +Cc: Daniel Bristot de Oliveira, linux-rt-users
On 10/6/2022 8:27 AM, Sebastian Andrzej Siewior wrote:
> that looks fine to me.
> The runtime_resume path points to intel_dmc_load_program(). The
> preempt-disable section there was introduced by commit
> dff457d74e7ea ("drm/i915: Speed up DMC firmware loading")
>
> and the other thing seems to be intel_irq_reset() not sure where but it
> is the runtime_suspend path.
>
> So disabling runtime-suspend should help.
OK, so it was a user error :) Thanks for teaching me about rtla in the
process! This will turn out to be helpful in the future!
I passed acpi=off as kernel parameter and that seems to have helped! The
closest to runtime-suspend I could find was:
/sys/devices/system/cpu/power/runtime_enabled
which is "disabled" now.
> Sebastian
Thanks again and kind regards,
FPS
--
https://dfdx.eu
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-06 7:16 ` Florian Paul Schmidt
@ 2022-10-06 7:26 ` Sebastian Andrzej Siewior
2022-10-06 11:22 ` Florian Paul Schmidt
1 sibling, 0 replies; 11+ messages in thread
From: Sebastian Andrzej Siewior @ 2022-10-06 7:26 UTC (permalink / raw)
To: Florian Paul Schmidt; +Cc: Daniel Bristot de Oliveira, linux-rt-users
On 2022-10-06 09:16:25 [+0200], Florian Paul Schmidt wrote:
> On 10/6/2022 8:27 AM, Sebastian Andrzej Siewior wrote:
> > that looks fine to me.
> > The runtime_resume path points to intel_dmc_load_program(). The
> > preempt-disable section there was introduced by commit
> > dff457d74e7ea ("drm/i915: Speed up DMC firmware loading")
> >
> > and the other thing seems to be intel_irq_reset() not sure where but it
> > is the runtime_suspend path.
> >
> > So disabling runtime-suspend should help.
>
> OK, so it was a user error :) Thanks for teaching me about rtla in the
> process! This will turn out to be helpful in the future!
So that got introduced in the v5.17 cycle then independent of RT itself?
If so I'm not sure what to do about it. Probably adding it to the i915
pile…
> I passed acpi=off as kernel parameter and that seems to have helped! The
> closest to runtime-suspend I could find was:
>
> /sys/devices/system/cpu/power/runtime_enabled
You should have one for the i915 somewhere under
/sys/devices/pci*/*/drm/*/power
there is powertop which should also have a disable button (it is usually
used to enable it).
Disabling acpi could be a big hammer in case there are also useful
things coming out it.
> which is "disabled" now.
>
> > Sebastian
>
> Thanks again and kind regards,
> FPS
Sebastian
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17
2022-10-06 7:16 ` Florian Paul Schmidt
2022-10-06 7:26 ` Sebastian Andrzej Siewior
@ 2022-10-06 11:22 ` Florian Paul Schmidt
1 sibling, 0 replies; 11+ messages in thread
From: Florian Paul Schmidt @ 2022-10-06 11:22 UTC (permalink / raw)
To: Sebastian Andrzej Siewior; +Cc: Daniel Bristot de Oliveira, linux-rt-users
On 10/6/2022 9:16 AM, Florian Paul Schmidt wrote:
> I passed acpi=off as kernel parameter and that seems to have helped!
It helped on 5.17-rc1-rt1 but not on 5.19-rt10. But your comment about
powertop was really helpful for digging through those entries. Setting this:
>> Bad Runtime PM for PCI Device Intel Corporation GeminiLake
[UHD Graphics 600]
from Good to Bad fixed the spikes on that particular kernel.
FPS
--
https://dfdx.eu
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2022-10-06 11:22 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-10-05 7:46 Regression (latency spike) between 5.16.2-rt19 and 5.17.1-rt17 Florian Paul Schmidt
2022-10-05 13:31 ` Sebastian Andrzej Siewior
2022-10-05 14:45 ` Daniel Bristot de Oliveira
2022-10-05 16:17 ` Florian Paul Schmidt
2022-10-05 16:23 ` Daniel Bristot de Oliveira
2022-10-06 3:25 ` Florian Paul Schmidt
2022-10-06 6:27 ` Sebastian Andrzej Siewior
2022-10-06 7:16 ` Florian Paul Schmidt
2022-10-06 7:26 ` Sebastian Andrzej Siewior
2022-10-06 11:22 ` Florian Paul Schmidt
2022-10-05 16:20 ` Florian Paul Schmidt
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.