[2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Daniel J Blueman
On 24 May 2011 12:02, Andy Lutomirski  wrote:
> On 05/17/2011 07:27 AM, Daniel J Blueman wrote:
>> With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
>> sometimes I find one of the kworker threads busily running with 15-20%
>> system time for some minutes, causing terrible interactivity latency.
>> I've seen it occur when plugging eg a HDMI display, and also when no
>> display has been plugged (ie only the internal LVDS connection is
>> active).
>>
>> Across multiple kernel task captures, I see the kernel thread
>> consistently reading one of the connector's EDID data [1]; I guess
>> either it's having a hard time reading from a disconnected connector
>> and retrying, or is incorrectly detecting a change when there is none.
>>
>> I'll enable DRM debugging to see what connectors it believes it needs
>> to read from. Anything else that would be handy to capture, or any
>> thoughts?
>>
>> Also, the 100ms connector change polling seems overkill, particularly
>> when power consumption is important; 1000-2000ms would be sufficient,
>> do you think?
>
> I think it's meant to be every 10 seconds.
>
> In any case, the output_poll_execute code does more work than necessary,
> which might exacerbate the problem. ?Here's an old patch I wrote that
> probably doesn't apply any more but might help.

Thanks for the patch Andy; I'll test it after we've found a fix for
the underlying issue.

Daniel
-- 
Daniel J Blueman


[2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Daniel J Blueman
On 17 May 2011 12:27, Daniel J Blueman  wrote:
> With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
> sometimes I find one of the kworker threads busily running with 15-20%
> system time for some minutes, causing terrible interactivity latency.
> I've seen it occur when plugging eg a HDMI display, and also when no
> display has been plugged (ie only the internal LVDS connection is
> active).
>
> Across multiple kernel task captures, I see the kernel thread
> consistently reading one of the connector's EDID data [1]; I guess
> either it's having a hard time reading from a disconnected connector
> and retrying, or is incorrectly detecting a change when there is none.
>
> I'll enable DRM debugging to see what connectors it believes it needs
> to read from. Anything else that would be handy to capture, or any
> thoughts?
>
> Also, the 100ms connector change polling seems overkill, particularly
> when power consumption is important; 1000-2000ms would be sufficient,
> do you think?
>
> Thanks,
> ?Daniel
>
> --- [1]
>
> kworker/2:2 ? ? R ?running task ? ? 5048 ? ?86 ? ? ?2 0x
> ?0002 88021e804040 88021e85f9b0 88021e804040
> ?88021e85e000 4000 8802210a4040 88021e804040
> ?0046 81c18b20 88022106c000 8270b740
> Call Trace:
> ?[] ? mark_held_locks+0x70/0xa0
> ?[] ? get_parent_ip+0x11/0x50
> ?[] ? sub_preempt_count+0x9d/0xd0
> ?[] schedule_timeout+0x175/0x250
> ?[] ? run_timer_softirq+0x2a0/0x2a0
> ?[] schedule_timeout_uninterruptible+0x19/0x20
> ?[] msleep+0x18/0x20
> ?[] gmbus_xfer+0x400/0x620 [i915]
> ?[] i2c_transfer+0xa2/0xf0
> ?[] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
> ?[] drm_get_edid+0x29/0x60 [drm]
> ?[] intel_hdmi_detect+0x56/0xe0 [i915]
> ?[] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
> ?[] process_one_work+0x1a4/0x450
> ?[] ? process_one_work+0x146/0x450
> ?[] ?
> drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
> ?[] process_scheduled_works+0x2c/0x40
> ?[] worker_thread+0x284/0x350
> ?[] ? manage_workers.clone.23+0x120/0x120
> ?[] kthread+0xb6/0xc0
> ?[] ? trace_hardirqs_on_caller+0x13d/0x180
> ?[] kernel_thread_helper+0x4/0x10
> ?[] ? finish_task_switch+0x6f/0x100
> ?[] ? retint_restore_args+0xe/0xe
> ?[] ? __init_kthread_worker+0x70/0x70
> ?[] ? gs_change+0xb/0xb

Interestingly, I appear to observe this behaviour when the laptop
battery is charging. Anyway, we see continual connector update events
[1], booted drm.debug=0x4. This reproduces with 2.6.39.

Any thoughts?

Daniel

--- [1]

[   67.035097] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[   67.046549] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[   67.047063] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.047065] [drm:ironlake_dp_detect], DPCD: 
[   67.047066] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[   67.047578] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.047579] [drm:ironlake_dp_detect], DPCD: 
[   67.047581] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[   67.047588] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf4, result 0
[   67.047591] [drm:intel_crt_detect], CRT not detected via hotplug
[   67.047593] [drm:output_poll_execute], [CONNECTOR:12:VGA-1] status
updated from 2 to 2
[   67.059062] [drm:output_poll_execute], [CONNECTOR:15:HDMI-A-1]
status updated from 2 to 2
[   67.059573] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.059575] [drm:ironlake_dp_detect], DPCD: 
[   67.059576] [drm:output_poll_execute], [CONNECTOR:18:DP-1] status
updated from 2 to 2
[   67.059886] [drm:i915_hotplug_work_func], running encoder hotplug functions
<85 lines the same>
[   67.153172] [drm:i915_hotplug_work_func], running encoder hotplug functions
[   67.155109] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[   67.166569] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[   67.167082] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.167084] [drm:ironlake_dp_detect], DPCD: 
[   67.167086] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[   67.167598] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.167600] [drm:ironlake_dp_detect], DPCD: 
[   67.167601] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[   67.167608] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf4, result 0
[   67.167610] [drm:intel_crt_detect], CRT not detected via hotplug
[   67.167612] [drm:output_poll_execute], [CONNECTOR:12:VGA-1] status
updated from 2 to 2
[   67.179051] [drm:output_poll_execute], [CONNECTOR:15:HDMI-A-1]
status updated from 2 to 2
[   67.179563] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.179564] [drm:ironlake_dp_detect], DPCD: 

