Re: [RFC] drm/i915: Move execlists irq handler to a bottom half

[Tvrtko Ursulin <tvrtko.ursulin@linux.intel.com>]

On 23/03/16 11:31, Chris Wilson wrote:
> 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@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!

Yes, impact is easily felt.

>> 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.

2C/4T correct.

>>>>> 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!)

I don't see that has been merged. Is it all ready CI wise so we could?

>>>>> Signed-off-by: Tvrtko Ursulin <tvrtko.ursulin@intel.com>
>>>>> Cc: Chris Wilson <chris@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.

I suppose it must be this one you don't have then:

config IRQ_TIME_ACCOUNTING
         bool "Fine granularity task level IRQ time accounting"
         depends on HAVE_IRQ_TIME_ACCOUNTING && !NO_HZ_FULL
         help
           Select this option to enable fine granularity task irq time
           accounting. This is done by reading a timestamp on each
           transitions between softirq and hardirq state, so there can
           be a small performance impact.

>>> 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

Ooops yes, _bh variant is the correct one. I wonder if that would 
further improve things. Will try.

> 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!

Note that in that respect it is then no worse than the current situation 
wrt CPU time accounting.

Regards,

Tvrtko
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx