[4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Christoph Mathys]

When running cyclictest and the opengl benchmark tool glmark2 I see
pretty severe latency spikes of about 1.8 milliseconds with kernel
4.1.7-rt8.

Using the same machine with different RT kernels (also only one testrun)
- 3.12 max latency is 66 microseconds.
- 3.18 max latency is 157 microseconds

The machine in question uses a Core i7-3770 CPU and the Intel i915
kernel driver.

Can anyone reproduce this? Any ideas? dmesg does not contain any funny
reports...

Christoph

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Matthias Meier]

> When running cyclictest and the opengl benchmark tool glmark2 I see
> pretty severe latency spikes of about 1.8 milliseconds with kernel
> 4.1.7-rt8.
is there a high interrupt rate on '/proc/interrupts' during glmark2 
running compared to the other kernels?

Regards
     Matthias

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Christoph Mathys]

On Wed, Oct 14, 2015 at 9:51 AM, Matthias Meier
<matthias.j.meier@gmx.net> wrote:
> is there a high interrupt rate on '/proc/interrupts' during glmark2 running
> compared to the other kernels?

I checked the interrupt for i915 on 3.12 and 4.1. After a complete
glmark2 run on a freshly booted system I have a lot less interrupts on
4.1 than on 3.12.

3.12: 1'794843 irqs
4.1: 950'367 irqs

Christoph

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Christoph Mathys]

On Tue, Oct 13, 2015 at 5:35 PM, Christoph Mathys <eraserix@gmail.com> wrote:
> Can anyone reproduce this? Any ideas? dmesg does not contain any funny
> reports...

It is actually not true that there are no funny reports. After
enabling more debug options I now get the BUG below once per second.
There are other callpaths than the one below that trigger this
message, but they all go through the function
intel_pipe_update_start().

[   17.694307] BUG: sleeping function called from invalid context at
kernel/locking/rtmutex.c:917
[   17.694308] in_atomic(): 0, irqs_disabled(): 1, pid: 102, name: kworker/3:1
[   17.694309] 2 locks held by kworker/3:1/102:
[   17.694326]  #0:  ("events"){.+.+.+}, at: [<ffffffff81079e60>]
process_one_work+0x170/0x8b0
[   17.694328]  #1:  ((&intel_crtc->mmio_flip.work)){+.+...}, at:
[<ffffffff81079e60>] process_one_work+0x170/0x8b0
[   17.694329] irq event stamp: 21082
[   17.694330] hardirqs last  enabled at (21081): [<ffffffff810ed791>]
ktime_get_raw+0x61/0x100
[   17.694347] hardirqs last disabled at (21082): [<ffffffffa02fabf3>]
intel_pipe_update_start+0x113/0x640 [i915]
[   17.694349] softirqs last  enabled at (0): [<ffffffff81057591>]
copy_process.part.34+0x5e1/0x1d50
[   17.694350] softirqs last disabled at (0): [<          (null)>]
      (null)
[   17.694351] CPU: 3 PID: 102 Comm: kworker/3:1 Tainted: G
E   4.1.7-realtime-2-rt8 #2
[   17.694352] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
BIOS DD3-1-1D 08/21/2013
[   17.694364] Workqueue: events intel_mmio_flip_work_func [i915]
[   17.694365]  ffffffff81c84a33 ffff8803fbf4fb98 ffffffff817f961d
0000000000000002
[   17.694366]  ffff8803fbf60000 ffff8803fbf4fbc8 ffffffff8108785a
ffff8803fbf4fbc8
[   17.694367]  ffff880036510808 ffff880036510808 0000000000000002
ffff8803fbf4fbf8
[   17.694367] Call Trace:
[   17.694370]  [<ffffffff817f961d>] dump_stack+0x4a/0x61
[   17.694372]  [<ffffffff8108785a>] ___might_sleep+0x13a/0x200
[   17.694373]  [<ffffffff81800f24>] rt_spin_lock+0x24/0x60
[   17.694374]  [<ffffffff8108bbac>] ? migrate_disable+0x6c/0xe0
[   17.694375]  [<ffffffff810a9bab>] prepare_to_wait+0x2b/0xa0
[   17.694386]  [<ffffffffa02faca8>] intel_pipe_update_start+0x1c8/0x640 [i915]
[   17.694387]  [<ffffffff810aa070>] ? prepare_to_wait_event+0x130/0x130
[   17.694396]  [<ffffffffa02dcf04>] intel_mmio_flip_work_func+0x64/0x310 [i915]
[   17.694397]  [<ffffffff810b2d2f>] ? __lock_is_held+0x5f/0x90
[   17.694399]  [<ffffffff81079f0f>] process_one_work+0x21f/0x8b0
[   17.694400]  [<ffffffff81079e60>] ? process_one_work+0x170/0x8b0
[   17.694402]  [<ffffffff8107a709>] worker_thread+0x169/0x4e0
[   17.694404]  [<ffffffff8107a5a0>] ? process_one_work+0x8b0/0x8b0
[   17.694405]  [<ffffffff81081054>] kthread+0xe4/0x100
[   17.694406]  [<ffffffff810b5a4d>] ? trace_hardirqs_on+0xd/0x10
[   17.694407]  [<ffffffff81080f70>] ? kthread_create_on_node+0x240/0x240
[   17.694409]  [<ffffffff81801d62>] ret_from_fork+0x42/0x70
[   17.694410]  [<ffffffff81080f70>] ? kthread_create_on_node+0x240/0x240

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Josh Cartwright]

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