[2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Andy Lutomirski
On 05/17/2011 07:27 AM, Daniel J Blueman wrote:
> With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
> sometimes I find one of the kworker threads busily running with 15-20%
> system time for some minutes, causing terrible interactivity latency.
> I've seen it occur when plugging eg a HDMI display, and also when no
> display has been plugged (ie only the internal LVDS connection is
> active).
> 
> Across multiple kernel task captures, I see the kernel thread
> consistently reading one of the connector's EDID data [1]; I guess
> either it's having a hard time reading from a disconnected connector
> and retrying, or is incorrectly detecting a change when there is none.
> 
> I'll enable DRM debugging to see what connectors it believes it needs
> to read from. Anything else that would be handy to capture, or any
> thoughts?
> 
> Also, the 100ms connector change polling seems overkill, particularly
> when power consumption is important; 1000-2000ms would be sufficient,
> do you think?

I think it's meant to be every 10 seconds.

In any case, the output_poll_execute code does more work than necessary,
which might exacerbate the problem.  Here's an old patch I wrote that
probably doesn't apply any more but might help.

commit 82c9114cdc60aba7d9bec1396d818362a208cfdc
Author: Andy Lutomirski 
Date:   Tue Aug 17 09:38:59 2010 -0400

drm: Try to poll fewer unnecessary outputs

We used to poll all outputs that had any kind of polling enabled every time
that the output polling work ran (i.e. every ten seconds).  Now only poll
hotplug-interrupt capable outputs when hotplug is detected and we only
poll POLL_CONNECT and POLL_DISCONNECT when in the appropriate state.

Signed-off-by: Andy Lutomirski 

diff --git a/drivers/gpu/drm/drm_crtc_helper.c 
b/drivers/gpu/drm/drm_crtc_helper.c
index 9b2a541..5a39e3c 100644
--- a/drivers/gpu/drm/drm_crtc_helper.c
+++ b/drivers/gpu/drm/drm_crtc_helper.c
@@ -817,31 +817,38 @@ static void output_poll_execute(struct slow_work *work)
struct drm_device *dev = container_of(delayed_work, struct drm_device, 
mode_config.output_poll_slow_work);
struct drm_connector *connector;
enum drm_connector_status old_status, status;
-   bool repoll = false, changed = false;
+   bool repoll = false, changed = false, need_poll, hpd_detected;
int ret;

+   hpd_detected = ACCESS_ONCE(dev->mode_config.hpd_detected);
+   ACCESS_ONCE(dev->mode_config.hpd_detected) = 0;
+
mutex_lock(>mode_config.mutex);
list_for_each_entry(connector, >mode_config.connector_list, head) {

-   /* if this is HPD or polled don't check it -
-  TV out for instance */
+   /* don't poll unless the drivers asked us to. */
if (!connector->polled)
continue;

-   else if (connector->polled & (DRM_CONNECTOR_POLL_CONNECT | 
DRM_CONNECTOR_POLL_DISCONNECT))
-   repoll = true;
+   /* poll if we got an HPD request... */
+   need_poll = hpd_detected;

+   /* ...or if we're supposed to poll all the time */
old_status = connector->status;
-   /* if we are connected and don't want to poll for disconnect
-  skip it */
-   if (old_status == connector_status_connected &&
-   !(connector->polled & DRM_CONNECTOR_POLL_DISCONNECT) &&
-   !(connector->polled & DRM_CONNECTOR_POLL_HPD))
-   continue;
+   if (old_status == connector_status_connected ?
+   (connector->polled & DRM_CONNECTOR_POLL_CONNECT) :
+   (connector->polled & DRM_CONNECTOR_POLL_DISCONNECT))
+   need_poll = true;

-   status = connector->funcs->detect(connector);
-   if (old_status != status)
-   changed = true;
+   /* Do we re-queue? */
+   if (connector->polled & (DRM_CONNECTOR_POLL_CONNECT | 
DRM_CONNECTOR_POLL_DISCONNECT))
+   repoll = true;
+
+   if (need_poll) {
+   status = connector->funcs->detect(connector);
+   if (old_status != status)
+   changed = true;
+   }
}

mutex_unlock(>mode_config.mutex);
@@ -911,6 +918,7 @@ void drm_helper_hpd_irq_event(struct drm_device *dev)
return;
delayed_slow_work_cancel(>mode_config.output_poll_slow_work);
/* schedule a slow work asap */
+   ACCESS_ONCE(dev->mode_config.hpd_detected) = true;
delayed_slow_work_enqueue(>mode_config.output_poll_slow_work, 0);
 }
 EXPORT_SYMBOL(drm_helper_hpd_irq_event);
diff --git a/include/drm/drm_crtc.h b/include/drm/drm_crtc.h
index 93a1a31..586f41f 100644
--- a/include/drm/drm_crtc.h
+++ b/include/drm/drm_crtc.h
@@ -596,6 +596,7 @@ struct drm_mode_config {

Re: [2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Daniel J Blueman
On 17 May 2011 12:27, Daniel J Blueman daniel.blue...@gmail.com wrote:
 With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
 sometimes I find one of the kworker threads busily running with 15-20%
 system time for some minutes, causing terrible interactivity latency.
 I've seen it occur when plugging eg a HDMI display, and also when no
 display has been plugged (ie only the internal LVDS connection is
 active).

 Across multiple kernel task captures, I see the kernel thread
 consistently reading one of the connector's EDID data [1]; I guess
 either it's having a hard time reading from a disconnected connector
 and retrying, or is incorrectly detecting a change when there is none.

 I'll enable DRM debugging to see what connectors it believes it needs
 to read from. Anything else that would be handy to capture, or any
 thoughts?

 Also, the 100ms connector change polling seems overkill, particularly
 when power consumption is important; 1000-2000ms would be sufficient,
 do you think?

 Thanks,
  Daniel

 --- [1]

 kworker/2:2     R  running task     5048    86      2 0x
  0002 88021e804040 88021e85f9b0 88021e804040
  88021e85e000 4000 8802210a4040 88021e804040
  0046 81c18b20 88022106c000 8270b740
 Call Trace:
  [8109a460] ? mark_held_locks+0x70/0xa0
  [81059261] ? get_parent_ip+0x11/0x50
  [8105933d] ? sub_preempt_count+0x9d/0xd0
  [81705a35] schedule_timeout+0x175/0x250
  [8106ec10] ? run_timer_softirq+0x2a0/0x2a0
  [81705b29] schedule_timeout_uninterruptible+0x19/0x20
  [8106f878] msleep+0x18/0x20
  [a017c620] gmbus_xfer+0x400/0x620 [i915]
  [8150c892] i2c_transfer+0xa2/0xf0
  [a002bc96] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
  [a002c0f9] drm_get_edid+0x29/0x60 [drm]
  [a0176f86] intel_hdmi_detect+0x56/0xe0 [i915]
  [a00d1177] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
  [81078e14] process_one_work+0x1a4/0x450
  [81078db6] ? process_one_work+0x146/0x450
  [a00d10a0] ?
 drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
  [810790ec] process_scheduled_works+0x2c/0x40
  [8107c384] worker_thread+0x284/0x350
  [8107c100] ? manage_workers.clone.23+0x120/0x120
  [81080ea6] kthread+0xb6/0xc0
  [8109a5cd] ? trace_hardirqs_on_caller+0x13d/0x180
  [8170a494] kernel_thread_helper+0x4/0x10
  [8104c64f] ? finish_task_switch+0x6f/0x100
  [81708bc4] ? retint_restore_args+0xe/0xe
  [81080df0] ? __init_kthread_worker+0x70/0x70
  [8170a490] ? gs_change+0xb/0xb

Interestingly, I appear to observe this behaviour when the laptop
battery is charging. Anyway, we see continual connector update events
[1], booted drm.debug=0x4. This reproduces with 2.6.39.

Any thoughts?

Daniel

--- [1]

[   67.035097] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[   67.046549] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[   67.047063] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.047065] [drm:ironlake_dp_detect], DPCD: 
[   67.047066] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[   67.047578] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.047579] [drm:ironlake_dp_detect], DPCD: 
[   67.047581] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[   67.047588] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf4, result 0
[   67.047591] [drm:intel_crt_detect], CRT not detected via hotplug
[   67.047593] [drm:output_poll_execute], [CONNECTOR:12:VGA-1] status
updated from 2 to 2
[   67.059062] [drm:output_poll_execute], [CONNECTOR:15:HDMI-A-1]
status updated from 2 to 2
[   67.059573] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.059575] [drm:ironlake_dp_detect], DPCD: 
[   67.059576] [drm:output_poll_execute], [CONNECTOR:18:DP-1] status
updated from 2 to 2
[   67.059886] [drm:i915_hotplug_work_func], running encoder hotplug functions
85 lines the same
[   67.153172] [drm:i915_hotplug_work_func], running encoder hotplug functions
[   67.155109] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[   67.166569] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[   67.167082] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.167084] [drm:ironlake_dp_detect], DPCD: 
[   67.167086] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[   67.167598] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[   67.167600] [drm:ironlake_dp_detect], DPCD: 
[   67.167601] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[   67.167608] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf4, 

