Hello,
today I run at the latest 2.6.35.6 kernel few apps like Lotus Notes under wine, amarok and firefox and in parallel a "git bisect" when I got this :
n22 ~ # grep 2010-09-29T11:21 /var/log/messages | grep kernel 2010-09-29T11:21:36.984+02:00 n22 kernel: INFO: task i915:868 blocked for more than 120 seconds. 2010-09-29T11:21:36.984+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-09-29T11:21:36.984+02:00 n22 kernel: i915 D ffa47280 0 868 2 0x00000000 2010-09-29T11:21:36.984+02:00 n22 kernel: f5d0ff1c 00000046 000112be ffa47280 f53f0064 0ec0c353 00000532 f723b804 2010-09-29T11:21:36.984+02:00 n22 kernel: c2406b40 0000118d 00000000 c13b7b00 0ec0b1c6 00000532 c13b1000 c13b1000 2010-09-29T11:21:36.984+02:00 n22 kernel: c13b7b00 c13b7b00 f6384030 f6384030 f5d0ff6c c123c6f1 1ddceea9 0000164f 2010-09-29T11:21:36.984+02:00 n22 kernel: Call Trace: 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c123c6f1>] ? schedule+0x211/0x780 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c123d5c0>] __mutex_lock_slowpath+0xd0/0x130 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c123d980>] mutex_lock+0x20/0x40 2010-09-29T11:21:36.984+02:00 n22 kernel: [<f8a88508>] i915_gem_retire_work_handler+0x28/0xc0 [i915] 2010-09-29T11:21:36.984+02:00 n22 kernel: [<f8a884e0>] ? i915_gem_retire_work_handler+0x0/0xc0 [i915] 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c10441af>] worker_thread+0xef/0x1b0 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c102e6ab>] ? default_wake_function+0xb/0x10 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c1047bd0>] ? autoremove_wake_function+0x0/0x40 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c10440c0>] ? worker_thread+0x0/0x1b0 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c1047864>] kthread+0x74/0x80 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c10477f0>] ? kthread+0x0/0x80 2010-09-29T11:21:36.984+02:00 n22 kernel: [<c10032be>] kernel_thread_helper+0x6/0x18 2010-09-29T11:21:36.984+02:00 n22 kernel: INFO: task X:12082 blocked for more than 120 seconds. 2010-09-29T11:21:36.985+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-09-29T11:21:36.985+02:00 n22 kernel: X D c11cf5a4 0 12082 12029 0x00400004 2010-09-29T11:21:36.985+02:00 n22 kernel: f5fc7dd0 00203082 f5fc7db0 c11cf5a4 ffffffff f2e0157c 00000531 00000000 2010-09-29T11:21:36.985+02:00 n22 kernel: 000004d0 000382ff 00000000 c13b7b00 f2dc927d 00000531 c13b1000 c13b1000 2010-09-29T11:21:36.985+02:00 n22 kernel: c13b7b00 c13b7b00 f516dba0 f5fc7dc4 c11d26e8 00000020 c3680c80 00000020 2010-09-29T11:21:36.985+02:00 n22 kernel: Call Trace: 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c11cf5a4>] ? sock_alloc_send_pskb+0x164/0x2a0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c11d26e8>] ? skb_queue_tail+0x38/0x50 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c123d5c0>] __mutex_lock_slowpath+0xd0/0x130 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c123d980>] mutex_lock+0x20/0x40 2010-09-29T11:21:36.985+02:00 n22 kernel: [<f8a8843b>] i915_gem_throttle_ioctl+0x2b/0x80 [i915] 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c11cb3f3>] ? sock_aio_write+0x113/0x140 2010-09-29T11:21:36.985+02:00 n22 kernel: [<f89ea08b>] drm_ioctl+0x1ab/0x430 [drm] 2010-09-29T11:21:36.985+02:00 n22 kernel: [<f8a88410>] ? i915_gem_throttle_ioctl+0x0/0x80 [i915] 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10a2045>] ? do_sync_readv_writev+0x95/0xd0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10a1eb2>] ? rw_copy_check_uvector+0x52/0x100 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10af03d>] vfs_ioctl+0x2d/0xc0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10a27c1>] ? do_readv_writev+0x141/0x1b0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<f89e9ee0>] ? drm_ioctl+0x0/0x430 [drm] 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10af21a>] do_vfs_ioctl+0x6a/0x590 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c104bac3>] ? hrtimer_try_to_cancel+0x33/0x80 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c1036efd>] ? do_setitimer+0xad/0x1a0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c112c6e8>] ? _copy_from_user+0x38/0x130 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c103703c>] ? sys_setitimer+0x4c/0xa0 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c10af779>] sys_ioctl+0x39/0x60 2010-09-29T11:21:36.985+02:00 n22 kernel: [<c1002d97>] sysenter_do_call+0x12/0x26
The ThinkPad T400 hang completey and I had to use the magic SysRq+B key to reboot the system. Is this a known problem ?
On Wed, 29 Sep 2010 11:36:22 +0200, Toralf Förster toralf.foerster@gmx.de wrote:
Hello,
today I run at the latest 2.6.35.6 kernel few apps like Lotus Notes under wine, amarok and firefox and in parallel a "git bisect" when I got this :
n22 ~ # grep 2010-09-29T11:21 /var/log/messages | grep kernel 2010-09-29T11:21:36.984+02:00 n22 kernel: INFO: task i915:868 blocked for more than 120 seconds. 2010-09-29T11:21:36.984+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-09-29T11:21:36.984+02:00 n22 kernel: i915 D ffa47280 0 868 2 0x00000000
It's a mysterious lost interrupt (or a touch of incoherency around the dword seqno write). The pipe control dance is meant to ensure the write to memory is truly flushed before the interrupt fires. [T400 is ironlake?]
cat /sys/kernel/debug/dri/0/i915_gem_interrupt
That should show whether the seqno was ever updated. We could extend that file by recording the number of User Interrupts since waiting to see if we miss the interrupt.
drm-intel-next contains patches to hopefully workaround the hang. So hopefully your machine will no longer die whilst we uncover the root cause. -Chris
Toralf Förster wrote at 09:49:00
Chris Wilson wrote at 16:02:08
memory is truly flushed before the interrupt fires. [T400 is ironlake?] -Chris
It is a Intel GM45 Chipset.
BTW, today I got it again :
... 2010-10-04T14:58:56.378+02:00 n22 kernel: INFO: task i915:907 blocked for more than 120 seconds. 2010-10-04T14:58:56.378+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-10-04T14:58:56.378+02:00 n22 kernel: i915 D ffa48858 0 907 2 0x00000000 2010-10-04T14:58:56.378+02:00 n22 kernel: f5e73f1c 00000046 0002f941 ffa48858 00000000 0b298d84 00000cee dfa3f844 2010-10-04T14:58:56.378+02:00 n22 kernel: c2406b40 00001a02 00000000 c13b7b00 0b297382 00000cee c13b1000 c13b1000 2010-10-04T14:58:56.378+02:00 n22 kernel: c13b7b00 c13b7b00 f71d3070 f71d3070 f5e73f6c c123c4f1 0029d5af 0000377e 2010-10-04T14:58:56.378+02:00 n22 kernel: Call Trace: 2010-10-04T14:58:56.378+02:00 n22 kernel: [<c123c4f1>] ? schedule+0x211/0x780 2010-10-04T14:58:56.378+02:00 n22 kernel: [<c123d3c0>] __mutex_lock_slowpath+0xd0/0x130 2010-10-04T14:58:56.378+02:00 n22 kernel: [<c123d780>] mutex_lock+0x20/0x40 2010-10-04T14:58:56.379+02:00 n22 kernel: [<f84fb508>] i915_gem_retire_work_handler+0x28/0xc0 [i915] 2010-10-04T14:58:56.379+02:00 n22 kernel: [<f84fb4e0>] ? i915_gem_retire_work_handler+0x0/0xc0 [i915] 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c104418f>] worker_thread+0xef/0x1b0 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c1047ba0>] ? autoremove_wake_function+0x0/0x40 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c10440a0>] ? worker_thread+0x0/0x1b0 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c1047834>] kthread+0x74/0x80 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c10477c0>] ? kthread+0x0/0x80 2010-10-04T14:58:56.379+02:00 n22 kernel: [<c10032be>] kernel_thread_helper+0x6/0x18 2010-10-04T14:58:56.379+02:00 n22 kernel: INFO: task X:11480 blocked for more than 120 seconds. 2010-10-04T14:58:56.379+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-10-04T14:58:56.380+02:00 n22 kernel: X D f51a9d80 0 11480 11426 0x00400004 2010-10-04T14:58:56.380+02:00 n22 kernel: f51a9dd8 00203086 f51a9da0 f51a9d80 c2606b00 f33e3ef9 00000ced c2606b00 2010-10-04T14:58:56.380+02:00 n22 kernel: f6a32000 0027fbb7 00000000 c13b7b00 f3164342 00000ced c13b1000 c13b1000 2010-10-04T14:58:56.380+02:00 n22 kernel: c13b7b00 c13b7b00 f5607400 c1025ef9 00000060 00000001 f63f6414 f63f6400 2010-10-04T14:58:56.380+02:00 n22 kernel: Call Trace: 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c1025ef9>] ? mutex_spin_on_owner+0x79/0xa0 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c123d3c0>] __mutex_lock_slowpath+0xd0/0x130 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c123d780>] mutex_lock+0x20/0x40 2010-10-04T14:58:56.380+02:00 n22 kernel: [<f84fab33>] i915_gem_sw_finish_ioctl+0x43/0xa0 [i915] 2010-10-04T14:58:56.380+02:00 n22 kernel: [<f827008b>] drm_ioctl+0x1ab/0x430 [drm] 2010-10-04T14:58:56.380+02:00 n22 kernel: [<f84faaf0>] ? i915_gem_sw_finish_ioctl+0x0/0xa0 [i915] 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c10a21a4>] ? do_sync_read+0xa4/0xe0 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c104bc54>] ? __hrtimer_start_range_ns+0x154/0x3a0 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c10aefcd>] vfs_ioctl+0x2d/0xc0 2010-10-04T14:58:56.380+02:00 n22 kernel: [<f826fee0>] ? drm_ioctl+0x0/0x430 [drm] 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c10af1aa>] do_vfs_ioctl+0x6a/0x590 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c1036fc3>] ? do_setitimer+0x193/0x1a0 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c10508cb>] ? ktime_get_ts+0xdb/0x110 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c10af709>] sys_ioctl+0x39/0x60 2010-10-04T14:58:56.380+02:00 n22 kernel: [<c1002d97>] sysenter_do_call+0x12/0x26
...
010-10-04T15:00:56.379+02:00 n22 kernel: INFO: task i915:907 blocked for more than 120 seconds. 2010-10-04T15:00:56.379+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-10-04T15:00:56.379+02:00 n22 kernel: i915 D ffa48858 0 907 2 0x00000000 2010-10-04T15:00:56.379+02:00 n22 kernel: f5e73f1c 00000046 0002f941 ffa48858 00000000 0b298d84 00000cee dfa3f844 2010-10-04T15:00:56.379+02:00 n22 kernel: c2406b40 00001a02 00000000 c13b7b00 0b297382 00000cee c13b1000 c13b1000 2010-10-04T15:00:56.379+02:00 n22 kernel: c13b7b00 c13b7b00 f71d3070 f71d3070 f5e73f6c c123c4f1 0029d5af 0000377e 2010-10-04T15:00:56.379+02:00 n22 kernel: Call Trace: 2010-10-04T15:00:56.379+02:00 n22 kernel: [<c123c4f1>] ? schedule+0x211/0x780 2010-10-04T15:00:56.379+02:00 n22 kernel: [<c123d3c0>] __mutex_lock_slowpath+0xd0/0x130 2010-10-04T15:00:56.379+02:00 n22 kernel: [<c123d780>] mutex_lock+0x20/0x40 2010-10-04T15:00:56.380+02:00 n22 kernel: [<f84fb508>] i915_gem_retire_work_handler+0x28/0xc0 [i915] 2010-10-04T15:00:56.380+02:00 n22 kernel: [<f84fb4e0>] ? i915_gem_retire_work_handler+0x0/0xc0 [i915] 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c104418f>] worker_thread+0xef/0x1b0 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c1047ba0>] ? autoremove_wake_function+0x0/0x40 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c10440a0>] ? worker_thread+0x0/0x1b0 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c1047834>] kthread+0x74/0x80 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c10477c0>] ? kthread+0x0/0x80 2010-10-04T15:00:56.380+02:00 n22 kernel: [<c10032be>] kernel_thread_helper+0x6/0x18 2010-10-04T15:00:56.380+02:00 n22 kernel: INFO: task X:11480 blocked for more than 120 seconds. 2010-10-04T15:00:56.380+02:00 n22 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 2010-10-04T15:00:56.381+02:00 n22 kernel: X D f51a9d80 0 11480 11426 0x00400004 2010-10-04T15:00:56.381+02:00 n22 kernel: f51a9dd8 00203086 f51a9da0 f51a9d80 c2606b00 f33e3ef9 00000ced c2606b00 2010-10-04T15:00:56.381+02:00 n22 kernel: f6a32000 0027fbb7 00000000 c13b7b00 f3164342 00000ced c13b1000 c13b1000 2010-10-04T15:00:56.381+02:00 n22 kernel: c13b7b00 c13b7b00 f5607400 c1025ef9 00000060 00000001 f63f6414 f63f6400 2010-10-04T15:00:56.381+02:00 n22 kernel: Call Trace: 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c1025ef9>] ? mutex_spin_on_owner+0x79/0xa0 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c123d3c0>] __mutex_lock_slowpath+0xd0/0x130 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c123d780>] mutex_lock+0x20/0x40 2010-10-04T15:00:56.381+02:00 n22 kernel: [<f84fab33>] i915_gem_sw_finish_ioctl+0x43/0xa0 [i915] 2010-10-04T15:00:56.381+02:00 n22 kernel: [<f827008b>] drm_ioctl+0x1ab/0x430 [drm] 2010-10-04T15:00:56.381+02:00 n22 kernel: [<f84faaf0>] ? i915_gem_sw_finish_ioctl+0x0/0xa0 [i915] 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c10a21a4>] ? do_sync_read+0xa4/0xe0 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c104bc54>] ? __hrtimer_start_range_ns+0x154/0x3a0 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c10aefcd>] vfs_ioctl+0x2d/0xc0 2010-10-04T15:00:56.381+02:00 n22 kernel: [<f826fee0>] ? drm_ioctl+0x0/0x430 [drm] 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c10af1aa>] do_vfs_ioctl+0x6a/0x590 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c1036fc3>] ? do_setitimer+0x193/0x1a0 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c10508cb>] ? ktime_get_ts+0xdb/0x110 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c10af709>] sys_ioctl+0x39/0x60 2010-10-04T15:00:56.381+02:00 n22 kernel: [<c1002d97>] sysenter_do_call+0x12/0x26 22010-10-04T15:01:49.362+02:00 n22 kernel: usb 7-1: USB disconnect, address 8 2010-10-04T15:01:49.392+02:00 n22 kernel: dvb-usb: Terratec Cinergy T USB XXS (HD)/ T3 successfully deinitialized and disconnected. 2010-10-04T15:02:14.087+02:00 n22 kernel: SysRq : Emergency Sync 2010-10-04T15:02:14.101+02:00 n22 kernel: Emergency Sync complete 2010-10-04T15:02:16.559+02:00 n22 kernel: SysRq : Emergency Sync 2010-10-04T15:02:16.576+02:00 n22 kernel: Emergency Sync complete 2010-10-04T15:02:17.495+02:00 n22 kernel: SysRq : Emergency Remount R/O
Chris Wilson wrote at 16:02:08
drm-intel-next contains patches to hopefully workaround the hang. So hopefully your machine will no longer die whilst we uncover the root cause. -Chris
Well, I appreciate it:-)
- b/c today I run again into this issue w/ 2.6.35.6 - BTW again, if I walked thru a bookmark lists (RSS feeds) of firefox
Toralf Förster wrote:
today I run at the latest 2.6.35.6 kernel few apps like Lotus Notes under wine,
I'm still stuck with 2.6.36-rc1, and both here and on many/most earlier kernels I get a few seconds of very irritating stuttering whenever I run wine. It is definately related to interaction with X. wine folks' reaction was sortof "mh i915 is kinda slow may be it can not do any better" but I think it's remarkably bad. Didn't think to mention it here earlier. I've never seen a problem like Toralf's however, but I also don't use wine for complex GUI things.
//Peter
On Thu, 30 Sep 2010 01:08:47 +0200, Peter Stuge peter@stuge.se wrote:
Toralf Förster wrote:
today I run at the latest 2.6.35.6 kernel few apps like Lotus Notes under wine,
I'm still stuck with 2.6.36-rc1, and both here and on many/most earlier kernels I get a few seconds of very irritating stuttering whenever I run wine. It is definately related to interaction with X. wine folks' reaction was sortof "mh i915 is kinda slow may be it can not do any better" but I think it's remarkably bad. Didn't think to mention it here earlier. I've never seen a problem like Toralf's however, but I also don't use wine for complex GUI things.
wine triggers an xrandr storm for its own unknown reasons. The delay you see on starting is the driver (on wine's behalf) repeatedly querying the outputs for connected displays (which can be excruciatingly slow due to dumb hardware, e.g. VGA load-detection on i8xx/i915). -Chris
Chris Wilson wrote:
a few seconds of very irritating stuttering whenever I run wine. i915
wine triggers an xrandr storm for its own unknown reasons.
Same underlying reason as for the 600ms keyboard pauses I saw.
One #winehq person claims that ATI and NV drivers track monitor state and cache resolution information, which is what wine queries on startup.
The delay you see on starting is the driver (on wine's behalf) repeatedly querying the outputs for connected displays
It feels like it is being done twice.
I'm taking a look in the wine code. I hope it can be resolved. I guess it's this call to XRRSizes():
http://source.winehq.org/git/wine.git/?a=blob;f=dlls/winex11.drv/xrandr.c#l2...
Maybe make_modes() is also involved:
http://source.winehq.org/git/wine.git/?a=blob;f=dlls/winex11.drv/xrandr.c#l1...
//Peter
Peter Stuge wrote:
I hope it can be resolved.
There was talk about knobs. Maybe a simple kill switch for VGA1? I want my machine to require explicit enable of VGA1 before it will be used anyway. A disable knob would work great for me. :)
//Peter
dri-devel@lists.freedesktop.org
-
Chris Wilson -
Peter Stuge -
Toralf Förster