On Wed, Oct 14, 2015 at 11:08:38AM +0200, Christoph Mathys wrote:
> On Tue, Oct 13, 2015 at 5:35 PM, Christoph Mathys <eraserix@gmail.com> wrote:
> > Can anyone reproduce this? Any ideas? dmesg does not contain any funny
> > reports...
>
> It is actually not true that there are no funny reports. After
> enabling more debug options I now get the BUG below once per second.
> There are other callpaths than the one below that trigger this
> message, but they all go through the function
> intel_pipe_update_start().
>
> [   17.694307] BUG: sleeping function called from invalid context at
> kernel/locking/rtmutex.c:917
> [   17.694308] in_atomic(): 0, irqs_disabled(): 1, pid: 102, name: kworker/3:1
[..]
> [   17.694347] hardirqs last disabled at (21082): [<ffffffffa02fabf3>] intel_pipe_update_start+0x113/0x640 [i915]
[..]
> [   17.694367] Call Trace:
> [   17.694370]  [<ffffffff817f961d>] dump_stack+0x4a/0x61
> [   17.694372]  [<ffffffff8108785a>] ___might_sleep+0x13a/0x200
> [   17.694373]  [<ffffffff81800f24>] rt_spin_lock+0x24/0x60
> [   17.694374]  [<ffffffff8108bbac>] ? migrate_disable+0x6c/0xe0
> [   17.694375]  [<ffffffff810a9bab>] prepare_to_wait+0x2b/0xa0
> [   17.694386]  [<ffffffffa02faca8>] intel_pipe_update_start+0x1c8/0x640 [i915]

Looks like intel_pipe_update_start() is trying to queue the caller up on
the drm_crtc_vblank_waitqueue() from an local_irq_disable()'d region,
which doesn't fly on -rt, as the internal waitqueue lock is a converted
rt_mutex w/ PREEMPT_RT (and thus can sleep if contended).

Perhaps this driver is a candidate for a simple waitqueue conversion.

  Josh

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

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Thomas Gleixner]

On Fri, 16 Oct 2015, Josh Cartwright wrote:
> On Wed, Oct 14, 2015 at 11:08:38AM +0200, Christoph Mathys wrote:
> > On Tue, Oct 13, 2015 at 5:35 PM, Christoph Mathys <eraserix@gmail.com> wrote:
> > > Can anyone reproduce this? Any ideas? dmesg does not contain any funny
> > > reports...
> >
> > It is actually not true that there are no funny reports. After
> > enabling more debug options I now get the BUG below once per second.
> > There are other callpaths than the one below that trigger this
> > message, but they all go through the function
> > intel_pipe_update_start().
> >
> > [   17.694307] BUG: sleeping function called from invalid context at
> > kernel/locking/rtmutex.c:917
> > [   17.694308] in_atomic(): 0, irqs_disabled(): 1, pid: 102, name: kworker/3:1
> [..]
> > [   17.694347] hardirqs last disabled at (21082): [<ffffffffa02fabf3>] intel_pipe_update_start+0x113/0x640 [i915]
> [..]
> > [   17.694367] Call Trace:
> > [   17.694370]  [<ffffffff817f961d>] dump_stack+0x4a/0x61
> > [   17.694372]  [<ffffffff8108785a>] ___might_sleep+0x13a/0x200
> > [   17.694373]  [<ffffffff81800f24>] rt_spin_lock+0x24/0x60
> > [   17.694374]  [<ffffffff8108bbac>] ? migrate_disable+0x6c/0xe0
> > [   17.694375]  [<ffffffff810a9bab>] prepare_to_wait+0x2b/0xa0
> > [   17.694386]  [<ffffffffa02faca8>] intel_pipe_update_start+0x1c8/0x640 [i915]
> 
> Looks like intel_pipe_update_start() is trying to queue the caller up on
> the drm_crtc_vblank_waitqueue() from an local_irq_disable()'d region,
> which doesn't fly on -rt, as the internal waitqueue lock is a converted
> rt_mutex w/ PREEMPT_RT (and thus can sleep if contended).
> 
> Perhaps this driver is a candidate for a simple waitqueue conversion.