Re: [2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Andy Lutomirski
On 05/17/2011 07:27 AM, Daniel J Blueman wrote:
 With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
 sometimes I find one of the kworker threads busily running with 15-20%
 system time for some minutes, causing terrible interactivity latency.
 I've seen it occur when plugging eg a HDMI display, and also when no
 display has been plugged (ie only the internal LVDS connection is
 active).
 
 Across multiple kernel task captures, I see the kernel thread
 consistently reading one of the connector's EDID data [1]; I guess
 either it's having a hard time reading from a disconnected connector
 and retrying, or is incorrectly detecting a change when there is none.
 
 I'll enable DRM debugging to see what connectors it believes it needs
 to read from. Anything else that would be handy to capture, or any
 thoughts?
 
 Also, the 100ms connector change polling seems overkill, particularly
 when power consumption is important; 1000-2000ms would be sufficient,
 do you think?

I think it's meant to be every 10 seconds.

In any case, the output_poll_execute code does more work than necessary,
which might exacerbate the problem.  Here's an old patch I wrote that
probably doesn't apply any more but might help.

commit 82c9114cdc60aba7d9bec1396d818362a208cfdc
Author: Andy Lutomirski l...@mit.edu
Date:   Tue Aug 17 09:38:59 2010 -0400

drm: Try to poll fewer unnecessary outputs

We used to poll all outputs that had any kind of polling enabled every time
that the output polling work ran (i.e. every ten seconds).  Now only poll
hotplug-interrupt capable outputs when hotplug is detected and we only
poll POLL_CONNECT and POLL_DISCONNECT when in the appropriate state.

Signed-off-by: Andy Lutomirski l...@mit.edu

diff --git a/drivers/gpu/drm/drm_crtc_helper.c 
b/drivers/gpu/drm/drm_crtc_helper.c
index 9b2a541..5a39e3c 100644
--- a/drivers/gpu/drm/drm_crtc_helper.c
+++ b/drivers/gpu/drm/drm_crtc_helper.c
@@ -817,31 +817,38 @@ static void output_poll_execute(struct slow_work *work)
struct drm_device *dev = container_of(delayed_work, struct drm_device, 
mode_config.output_poll_slow_work);
struct drm_connector *connector;
enum drm_connector_status old_status, status;
-   bool repoll = false, changed = false;
+   bool repoll = false, changed = false, need_poll, hpd_detected;
int ret;
 
+   hpd_detected = ACCESS_ONCE(dev-mode_config.hpd_detected);
+   ACCESS_ONCE(dev-mode_config.hpd_detected) = 0;
+
mutex_lock(dev-mode_config.mutex);
list_for_each_entry(connector, dev-mode_config.connector_list, head) {
 
-   /* if this is HPD or polled don't check it -
-  TV out for instance */
+   /* don't poll unless the drivers asked us to. */
if (!connector-polled)
continue;
 
-   else if (connector-polled  (DRM_CONNECTOR_POLL_CONNECT | 
DRM_CONNECTOR_POLL_DISCONNECT))
-   repoll = true;
+   /* poll if we got an HPD request... */
+   need_poll = hpd_detected;
 
+   /* ...or if we're supposed to poll all the time */
old_status = connector-status;
-   /* if we are connected and don't want to poll for disconnect
-  skip it */
-   if (old_status == connector_status_connected 
-   !(connector-polled  DRM_CONNECTOR_POLL_DISCONNECT) 
-   !(connector-polled  DRM_CONNECTOR_POLL_HPD))
-   continue;
+   if (old_status == connector_status_connected ?
+   (connector-polled  DRM_CONNECTOR_POLL_CONNECT) :
+   (connector-polled  DRM_CONNECTOR_POLL_DISCONNECT))
+   need_poll = true;
 
-   status = connector-funcs-detect(connector);
-   if (old_status != status)
-   changed = true;
+   /* Do we re-queue? */
+   if (connector-polled  (DRM_CONNECTOR_POLL_CONNECT | 
DRM_CONNECTOR_POLL_DISCONNECT))
+   repoll = true;
+
+   if (need_poll) {
+   status = connector-funcs-detect(connector);
+   if (old_status != status)
+   changed = true;
+   }
}
 
mutex_unlock(dev-mode_config.mutex);
@@ -911,6 +918,7 @@ void drm_helper_hpd_irq_event(struct drm_device *dev)
return;
delayed_slow_work_cancel(dev-mode_config.output_poll_slow_work);
/* schedule a slow work asap */
+   ACCESS_ONCE(dev-mode_config.hpd_detected) = true;
delayed_slow_work_enqueue(dev-mode_config.output_poll_slow_work, 0);
 }
 EXPORT_SYMBOL(drm_helper_hpd_irq_event);
