[Intel-gfx] [RFC] drm/i915: Move execlists irq handler to a bottom half

Wed Mar 23 11:31:37 UTC 2016

On Wed, Mar 23, 2016 at 10:08:46AM +0000, Tvrtko Ursulin wrote:
> 
> On 23/03/16 09:14, Chris Wilson wrote:
> >On Wed, Mar 23, 2016 at 10:07:35AM +0100, Daniel Vetter wrote:
> >>On Tue, Mar 22, 2016 at 05:30:04PM +0000, Tvrtko Ursulin wrote:
> >>>From: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> >>>
> >>>Doing a lot of work in the interrupt handler introduces huge
> >>>latencies to the system as a whole.
> >>>
> >>>Most dramatic effect can be seen by running an all engine
> >>>stress test like igt/gem_exec_nop/all where, when the kernel
> >>>config is lean enough, the whole system can be brought into
> >>>multi-second periods of complete non-interactivty. That can
> >>>look for example like this:
> >>>
> >>>  NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [kworker/u8:3:143]
> >>>  Modules linked in: [redacted for brevity]
> >>>  CPU: 0 PID: 143 Comm: kworker/u8:3 Tainted: G     U       L  4.5.0-160321+ #183
> >>>  Hardware name: Intel Corporation Broadwell Client platform/WhiteTip Mountain 1
> >>>  Workqueue: i915 gen6_pm_rps_work [i915]
> >>>  task: ffff8800aae88000 ti: ffff8800aae90000 task.ti: ffff8800aae90000
> >>>  RIP: 0010:[<ffffffff8104a3c2>]  [<ffffffff8104a3c2>] __do_softirq+0x72/0x1d0
> >>>  RSP: 0000:ffff88014f403f38  EFLAGS: 00000206
> >>>  RAX: ffff8800aae94000 RBX: 0000000000000000 RCX: 00000000000006e0
> >>>  RDX: 0000000000000020 RSI: 0000000004208060 RDI: 0000000000215d80
> >>>  RBP: ffff88014f403f80 R08: 0000000b1b42c180 R09: 0000000000000022
> >>>  R10: 0000000000000004 R11: 00000000ffffffff R12: 000000000000a030
> >>>  R13: 0000000000000082 R14: ffff8800aa4d0080 R15: 0000000000000082
> >>>  FS:  0000000000000000(0000) GS:ffff88014f400000(0000) knlGS:0000000000000000
> >>>  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> >>>  CR2: 00007fa53b90c000 CR3: 0000000001a0a000 CR4: 00000000001406f0
> >>>  DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> >>>  DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> >>>  Stack:
> >>>   042080601b33869f ffff8800aae94000 00000000fffc2678 ffff88010000000a
> >>>   0000000000000000 000000000000a030 0000000000005302 ffff8800aa4d0080
> >>>   0000000000000206 ffff88014f403f90 ffffffff8104a716 ffff88014f403fa8
> >>>  Call Trace:
> >>>   <IRQ>
> >>>   [<ffffffff8104a716>] irq_exit+0x86/0x90
> >>>   [<ffffffff81031e7d>] smp_apic_timer_interrupt+0x3d/0x50
> >>>   [<ffffffff814f3eac>] apic_timer_interrupt+0x7c/0x90
> >>>   <EOI>
> >>>   [<ffffffffa01c5b40>] ? gen8_write64+0x1a0/0x1a0 [i915]
> >>>   [<ffffffff814f2b39>] ? _raw_spin_unlock_irqrestore+0x9/0x20
> >>>   [<ffffffffa01c5c44>] gen8_write32+0x104/0x1a0 [i915]
> >>>   [<ffffffff8132c6a2>] ? n_tty_receive_buf_common+0x372/0xae0
> >>>   [<ffffffffa017cc9e>] gen6_set_rps_thresholds+0x1be/0x330 [i915]
> >>>   [<ffffffffa017eaf0>] gen6_set_rps+0x70/0x200 [i915]
> >>>   [<ffffffffa0185375>] intel_set_rps+0x25/0x30 [i915]
> >>>   [<ffffffffa01768fd>] gen6_pm_rps_work+0x10d/0x2e0 [i915]
> >>>   [<ffffffff81063852>] ? finish_task_switch+0x72/0x1c0
> >>>   [<ffffffff8105ab29>] process_one_work+0x139/0x350
> >>>   [<ffffffff8105b186>] worker_thread+0x126/0x490
> >>>   [<ffffffff8105b060>] ? rescuer_thread+0x320/0x320
> >>>   [<ffffffff8105fa64>] kthread+0xc4/0xe0
> >>>   [<ffffffff8105f9a0>] ? kthread_create_on_node+0x170/0x170
> >>>   [<ffffffff814f351f>] ret_from_fork+0x3f/0x70
> >>>   [<ffffffff8105f9a0>] ? kthread_create_on_node+0x170/0x170
> >>>
> >>>I could not explain, or find a code path, which would explain
> >>>a +20 second lockup, but from some instrumentation it was
> >>>apparent the interrupts off proportion of time was between
> >>>10-25% under heavy load which is quite bad.
> >>>
> >>>By moving the GT interrupt handling to a tasklet in a most
> >>>simple way, the problem above disappears completely.
> >>>
> >>>Also, gem_latency -n 100 shows 25% better throughput and CPU
> >>>usage, and 14% better latencies.
> >
> >Forgot gem_syslatency, since that does reflect UX under load really
> >startlingly well.
> 
> gem_syslatency, before:
> 
> gem_syslatency: cycles=1532739, latency mean=416531.829us max=2499237us
> gem_syslatency: cycles=1839434, latency mean=1458099.157us max=4998944us
> gem_syslatency: cycles=1432570, latency mean=2688.451us max=1201185us
> gem_syslatency: cycles=1533543, latency mean=416520.499us max=2498886us
> 
> with tasklet:
> 
> gem_syslatency: cycles=808907, latency mean=53.133us max=1640us
> gem_syslatency: cycles=862154, latency mean=62.778us max=2117us
> gem_syslatency: cycles=856039, latency mean=58.079us max=2123us
> gem_syslatency: cycles=841683, latency mean=56.914us max=1667us
> 
> Is this smaller throughput and better latency?