It can, but it calls some more functions with interrupts disabled
which are taking regular spinlocks. So that does not cure it.

Thanks,

	tglx

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Christoph Mathys]

While playing with 4.1.13-rt15 I stumbled across the following thread
where Luis reports the same problem with i915 gpu:
i915: sleeping function called from invalid context at
intel_pipe_update_start/end
http://www.spinics.net/lists/linux-rt-users/msg13543.html

Sebastian suggested to set i915.use_mmio_flip to -1. I tried this, and
this avoids the callstack that I've posted before
(intel_mmio_flip_work). The BUG below is now the dominant one:

[ 1513.969093] BUG: sleeping function called from invalid context at
kernel/locking/rtmutex.c:917
[ 1513.969094] in_atomic(): 0, irqs_disabled(): 1, pid: 2109, name: Xorg
[ 1513.969095] 2 locks held by Xorg/2109:
[ 1513.969110]  #0:  (crtc_ww_class_acquire){+.+.+.}, at:
[<ffffffffa01d8a6c>] drm_modeset_lock_crtc+0x4c/0x100 [drm]
[ 1513.969118]  #1:  (crtc_ww_class_mutex){+.+.+.}, at:
[<ffffffffa01d8871>] drm_modeset_lock+0x41/0x130 [drm]
[ 1513.969119] irq event stamp: 23744596
[ 1513.969121] hardirqs last  enabled at (23744595):
[<ffffffff810ed47f>] ktime_get+0x6f/0x120
[ 1513.969137] hardirqs last disabled at (23744596):
[<ffffffffa02bca93>] intel_pipe_update_start+0x113/0x640 [i915]
[ 1513.969139] softirqs last  enabled at (0): [<ffffffff810565f1>]
copy_process.part.33+0x5e1/0x1d50
[ 1513.969140] softirqs last disabled at (0): [<          (null)>]
      (null)
[ 1513.969141] CPU: 2 PID: 2109 Comm: Xorg Tainted: G            E
4.1.13-realtime-1-rt15 #3
[ 1513.969142] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
BIOS DD3-1-1D 08/21/2013
[ 1513.969144]  ffffffff81c8606d ffff8803ec1bb958 ffffffff81802c33
0000000000000002
[ 1513.969145]  ffff8803fdfb0000 ffff8803ec1bb988 ffffffff8108713a
ffff8803ec1bb988
[ 1513.969146]  ffff8803fa99a188 ffff8803fa99a188 0000000000000002
ffff8803ec1bb9b8
[ 1513.969146] Call Trace:
[ 1513.969149]  [<ffffffff81802c33>] dump_stack+0x4a/0x61
[ 1513.969151]  [<ffffffff8108713a>] ___might_sleep+0x13a/0x200
[ 1513.969153]  [<ffffffff8180a5e4>] rt_spin_lock+0x24/0x60
[ 1513.969155]  [<ffffffff8108b47c>] ? migrate_disable+0x6c/0xe0
[ 1513.969156]  [<ffffffff810a95fb>] prepare_to_wait+0x2b/0xa0
[ 1513.969167]  [<ffffffffa02bcb48>] intel_pipe_update_start+0x1c8/0x640 [i915]
[ 1513.969168]  [<ffffffff810a9ac0>] ? prepare_to_wait_event+0x130/0x130
[ 1513.969178]  [<ffffffffa02a7fc6>] intel_begin_crtc_commit+0x166/0x1e0 [i915]
[ 1513.969183]  [<ffffffffa02146f2>]
drm_plane_helper_commit+0x112/0x2c0 [drm_kms_helper]
[ 1513.969186]  [<ffffffffa021493a>] drm_plane_helper_update+0x9a/0xf0
[drm_kms_helper]
[ 1513.969193]  [<ffffffffa01c8bc8>] __setplane_internal+0x248/0x350 [drm]
[ 1513.969199]  [<ffffffffa01c8df5>] drm_mode_cursor_universal+0x125/0x210 [drm]
[ 1513.969205]  [<ffffffffa01c8f5f>] drm_mode_cursor_common+0x7f/0x1b0 [drm]
[ 1513.969212]  [<ffffffffa01cd411>] drm_mode_cursor_ioctl+0x41/0x50 [drm]
[ 1513.969216]  [<ffffffffa01bd0a9>] drm_ioctl+0x349/0x690 [drm]
[ 1513.969222]  [<ffffffffa01cd3d0>] ? drm_mode_setcrtc+0x630/0x630 [drm]
[ 1513.969224]  [<ffffffff81095585>] ? local_clock+0x25/0x30
[ 1513.969225]  [<ffffffff810b2443>] ? lock_release_holdtime.part.31+0xd3/0x1a0
[ 1513.969227]  [<ffffffff81203088>] do_vfs_ioctl+0x328/0x5e0
[ 1513.969228]  [<ffffffff8120f2a5>] ? __fget+0x5/0x210
[ 1513.969229]  [<ffffffff8120f51a>] ? __fget_light+0x2a/0xa0
[ 1513.969230]  [<ffffffff812033c1>] SyS_ioctl+0x81/0xa0
[ 1513.969232]  [<ffffffff8180afdb>] system_call_fastpath+0x16/0x73