diff --git a/include/drm/drm_crtc.h b/include/drm/drm_crtc.h
index 93a1a31..586f41f 100644
--- a/include/drm/drm_crtc.h
+++ b/include/drm/drm_crtc.h
@@ -596,6 +596,7 @@ struct drm_mode_config {

Re: [2.6.39-rc7] i915: kworker busily spinning...

2011-05-24 Thread Daniel J Blueman
On 24 May 2011 12:02, Andy Lutomirski l...@mit.edu wrote:
 On 05/17/2011 07:27 AM, Daniel J Blueman wrote:
 With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
 sometimes I find one of the kworker threads busily running with 15-20%
 system time for some minutes, causing terrible interactivity latency.
 I've seen it occur when plugging eg a HDMI display, and also when no
 display has been plugged (ie only the internal LVDS connection is
 active).

 Across multiple kernel task captures, I see the kernel thread
 consistently reading one of the connector's EDID data [1]; I guess
 either it's having a hard time reading from a disconnected connector
 and retrying, or is incorrectly detecting a change when there is none.

 I'll enable DRM debugging to see what connectors it believes it needs
 to read from. Anything else that would be handy to capture, or any
 thoughts?

 Also, the 100ms connector change polling seems overkill, particularly
 when power consumption is important; 1000-2000ms would be sufficient,
 do you think?

 I think it's meant to be every 10 seconds.

 In any case, the output_poll_execute code does more work than necessary,
 which might exacerbate the problem.  Here's an old patch I wrote that
 probably doesn't apply any more but might help.

Thanks for the patch Andy; I'll test it after we've found a fix for
the underlying issue.

Daniel
-- 
Daniel J Blueman
___
dri-devel mailing list
dri-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/dri-devel


[2.6.39-rc7] i915: kworker busily spinning...

2011-05-17 Thread Daniel J Blueman
With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
sometimes I find one of the kworker threads busily running with 15-20%
system time for some minutes, causing terrible interactivity latency.
I've seen it occur when plugging eg a HDMI display, and also when no
display has been plugged (ie only the internal LVDS connection is
active).

Across multiple kernel task captures, I see the kernel thread
consistently reading one of the connector's EDID data [1]; I guess
either it's having a hard time reading from a disconnected connector
and retrying, or is incorrectly detecting a change when there is none.

I'll enable DRM debugging to see what connectors it believes it needs
to read from. Anything else that would be handy to capture, or any
thoughts?

Also, the 100ms connector change polling seems overkill, particularly
when power consumption is important; 1000-2000ms would be sufficient,
do you think?

Thanks,
  Daniel

--- [1]

kworker/2:2 R  running task 504886  2 0x
 0002 88021e804040 88021e85f9b0 88021e804040
 88021e85e000 4000 8802210a4040 88021e804040
 0046 81c18b20 88022106c000 8270b740
Call Trace:
 [] ? mark_held_locks+0x70/0xa0
 [] ? get_parent_ip+0x11/0x50
 [] ? sub_preempt_count+0x9d/0xd0
 [] schedule_timeout+0x175/0x250
 [] ? run_timer_softirq+0x2a0/0x2a0
 [] schedule_timeout_uninterruptible+0x19/0x20
 [] msleep+0x18/0x20
 [] gmbus_xfer+0x400/0x620 [i915]
 [] i2c_transfer+0xa2/0xf0
 [] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
 [] drm_get_edid+0x29/0x60 [drm]
 [] intel_hdmi_detect+0x56/0xe0 [i915]
 [] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
 [] process_one_work+0x1a4/0x450
 [] ? process_one_work+0x146/0x450
 [] ?
drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
 [] process_scheduled_works+0x2c/0x40
 [] worker_thread+0x284/0x350
 [] ? manage_workers.clone.23+0x120/0x120
 [] kthread+0xb6/0xc0
 [] ? trace_hardirqs_on_caller+0x13d/0x180
 [] kernel_thread_helper+0x4/0x10
 [] ? finish_task_switch+0x6f/0x100
 [] ? retint_restore_args+0xe/0xe
 [] ? __init_kthread_worker+0x70/0x70
 [] ? gs_change+0xb/0xb
-- 
Daniel J Blueman


[2.6.39-rc7] i915: kworker busily spinning...

2011-05-17 Thread Daniel J Blueman
With 2.6.39-rc7 on my Sandy Bridge laptop GPU (8086:0126 rev 9),
sometimes I find one of the kworker threads busily running with 15-20%
system time for some minutes, causing terrible interactivity latency.
I've seen it occur when plugging eg a HDMI display, and also when no
display has been plugged (ie only the internal LVDS connection is
active).

Across multiple kernel task captures, I see the kernel thread
consistently reading one of the connector's EDID data [1]; I guess
either it's having a hard time reading from a disconnected connector
and retrying, or is incorrectly detecting a change when there is none.

I'll enable DRM debugging to see what connectors it believes it needs
to read from. Anything else that would be handy to capture, or any
thoughts?

Also, the 100ms connector change polling seems overkill, particularly
when power consumption is important; 1000-2000ms would be sufficient,
do you think?

Thanks,
  Daniel

--- [1]

kworker/2:2 R  running task 504886  2 0x
 0002 88021e804040 88021e85f9b0 88021e804040
 88021e85e000 4000 8802210a4040 88021e804040
 0046 81c18b20 88022106c000 8270b740
Call Trace:
 [8109a460] ? mark_held_locks+0x70/0xa0
 [81059261] ? get_parent_ip+0x11/0x50
 [8105933d] ? sub_preempt_count+0x9d/0xd0
 [81705a35] schedule_timeout+0x175/0x250
 [8106ec10] ? run_timer_softirq+0x2a0/0x2a0
 [81705b29] schedule_timeout_uninterruptible+0x19/0x20
 [8106f878] msleep+0x18/0x20
 [a017c620] gmbus_xfer+0x400/0x620 [i915]
 [8150c892] i2c_transfer+0xa2/0xf0
 [a002bc96] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
 [a002c0f9] drm_get_edid+0x29/0x60 [drm]
 [a0176f86] intel_hdmi_detect+0x56/0xe0 [i915]
 [a00d1177] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
 [81078e14] process_one_work+0x1a4/0x450
 [81078db6] ? process_one_work+0x146/0x450
 [a00d10a0] ?
drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
 [810790ec] process_scheduled_works+0x2c/0x40
 [8107c384] worker_thread+0x284/0x350
 [8107c100] ? manage_workers.clone.23+0x120/0x120
 [81080ea6] kthread+0xb6/0xc0
 [8109a5cd] ? trace_hardirqs_on_caller+0x13d/0x180
 [8170a494] kernel_thread_helper+0x4/0x10
 [8104c64f] ? finish_task_switch+0x6f/0x100
 [81708bc4] ? retint_restore_args+0xe/0xe
 [81080df0] ? __init_kthread_worker+0x70/0x70
 [8170a490] ? gs_change+0xb/0xb
-- 
Daniel J Blueman
___
dri-devel mailing list
dri-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/dri-devel