[Intel-gfx] [PATCH 1/3] drm/i915: Limit C-states when waiting for the active request

[Chris Wilson]

Quoting Tvrtko Ursulin (2018-08-03 14:00:33)
> In the meantime I have exercised this via media-bench and it did seems 
> there are gains for a few workloads (and almost no reliable 
> regressions). But when ran under tracing the gains disappeared which 
> makes me think either the 2s workload duration I selected is too short 
> to give reliable numbers, or tracing brings a similar benefit wo/ PM QoS 
> patch. Only conclusion is that more thorough testing is needed.

Hmm, right tracing really does a number on cpufreq.

Switched to 

+       if (IS_ENABLED(CONFIG_DRM_I915_TRACE_IRQ_LATENCY)) {
+               struct drm_i915_private *dev_priv = rq->i915;
+               u32 now = I915_READ(RING_TIMESTAMP(rq->engine->mmio_base));
+
+               trace_i915_wait_irq_latency(rq,
+                                           now - intel_engine_get_timestamp(rq->engine),
+                                           rq->global_seqno == intel_engine_get_seqno(rq->engine));
+       }
+

from a plain pr_err() and the latency effect just vanished. That makes
it tricky.

        gem_sync   324 [002]   100.695373: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6882, prio=6882, delay=231
        gem_sync   324 [002]   100.695536: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6883, prio=6883, delay=219
        gem_sync   324 [002]   100.695697: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6884, prio=6884, delay=215
        gem_sync   324 [002]   100.695860: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6885, prio=6885, delay=231
        gem_sync   324 [002]   100.696040: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6886, prio=6886, delay=313
        gem_sync   324 [002]   100.696203: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6887, prio=6887, delay=218
        gem_sync   324 [002]   100.696366: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6888, prio=6888, delay=216
        gem_sync   324 [002]   100.696527: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6889, prio=6889, delay=214
        gem_sync   324 [002]   100.696689: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6890, prio=6890, delay=218
        gem_sync   324 [002]   100.696851: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6891, prio=6891, delay=215
        gem_sync   324 [002]   100.697013: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6892, prio=6892, delay=214
        gem_sync   324 [002]   100.697175: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6893, prio=6893, delay=216
        gem_sync   324 [002]   100.697336: i915:i915_wait_irq_latency: dev=0, engine=0:0, hw_id=2, ctx=20, seqno=6894, prio=6894, delay=217

from

[   14.232750] Wake up latency: 4004 cycles
[   14.233779] Wake up latency: 3236 cycles
[   14.234831] Wake up latency: 3580 cycles
[   14.235864] Wake up latency: 3220 cycles
[   14.236865] Wake up latency: 2653 cycles
[   14.237893] Wake up latency: 3209 cycles
[   14.238941] Wake up latency: 3492 cycles
[   14.239975] Wake up latency: 3227 cycles
[   14.240943] Wake up latency: 2019 cycles
[   14.241971] Wake up latency: 3199 cycles
[   14.243019] Wake up latency: 3500 cycles
[   14.244051] Wake up latency: 3198 cycles
[   14.245073] Wake up latency: 3014 cycles
[   14.246108] Wake up latency: 3238 cycles
[   14.247158] Wake up latency: 3539 cycles
[   14.248188] Wake up latency: 3200 cycles

-Chris