Christoph

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Sebastian Andrzej Siewior]

* Christoph Mathys | 2015-12-21 14:19:10 [+0100]:

>While playing with 4.1.13-rt15 I stumbled across the following thread
>where Luis reports the same problem with i915 gpu:
>i915: sleeping function called from invalid context at
>intel_pipe_update_start/end
>http://www.spinics.net/lists/linux-rt-users/msg13543.html
>
>Sebastian suggested to set i915.use_mmio_flip to -1. I tried this, and
>this avoids the callstack that I've posted before
>(intel_mmio_flip_work). The BUG below is now the dominant one:
perfect.

|BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:917
|in_atomic(): 0, irqs_disabled(): 1, pid: 2109, name: Xorg
|hardirqs last disabled at (23744596): [<ffffffffa02bca93>] intel_pipe_update_start+0x113/0x640 [i915]
|Call Trace:
| [<ffffffff81802c33>] dump_stack+0x4a/0x61
| [<ffffffff8108713a>] ___might_sleep+0x13a/0x200
| [<ffffffff8180a5e4>] rt_spin_lock+0x24/0x60
| [<ffffffff8108b47c>] ? migrate_disable+0x6c/0xe0
| [<ffffffff810a95fb>] prepare_to_wait+0x2b/0xa0
| [<ffffffffa02bcb48>] intel_pipe_update_start+0x1c8/0x640 [i915]
| [<ffffffff810a9ac0>] ? prepare_to_wait_event+0x130/0x130
| [<ffffffffa02a7fc6>] intel_begin_crtc_commit+0x166/0x1e0 [i915]
| [<ffffffffa02146f2>] drm_plane_helper_commit+0x112/0x2c0 [drm_kms_helper]
| [<ffffffffa021493a>] drm_plane_helper_update+0x9a/0xf0

I have to admit, the i915 tries very hard to avoid running on -RT. Could
you try the s/local_irq_disable();/local_irq_disable_nort();/ patch
mentioned in the thread?

Anyone of the i915 hackers an idea how could get the i915 working
without disabling interrupts? Is really required?

Sebastian

Re: [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Christoph Mathys]

On Tue, Dec 22, 2015 at 4:37 PM, Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
> I have to admit, the i915 tries very hard to avoid running on -RT. Could
> you try the s/local_irq_disable();/local_irq_disable_nort();/ patch
> mentioned in the thread?

It did not crash so far, I did some usual work and executed glmark2
several times. The BUG has not surfaced again. BUT, the latency is
still far from ideal, it takes only seconds for the maximum latency to
spike into the range of milliseconds. By the way, this is now
4.1.15-rt17 with the changes from here:
http://www.spinics.net/lists/linux-rt-users/msg13543.html

During some tests with cyclictests --breaktrace I've seen more BUG
messages, but they might relate to the kernel tracing. Unfortunately,
I could not make much of the --breaktrace.