Yeah. I wasn't expecting the smaller throughput, but the impact on other
users is massive. You should be able to feel the difference if you try
to use the machine whilst gem_syslatency or gem_exec_nop is running, a
delay of up to 2s in responding to human input can be annoying!

> gem_syslatency -n, before:
> 
> gem_syslatency: cycles=0, latency mean=2.446us max=18us
> gem_syslatency: cycles=0, latency mean=7.220us max=37us
> gem_syslatency: cycles=0, latency mean=6.949us max=36us
> gem_syslatency: cycles=0, latency mean=5.931us max=39us
> 
> with tasklet:
> 
> gem_syslatency: cycles=0, latency mean=2.477us max=5us
> gem_syslatency: cycles=0, latency mean=2.471us max=6us
> gem_syslatency: cycles=0, latency mean=2.696us max=24us
> gem_syslatency: cycles=0, latency mean=6.414us max=39us
> 
> This looks potentially the same or very similar. May need more runs
> to get a definitive picture.

-n should be unaffected, since it measures the background without gem
operations (cycles=0), so should tell us how stable the numbers are for
the timers.

> gem_exec_nop/all has a huge improvement also, if we ignore the fact
> it locks up the system with the curret irq handler on full tilt,
> when I limit the max GPU frequency a bit it can avoid that problem
> but tasklets make it twice as fast here.

Yes, with threaded submission can then concurrently submit requests to
multiple rings. I take it you have a 2-processor machine? We should
ideally see linear scaling upto min(num_engines, nproc-1) if we assume
that one cpu is enough to sustain gem_execbuf() ioctls.

> >>>I did not find any gains or regressions with Synmark2 or
> >>>GLbench under light testing. More benchmarking is certainly
> >>>required.
> >>>
> >
> >Bugzilla?
> 
> You think it is OK to continue sharing your one,
> https://bugs.freedesktop.org/show_bug.cgi?id=93467?

Yes, it fixes the same freeze (and we've removed the loop from chv irq
so there really shouldn't be any others left!)

> >>>Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin at intel.com>
> >>>Cc: Chris Wilson <chris at chris-wilson.co.uk>
> >>
> >>I thought tasklets are considered unpopular nowadays? They still steal cpu
> 
> Did not know, last (and first) time I've used them was ~15 years
> ago. :) You got any links to read about it? Since (see below) I am
> not sure they "steal" CPU time.
> 
> >>time, just have the benefit of not also disabling hard interrupts. There
> >>should be mitigation though to offload these softinterrupts to threads.
> >>Have you tried to create a threaded interrupt thread just for these pins
> >>instead? A bit of boilerplate, but not much using the genirq stuff iirc.
> >
> >Ah, you haven't been reading patches. Yes, there's been a patch to fix
> >the hardlockup using kthreads for a few months. Tvrtko is trying to move
> >this forward since he too has found a way of locking up his machine
> >using execlist under load.
> 
> Correct.
> 
> >So far kthreads seems to have a slight edge in the benchmarks, or rather
> >using tasklet I have some very wild results on Braswell. Using tasklets
> >the CPU time is accounted to the process (i.e. whoever was running at
> > the time of the irq, typically the benchmark), using kthread we have
> 
> I thought they run from ksoftirqd so the CPU time is accounted
> against it. And looking at top, that even seems what actually
> happens.

Not for me. :| Though I'm using simple CPU time accounting.

> >independent entries in the process table/top (which is quite nice to see
> >just how much time is been eaten up by the context-switches).
> >
> >Benchmarks still progessing, haven't yet got on to the latency
> >measureemnts....
> 
> My tasklets hack required surprisingly little code change, at least
> if there are not some missed corner cases to handle, but I don't
> mind your threads either.

Yes, though when moving to kthreads I dropped the requirement for
spin_lock_irq(engine->execlists_lock) and so there is a large amount of
fluff in changing those callsites to spin_lock(). (For tasklet, we could
argue that requirement is now changed to spin_lock_bh()...) The real meat
of the change is that with kthreads we have to worry about doing the
scheduling() ourselves, and that impacts upon the forcewake dance so
certainly more complex than tasklets! I liked how simple this patch is
and so far it looks as good as making our own kthread. The biggest
difference really is just who gets the CPU time!
-Chris

-- 
Chris Wilson, Intel Open Source Technology Centre