* Re: [2.6.39-rc7] i915: kworker busily spinning...
2011-05-17 11:27 [2.6.39-rc7] i915: kworker busily spinning Daniel J Blueman
@ 2011-05-24 10:52 ` Daniel J Blueman
2011-05-24 11:02 ` Andy Lutomirski
1 sibling, 0 replies; 4+ messages in thread
From: Daniel J Blueman @ 2011-05-24 10:52 UTC (permalink / raw)
To: Chris Wilson, Keith Packard; +Cc: intel-gfx, dri-devel, Dave Airlie
On 17 May 2011 12:27, Daniel J Blueman <daniel.blueman@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 0x00000000
> 0000000000000002 ffff88021e804040 ffff88021e85f9b0 ffff88021e804040
> ffff88021e85e000 0000000000004000 ffff8802210a4040 ffff88021e804040
> 0000000000000046 ffffffff81c18b20 ffff88022106c000 ffffffff8270b740
> Call Trace:
> [<ffffffff8109a460>] ? mark_held_locks+0x70/0xa0
> [<ffffffff81059261>] ? get_parent_ip+0x11/0x50
> [<ffffffff8105933d>] ? sub_preempt_count+0x9d/0xd0
> [<ffffffff81705a35>] schedule_timeout+0x175/0x250
> [<ffffffff8106ec10>] ? run_timer_softirq+0x2a0/0x2a0
> [<ffffffff81705b29>] schedule_timeout_uninterruptible+0x19/0x20
> [<ffffffff8106f878>] msleep+0x18/0x20
> [<ffffffffa017c620>] gmbus_xfer+0x400/0x620 [i915]
> [<ffffffff8150c892>] i2c_transfer+0xa2/0xf0
> [<ffffffffa002bc96>] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
> [<ffffffffa002c0f9>] drm_get_edid+0x29/0x60 [drm]
> [<ffffffffa0176f86>] intel_hdmi_detect+0x56/0xe0 [i915]
> [<ffffffffa00d1177>] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
> [<ffffffff81078e14>] process_one_work+0x1a4/0x450
> [<ffffffff81078db6>] ? process_one_work+0x146/0x450
> [<ffffffffa00d10a0>] ?
> drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
> [<ffffffff810790ec>] process_scheduled_works+0x2c/0x40
> [<ffffffff8107c384>] worker_thread+0x284/0x350
> [<ffffffff8107c100>] ? manage_workers.clone.23+0x120/0x120
> [<ffffffff81080ea6>] kthread+0xb6/0xc0
> [<ffffffff8109a5cd>] ? trace_hardirqs_on_caller+0x13d/0x180
> [<ffffffff8170a494>] kernel_thread_helper+0x4/0x10
> [<ffffffff8104c64f>] ? finish_task_switch+0x6f/0x100
> [<ffffffff81708bc4>] ? retint_restore_args+0xe/0xe
> [<ffffffff81080df0>] ? __init_kthread_worker+0x70/0x70
> [<ffffffff8170a490>] ? 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: 0000
[ 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: 0000
[ 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=0xf40000, 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: 0000
[ 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: 0000
[ 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: 0000
[ 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=0xf40000, 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: 0000
[ 67.179566] [drm:output_poll_execute], [CONNECTOR:18:DP-1] status
updated from 2 to 2
[ 67.179976] [drm:i915_hotplug_work_func], running encoder hotplug functions
<73 lines the same>
[ 67.275136] [drm:i915_hotplug_work_func], running encoder hotplug functions
[ 67.275145] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[ 67.286602] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[ 67.287113] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.287115] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.287117] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[ 67.287629] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.287631] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.287633] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[ 67.287640] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf40000, result 0
[ 67.287643] [drm:intel_crt_detect], CRT not detected via hotplug
[ 67.287645] [drm:output_poll_execute], [CONNECTOR:12:VGA-1] status
updated from 2 to 2
[ 67.299144] [drm:output_poll_execute], [CONNECTOR:15:HDMI-A-1]
status updated from 2 to 2
[ 67.299657] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.299659] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.299660] [drm:output_poll_execute], [CONNECTOR:18:DP-1] status
updated from 2 to 2
[ 67.300809] [drm:i915_hotplug_work_func], running encoder hotplug functions
<78 lines the same>
[ 67.395164] [drm:i915_hotplug_work_func], running encoder hotplug functions
[ 67.395173] [drm:output_poll_execute], [CONNECTOR:22:HDMI-A-2]
status updated from 2 to 2
[ 67.406644] [drm:output_poll_execute], [CONNECTOR:25:HDMI-A-3]
status updated from 2 to 2
[ 67.407158] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.407160] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.407162] [drm:output_poll_execute], [CONNECTOR:27:DP-2] status
updated from 2 to 2
[ 67.407673] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.407675] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.407676] [drm:output_poll_execute], [CONNECTOR:30:DP-3] status
updated from 2 to 2
[ 67.407683] [drm:intel_ironlake_crt_detect_hotplug], ironlake
hotplug adpa=0xf40000, result 0
[ 67.407686] [drm:intel_crt_detect], CRT not detected via hotplug
[ 67.407688] [drm:output_poll_execute], [CONNECTOR:12:VGA-1] status
updated from 2 to 2
[ 67.419136] [drm:output_poll_execute], [CONNECTOR:15:HDMI-A-1]
status updated from 2 to 2
[ 67.419648] [drm:intel_dp_aux_ch], dp_aux_ch timeout status 0x5143003e
[ 67.419650] [drm:ironlake_dp_detect], DPCD: 0000
[ 67.419651] [drm:output_poll_execute], [CONNECTOR:18:DP-1] status
updated from 2 to 2
[ 67.420569] [drm:i915_hotplug_work_func], running encoder hotplug functions
--
Daniel J Blueman
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [2.6.39-rc7] i915: kworker busily spinning...
2011-05-17 11:27 [2.6.39-rc7] i915: kworker busily spinning Daniel J Blueman
2011-05-24 10:52 ` Daniel J Blueman
@ 2011-05-24 11:02 ` Andy Lutomirski
2011-05-24 11:25 ` Daniel J Blueman
1 sibling, 1 reply; 4+ messages in thread
From: Andy Lutomirski @ 2011-05-24 11:02 UTC (permalink / raw)
To: Daniel J Blueman; +Cc: Dave Airlie, intel-gfx, dri-devel
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 <luto@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 <luto@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 {
/* output poll support */
bool poll_enabled;
struct delayed_slow_work output_poll_slow_work;
+ bool hpd_detected;
/* pointers to standard properties */
struct list_head property_blob_list;
--Andy
>
> Thanks,
> Daniel
>
> --- [1]
>
> kworker/2:2 R running task 5048 86 2 0x00000000
> 0000000000000002 ffff88021e804040 ffff88021e85f9b0 ffff88021e804040
> ffff88021e85e000 0000000000004000 ffff8802210a4040 ffff88021e804040
> 0000000000000046 ffffffff81c18b20 ffff88022106c000 ffffffff8270b740
> Call Trace:
> [<ffffffff8109a460>] ? mark_held_locks+0x70/0xa0
> [<ffffffff81059261>] ? get_parent_ip+0x11/0x50
> [<ffffffff8105933d>] ? sub_preempt_count+0x9d/0xd0
> [<ffffffff81705a35>] schedule_timeout+0x175/0x250
> [<ffffffff8106ec10>] ? run_timer_softirq+0x2a0/0x2a0
> [<ffffffff81705b29>] schedule_timeout_uninterruptible+0x19/0x20
> [<ffffffff8106f878>] msleep+0x18/0x20
> [<ffffffffa017c620>] gmbus_xfer+0x400/0x620 [i915]
> [<ffffffff8150c892>] i2c_transfer+0xa2/0xf0
> [<ffffffffa002bc96>] drm_do_probe_ddc_edid+0x66/0xa0 [drm]
> [<ffffffffa002c0f9>] drm_get_edid+0x29/0x60 [drm]
> [<ffffffffa0176f86>] intel_hdmi_detect+0x56/0xe0 [i915]
> [<ffffffffa00d1177>] output_poll_execute+0xd7/0x1a0 [drm_kms_helper]
> [<ffffffff81078e14>] process_one_work+0x1a4/0x450
> [<ffffffff81078db6>] ? process_one_work+0x146/0x450
> [<ffffffffa00d10a0>] ?
> drm_helper_disable_unused_functions+0x150/0x150 [drm_kms_helper]
> [<ffffffff810790ec>] process_scheduled_works+0x2c/0x40
> [<ffffffff8107c384>] worker_thread+0x284/0x350
> [<ffffffff8107c100>] ? manage_workers.clone.23+0x120/0x120
> [<ffffffff81080ea6>] kthread+0xb6/0xc0
> [<ffffffff8109a5cd>] ? trace_hardirqs_on_caller+0x13d/0x180
> [<ffffffff8170a494>] kernel_thread_helper+0x4/0x10
> [<ffffffff8104c64f>] ? finish_task_switch+0x6f/0x100
> [<ffffffff81708bc4>] ? retint_restore_args+0xe/0xe
> [<ffffffff81080df0>] ? __init_kthread_worker+0x70/0x70
> [<ffffffff8170a490>] ? gs_change+0xb/0xb
^ permalink raw reply related [flat|nested] 4+ messages in thread