[ 4629.753864] BUG: sleeping function called from invalid context at
kernel/locking/rtmutex.c:917
[ 4629.753865] in_atomic(): 1, irqs_disabled(): 0, pid: 1913, name: Xorg
[ 4629.753866] 2 locks held by Xorg/1913:
[ 4629.753879]  #0:  (crtc_ww_class_acquire){+.+.+.}, at:
[<ffffffffa0211a6c>] drm_modeset_lock_crtc+0x4c/0x100 [drm]
[ 4629.753887]  #1:  (crtc_ww_class_mutex){+.+.+.}, at:
[<ffffffffa0211871>] drm_modeset_lock+0x41/0x130 [drm]
[ 4629.753888] CPU: 4 PID: 1913 Comm: Xorg Tainted: G            E
4.1.15-i915-patch-realtime-1-rt17+ #4
[ 4629.753889] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
BIOS DD3-1-1D 08/21/2013
[ 4629.753891]  ffffffff81c862ce ffff8803e92538b8 ffffffff81805313
0000000000005b10
[ 4629.753892]  ffff8803e8baa660 ffff8803e92538e8 ffffffff8108813a
ffff8803e92538d8
[ 4629.753893]  ffff8803fe6d0070 ffff8803fe6d0070 ffff8803fe6d0068
ffff8803e9253918
[ 4629.753893] Call Trace:
[ 4629.753897]  [<ffffffff81805313>] dump_stack+0x4a/0x61
[ 4629.753899]  [<ffffffff8108813a>] ___might_sleep+0x13a/0x200
[ 4629.753901]  [<ffffffff8180ccc4>] rt_spin_lock+0x24/0x60
[ 4629.753916]  [<ffffffffa02f61d6>] gen6_read32+0x46/0x380 [i915]
[ 4629.753925]  [<ffffffffa02d4b42>] gm45_get_vblank_counter+0x32/0x40 [i915]
[ 4629.753934]  [<ffffffffa02e11b5>]
ftrace_raw_event_i915_pipe_update_start+0x65/0xb0 [i915]
[ 4629.753944]  [<ffffffffa0324c23>] intel_pipe_update_start+0x2a3/0x640 [i915]
[ 4629.753946]  [<ffffffff810aaac0>] ? prepare_to_wait_event+0x130/0x130
[ 4629.753956]  [<ffffffffa030ffc6>] intel_begin_crtc_commit+0x166/0x1e0 [i915]
[ 4629.753961]  [<ffffffffa026e6f2>]
drm_plane_helper_commit+0x112/0x2c0 [drm_kms_helper]
[ 4629.753963]  [<ffffffffa026e93a>] drm_plane_helper_update+0x9a/0xf0
[drm_kms_helper]
[ 4629.753970]  [<ffffffffa0201bc8>] __setplane_internal+0x248/0x350 [drm]
[ 4629.753975]  [<ffffffffa0201df5>] drm_mode_cursor_universal+0x125/0x210 [drm]
[ 4629.753981]  [<ffffffffa0201f5f>] drm_mode_cursor_common+0x7f/0x1b0 [drm]
[ 4629.753987]  [<ffffffffa0206411>] drm_mode_cursor_ioctl+0x41/0x50 [drm]
[ 4629.753992]  [<ffffffffa01f60a9>] drm_ioctl+0x349/0x690 [drm]
[ 4629.753998]  [<ffffffffa02063d0>] ? drm_mode_setcrtc+0x630/0x630 [drm]
[ 4629.753999]  [<ffffffff81096585>] ? local_clock+0x25/0x30
[ 4629.754001]  [<ffffffff810b3443>] ? lock_release_holdtime.part.31+0xd3/0x1a0
[ 4629.754002]  [<ffffffff81204088>] do_vfs_ioctl+0x328/0x5e0
[ 4629.754004]  [<ffffffff812102a5>] ? __fget+0x5/0x210
[ 4629.754004]  [<ffffffff8121051a>] ? __fget_light+0x2a/0xa0
[ 4629.754005]  [<ffffffff812043c1>] SyS_ioctl+0x81/0xa0
[ 4629.754007]  [<ffffffff8180d804>] tracesys_phase2+0x88/0x8d

[  361.526236] BUG: sleeping function called from invalid context at
kernel/locking/rtmutex.c:917
[  361.526237] in_atomic(): 1, irqs_disabled(): 0, pid: 667, name: irq/51-i915
[  361.526237] no locks held by irq/51-i915/667.
[  361.526239] CPU: 4 PID: 667 Comm: irq/51-i915 Tainted: G
E   4.1.15-i915-patch-realtime-1-rt17+ #4
[  361.526240] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
BIOS DD3-1-1D 08/21/2013
[  361.526242]  ffffffff81c862ce ffff8803fe6e7b58 ffffffff81805313
0000000000000000
[  361.526243]  ffff8803ff3d4cc0 ffff8803fe6e7b88 ffffffff8108813a
0000000000000296
[  361.526244]  ffff8803fe6d0070 ffff8803fe6d0070 ffff8803fe6d0068
ffff8803fe6e7bb8
[  361.526244] Call Trace:
[  361.526249]  [<ffffffff81805313>] dump_stack+0x4a/0x61
[  361.526251]  [<ffffffff8108813a>] ___might_sleep+0x13a/0x200
[  361.526253]  [<ffffffff8180ccc4>] rt_spin_lock+0x24/0x60
[  361.526281]  [<ffffffffa02f61d6>] gen6_read32+0x46/0x380 [i915]
[  361.526283]  [<ffffffff81142270>] ? trace_event_buffer_lock_reserve+0x40/0x80
[  361.526293]  [<ffffffffa02e782f>] gen6_ring_get_seqno+0x2f/0x40 [i915]
[  361.526301]  [<ffffffffa02e0eef>]
ftrace_raw_event_i915_gem_request_notify+0x5f/0x90 [i915]
[  361.526309]  [<ffffffffa02d843d>] notify_ring.isra.12+0xcd/0x240 [i915]
[  361.526316]  [<ffffffffa02d8a0c>] snb_gt_irq_handler+0x12c/0x180 [i915]
[  361.526323]  [<ffffffffa02dab97>] ironlake_irq_handler+0x1c7/0xfe0 [i915]
[  361.526324]  [<ffffffff81087f0d>] ? finish_task_switch+0x4d/0x140
[  361.526325]  [<ffffffff810cf7e7>] irq_forced_thread_fn+0x27/0x70
[  361.526326]  [<ffffffff810cfd99>] irq_thread+0x149/0x1f0
[  361.526327]  [<ffffffff810cf7c0>] ? irq_thread_fn+0x40/0x40
[  361.526328]  [<ffffffff810cf860>] ? wake_threads_waitq+0x30/0x30
[  361.526329]  [<ffffffff810cfc50>] ? irq_thread_check_affinity+0x70/0x70
[  361.526330]  [<ffffffff81081854>] kthread+0xe4/0x100
[  361.526332]  [<ffffffff810b649d>] ? trace_hardirqs_on+0xd/0x10
[  361.526333]  [<ffffffff81081770>] ? kthread_create_on_node+0x240/0x240
[  361.526334]  [<ffffffff8180db22>] ret_from_fork+0x42/0x70
[  361.526335]  [<ffffffff81081770>] ? kthread_create_on_node+0x240/0x240

Re: [Intel-gfx] [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Daniel Vetter]

On Wed, Dec 23, 2015 at 01:40:06PM +0100, Christoph Mathys wrote:
> On Tue, Dec 22, 2015 at 4:37 PM, Sebastian Andrzej Siewior
> <bigeasy@linutronix.de> wrote:
> > I have to admit, the i915 tries very hard to avoid running on -RT. Could
> > you try the s/local_irq_disable();/local_irq_disable_nort();/ patch
> > mentioned in the thread?
> 
> It did not crash so far, I did some usual work and executed glmark2
> several times. The BUG has not surfaced again. BUT, the latency is
> still far from ideal, it takes only seconds for the maximum latency to
> spike into the range of milliseconds. By the way, this is now
> 4.1.15-rt17 with the changes from here:
> http://www.spinics.net/lists/linux-rt-users/msg13543.html
> 
> During some tests with cyclictests --breaktrace I've seen more BUG
> messages, but they might relate to the kernel tracing. Unfortunately,
> I could not make much of the --breaktrace.

Waking the GT takes a while, and for a bunch of reasons we need to be able
to do this from irq context, hence spin_lock_irq. Doesn't RT convert that
to a mutex?

Otherwise not sure what would prevent interrupts in your backtrace ...
-Daniel

> 
> [ 4629.753864] BUG: sleeping function called from invalid context at
> kernel/locking/rtmutex.c:917
> [ 4629.753865] in_atomic(): 1, irqs_disabled(): 0, pid: 1913, name: Xorg
> [ 4629.753866] 2 locks held by Xorg/1913:
> [ 4629.753879]  #0:  (crtc_ww_class_acquire){+.+.+.}, at:
> [<ffffffffa0211a6c>] drm_modeset_lock_crtc+0x4c/0x100 [drm]
> [ 4629.753887]  #1:  (crtc_ww_class_mutex){+.+.+.}, at:
> [<ffffffffa0211871>] drm_modeset_lock+0x41/0x130 [drm]
> [ 4629.753888] CPU: 4 PID: 1913 Comm: Xorg Tainted: G            E
> 4.1.15-i915-patch-realtime-1-rt17+ #4
> [ 4629.753889] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
> BIOS DD3-1-1D 08/21/2013
> [ 4629.753891]  ffffffff81c862ce ffff8803e92538b8 ffffffff81805313
> 0000000000005b10
> [ 4629.753892]  ffff8803e8baa660 ffff8803e92538e8 ffffffff8108813a
> ffff8803e92538d8
> [ 4629.753893]  ffff8803fe6d0070 ffff8803fe6d0070 ffff8803fe6d0068
> ffff8803e9253918
> [ 4629.753893] Call Trace:
> [ 4629.753897]  [<ffffffff81805313>] dump_stack+0x4a/0x61
> [ 4629.753899]  [<ffffffff8108813a>] ___might_sleep+0x13a/0x200
> [ 4629.753901]  [<ffffffff8180ccc4>] rt_spin_lock+0x24/0x60
> [ 4629.753916]  [<ffffffffa02f61d6>] gen6_read32+0x46/0x380 [i915]
> [ 4629.753925]  [<ffffffffa02d4b42>] gm45_get_vblank_counter+0x32/0x40 [i915]
> [ 4629.753934]  [<ffffffffa02e11b5>]
> ftrace_raw_event_i915_pipe_update_start+0x65/0xb0 [i915]
> [ 4629.753944]  [<ffffffffa0324c23>] intel_pipe_update_start+0x2a3/0x640 [i915]
> [ 4629.753946]  [<ffffffff810aaac0>] ? prepare_to_wait_event+0x130/0x130
> [ 4629.753956]  [<ffffffffa030ffc6>] intel_begin_crtc_commit+0x166/0x1e0 [i915]
> [ 4629.753961]  [<ffffffffa026e6f2>]
> drm_plane_helper_commit+0x112/0x2c0 [drm_kms_helper]
> [ 4629.753963]  [<ffffffffa026e93a>] drm_plane_helper_update+0x9a/0xf0
> [drm_kms_helper]
> [ 4629.753970]  [<ffffffffa0201bc8>] __setplane_internal+0x248/0x350 [drm]
> [ 4629.753975]  [<ffffffffa0201df5>] drm_mode_cursor_universal+0x125/0x210 [drm]
> [ 4629.753981]  [<ffffffffa0201f5f>] drm_mode_cursor_common+0x7f/0x1b0 [drm]
> [ 4629.753987]  [<ffffffffa0206411>] drm_mode_cursor_ioctl+0x41/0x50 [drm]
> [ 4629.753992]  [<ffffffffa01f60a9>] drm_ioctl+0x349/0x690 [drm]
> [ 4629.753998]  [<ffffffffa02063d0>] ? drm_mode_setcrtc+0x630/0x630 [drm]
> [ 4629.753999]  [<ffffffff81096585>] ? local_clock+0x25/0x30
> [ 4629.754001]  [<ffffffff810b3443>] ? lock_release_holdtime.part.31+0xd3/0x1a0
> [ 4629.754002]  [<ffffffff81204088>] do_vfs_ioctl+0x328/0x5e0
> [ 4629.754004]  [<ffffffff812102a5>] ? __fget+0x5/0x210
> [ 4629.754004]  [<ffffffff8121051a>] ? __fget_light+0x2a/0xa0
> [ 4629.754005]  [<ffffffff812043c1>] SyS_ioctl+0x81/0xa0
> [ 4629.754007]  [<ffffffff8180d804>] tracesys_phase2+0x88/0x8d
> 
> [  361.526236] BUG: sleeping function called from invalid context at
> kernel/locking/rtmutex.c:917
> [  361.526237] in_atomic(): 1, irqs_disabled(): 0, pid: 667, name: irq/51-i915
> [  361.526237] no locks held by irq/51-i915/667.
> [  361.526239] CPU: 4 PID: 667 Comm: irq/51-i915 Tainted: G
> E   4.1.15-i915-patch-realtime-1-rt17+ #4
> [  361.526240] Hardware name: Komax AG, Dierikon Komax-PC/KMX-B75,
> BIOS DD3-1-1D 08/21/2013
> [  361.526242]  ffffffff81c862ce ffff8803fe6e7b58 ffffffff81805313
> 0000000000000000
> [  361.526243]  ffff8803ff3d4cc0 ffff8803fe6e7b88 ffffffff8108813a
> 0000000000000296
> [  361.526244]  ffff8803fe6d0070 ffff8803fe6d0070 ffff8803fe6d0068
> ffff8803fe6e7bb8
> [  361.526244] Call Trace:
> [  361.526249]  [<ffffffff81805313>] dump_stack+0x4a/0x61
> [  361.526251]  [<ffffffff8108813a>] ___might_sleep+0x13a/0x200
> [  361.526253]  [<ffffffff8180ccc4>] rt_spin_lock+0x24/0x60
> [  361.526281]  [<ffffffffa02f61d6>] gen6_read32+0x46/0x380 [i915]
> [  361.526283]  [<ffffffff81142270>] ? trace_event_buffer_lock_reserve+0x40/0x80
> [  361.526293]  [<ffffffffa02e782f>] gen6_ring_get_seqno+0x2f/0x40 [i915]
> [  361.526301]  [<ffffffffa02e0eef>]
> ftrace_raw_event_i915_gem_request_notify+0x5f/0x90 [i915]
> [  361.526309]  [<ffffffffa02d843d>] notify_ring.isra.12+0xcd/0x240 [i915]
> [  361.526316]  [<ffffffffa02d8a0c>] snb_gt_irq_handler+0x12c/0x180 [i915]
> [  361.526323]  [<ffffffffa02dab97>] ironlake_irq_handler+0x1c7/0xfe0 [i915]
> [  361.526324]  [<ffffffff81087f0d>] ? finish_task_switch+0x4d/0x140
> [  361.526325]  [<ffffffff810cf7e7>] irq_forced_thread_fn+0x27/0x70
> [  361.526326]  [<ffffffff810cfd99>] irq_thread+0x149/0x1f0
> [  361.526327]  [<ffffffff810cf7c0>] ? irq_thread_fn+0x40/0x40
> [  361.526328]  [<ffffffff810cf860>] ? wake_threads_waitq+0x30/0x30
> [  361.526329]  [<ffffffff810cfc50>] ? irq_thread_check_affinity+0x70/0x70
> [  361.526330]  [<ffffffff81081854>] kthread+0xe4/0x100
> [  361.526332]  [<ffffffff810b649d>] ? trace_hardirqs_on+0xd/0x10
> [  361.526333]  [<ffffffff81081770>] ? kthread_create_on_node+0x240/0x240
> [  361.526334]  [<ffffffff8180db22>] ret_from_fork+0x42/0x70
> [  361.526335]  [<ffffffff81081770>] ? kthread_create_on_node+0x240/0x240
> _______________________________________________
> Intel-gfx mailing list
> Intel-gfx@lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/intel-gfx

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch

Re: [Intel-gfx] [4.1.7-rt8][report] Very high cyclictest latency during glmark2 on i915 gpu

[Daniel Vetter]

On Tue, Dec 22, 2015 at 04:37:26PM +0100, Sebastian Andrzej Siewior wrote:
> * Christoph Mathys | 2015-12-21 14:19:10 [+0100]:
> 
> >While playing with 4.1.13-rt15 I stumbled across the following thread
> >where Luis reports the same problem with i915 gpu:
> >i915: sleeping function called from invalid context at
> >intel_pipe_update_start/end
> >http://www.spinics.net/lists/linux-rt-users/msg13543.html
> >
> >Sebastian suggested to set i915.use_mmio_flip to -1. I tried this, and
> >this avoids the callstack that I've posted before
> >(intel_mmio_flip_work). The BUG below is now the dominant one:
> perfect.
> 
> |BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:917
> |in_atomic(): 0, irqs_disabled(): 1, pid: 2109, name: Xorg
> |hardirqs last disabled at (23744596): [<ffffffffa02bca93>] intel_pipe_update_start+0x113/0x640 [i915]
> |Call Trace:
> | [<ffffffff81802c33>] dump_stack+0x4a/0x61
> | [<ffffffff8108713a>] ___might_sleep+0x13a/0x200
> | [<ffffffff8180a5e4>] rt_spin_lock+0x24/0x60
> | [<ffffffff8108b47c>] ? migrate_disable+0x6c/0xe0
> | [<ffffffff810a95fb>] prepare_to_wait+0x2b/0xa0
> | [<ffffffffa02bcb48>] intel_pipe_update_start+0x1c8/0x640 [i915]
> | [<ffffffff810a9ac0>] ? prepare_to_wait_event+0x130/0x130
> | [<ffffffffa02a7fc6>] intel_begin_crtc_commit+0x166/0x1e0 [i915]
> | [<ffffffffa02146f2>] drm_plane_helper_commit+0x112/0x2c0 [drm_kms_helper]
> | [<ffffffffa021493a>] drm_plane_helper_update+0x9a/0xf0
> 
> I have to admit, the i915 tries very hard to avoid running on -RT. Could
> you try the s/local_irq_disable();/local_irq_disable_nort();/ patch
> mentioned in the thread?
> 
> Anyone of the i915 hackers an idea how could get the i915 working
> without disabling interrupts? Is really required?

It's a correctness problem - if we don't disable everything we might miss
the timeframe and your screen will tear. Hence why we essentially need to
run this little section of code with hard-rt semantics. There's other
display chips with proper design which don't need hacks like this one
here.

Now of course you might want to accept a broken screen in exchange for
non-broken hard rt for the things you really care about, but I'm not sure
how to encode this.
-Daniel
-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch