Bug 10358 - xf86-video-i810 hang on startup with 100% cpu usage
Summary: xf86-video-i810 hang on startup with 100% cpu usage
Status: RESOLVED INVALID
Alias: None
Product: xorg
Classification: Unclassified
Component: Driver/intel (show other bugs)
Version: git
Hardware: x86 (IA32) Linux (All)
: medium normal
Assignee: Eric Anholt
QA Contact: Xorg Project Team
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-03-20 10:48 UTC by Grant Likely
Modified: 2007-03-27 23:07 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments
Config file (2.63 KB, text/plain)
2007-03-20 10:50 UTC, Grant Likely
no flags Details
Log output (27.77 KB, text/plain)
2007-03-20 10:53 UTC, Grant Likely
no flags Details
Output from xserver built with --enable-debug (66.95 KB, text/plain)
2007-03-24 12:28 UTC, Grant Likely
no flags Details

Description Grant Likely 2007-03-20 10:48:08 UTC
With both the 7.2 release and the latest git, the xserver hangs on startup while consuming 100% of the cpu.

Using minimal config file (simply output of Xorg -configure)
Probing strace reveals continual calls to gettimeofday
I didn't see anything obvious in the log file.

Details:
Macbook Core 2 Duo (February 2007 model)
Seen on both kernel versions 2.6.19 and 2.6.20

Problem first seen after using gentoo build scripts to install xorg 7.2
Can also reproduce in the following environment:
  Distro (Gentoo) installed xorg 7.1 modules except for the following:
  damageproto       commit id: cff2b116eb2a6a7827b866910a84f8357c299be0
  inputproto        commit id: c608d82c6b5b87ddc8d14862f528bdd69f5f5b72
  randrproto        commit id: aada204b1fc9ba6461efad3fe6bd032ee98536e1
  libXdamage        commit id: b96e17d8a4fe8e19515c0f183e5e299939c6eca0
  libXrandr         commit id: 3e753542bcf0fd49fe977e56b7ab7e540bbd4282
  xserver           commit id: b8df961843a95b29258ae9c5d46ccfc620d8de1c
  xf86-video-intel  commit id: 4c4faf260eb4dad1b1919c6168fa9ef477b98a39
Comment 1 Grant Likely 2007-03-20 10:50:38 UTC
Created attachment 9238 [details]
Config file
Comment 2 Grant Likely 2007-03-20 10:53:47 UTC
Created attachment 9239 [details]
Log output
Comment 3 Grant Likely 2007-03-24 11:32:21 UTC
I managed to get a backtrace out of GDB; output is below.  I also allowed GDB to execute up the call stack to try and determine what the root of the endless loop is.

(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7ce4cd6 in gettimeofday () from /lib/libc.so.6
#2  0x080f9e7e in I2CUDelay (b=0x82128d0, usec=5) at xf86i2c.c:82
#3  0x080f933c in I2CWriteBit (b=0x82128d0, sda=1,
    timeout=<value optimized out>) at xf86i2c.c:203
#4  0x080f943c in I2CPutByte (d=0x8212760, data=113 'q') at xf86i2c.c:255
#5  0x080f960f in I2CAddress (d=0x8212760, addr=113) at xf86i2c.c:360
#6  0x080f9717 in I2CWriteRead (d=0x8212760, WriteBuffer=0xbf900384 "\017",
    nWrite=0, ReadBuffer=0x82127c7 "", nRead=1) at xf86i2c.c:450
#7  0x080f9857 in xf86I2CReadByte (d=0x8212760, subaddr=15 '\017',
    pbyte=0x82127c7 "") at xf86i2c.c:490
#8  0xb7bb81f3 in i830_sdvo_read_byte (output=0x0, addr=6, ch=0x0)
    at i830_sdvo.c:122
#9  0xb7bb8281 in i830_sdvo_read_response (output=0x8212298,
    response=0x82127c2, response_len=8) at i830_sdvo.c:270
#10 0xb7bb86ee in i830_sdvo_get_timing (output=0x8212298, cmd=24 '\030',
    dtd=0x82127c2) at i830_sdvo.c:458
#11 0xb7bb8eed in i830_sdvo_save (output=0x8212298) at i830_sdvo.c:480
#12 0xb7ba8c47 in SaveHWState (pScrn=0x820e670) at i830_driver.c:1737
#13 0xb7baaa87 in I830PreInit (pScrn=0x820e670, flags=<value optimized out>)
    at i830_driver.c:1301
#14 0x080a4d6e in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4)
    at xf86Init.c:586
#15 0x08070901 in main (argc=3, argv=0xbf9006a4, envp=0xbf9006b4) at main.c:370
(gdb)  finish
Run till exit from #0  0xffffe410 in __kernel_vsyscall ()
0xb7ce4cd6 in gettimeofday () from /lib/libc.so.6
(gdb) finish
Run till exit from #0  0xb7ce4cd6 in gettimeofday () from /lib/libc.so.6
I2CUDelay (b=0x82128d0, usec=5) at xf86i2c.c:85
85            diff = d_secs*1000000 + d_usecs;
(gdb) finish
Run till exit from #0  I2CUDelay (b=0x82128d0, usec=5) at xf86i2c.c:85
I2CWriteBit (b=0x82128d0, sda=1, timeout=<value optimized out>)
    at xf86i2c.c:205
205         b->I2CPutBits(b, 0, sda);
(gdb) finish
Run till exit from #0  I2CWriteBit (b=0x82128d0, sda=1,
    timeout=<value optimized out>) at xf86i2c.c:205
0x080f943c in I2CPutByte (d=0x8212760, data=113 'q') at xf86i2c.c:255
255             if (!I2CWriteBit(b, (data >> i) & 1, d->BitTimeout))
Value returned is $16 = 1
(gdb) finish
Run till exit from #0  0x080f943c in I2CPutByte (d=0x8212760, data=113 'q')
    at xf86i2c.c:255
0x080f960f in I2CAddress (d=0x8212760, addr=113) at xf86i2c.c:360
360             if (I2CPutByte(d, addr & 0xFF)) {
Value returned is $17 = 1
(gdb) finish
Run till exit from #0  0x080f960f in I2CAddress (d=0x8212760, addr=113)
    at xf86i2c.c:360
I2CWriteRead (d=0x8212760, WriteBuffer=0xbf900384 "\017", nWrite=0,
    ReadBuffer=0x82127c7 "", nRead=1) at xf86i2c.c:451
451             if (r) {
Value returned is $18 = 1
(gdb) finish
Run till exit from #0  I2CWriteRead (d=0x8212760,
    WriteBuffer=0xbf900384 "\017", nWrite=0, ReadBuffer=0x82127c7 "", nRead=1)
    at xf86i2c.c:451
xf86I2CReadByte (d=0x8212760, subaddr=15 '\017', pbyte=0x82127c7 "")
    at xf86i2c.c:491
491     }
Value returned is $19 = 1
(gdb) finish
Run till exit from #0  xf86I2CReadByte (d=0x8212760, subaddr=15 '\017',
    pbyte=0x82127c7 "") at xf86i2c.c:491
0xb7bb81f3 in i830_sdvo_read_byte (output=<value optimized out>,
    addr=<value optimized out>, ch=<value optimized out>) at i830_sdvo.c:122
122         if (!xf86I2CReadByte(&dev_priv->d, addr, ch)) {
Value returned is $20 = 1
(gdb) finish
Run till exit from #0  0xb7bb81f3 in i830_sdvo_read_byte (
    output=<value optimized out>, addr=<value optimized out>,
    ch=<value optimized out>) at i830_sdvo.c:122
i830_sdvo_read_response (output=0x8212298, response=0x82127c2, response_len=8)
    at i830_sdvo.c:269
269         for (i = 0; i < response_len; i++) {
Value returned is $21 = 1
(gdb) finish
Run till exit from #0  i830_sdvo_read_response (output=0x8212298,
    response=0x82127c2, response_len=8) at i830_sdvo.c:269
i830_sdvo_get_timing (output=0x8212298, cmd=24 '\030', dtd=0x82127c2)
    at i830_sdvo.c:459
459         if (status != SDVO_CMD_STATUS_SUCCESS)
Value returned is $22 = 1 '\001'
(gdb) finish
Run till exit from #0  i830_sdvo_get_timing (output=0x8212298, cmd=24 '\030',
    dtd=0x82127c2) at i830_sdvo.c:459
i830_sdvo_save (output=0x8212298) at i830_sdvo.c:809
809         for (o = SDVO_OUTPUT_FIRST; o <= SDVO_OUTPUT_LAST; o++)
Value returned is $23 = 1
(gdb) finish
Run till exit from #0  i830_sdvo_save (output=0x8212298) at i830_sdvo.c:809
0xb7ba8c47 in SaveHWState (pScrn=0x820e670) at i830_driver.c:1737
1737             (*output->funcs->save) (output);
(gdb) finish
Run till exit from #0  0xb7ba8c47 in SaveHWState (pScrn=0x820e670)
    at i830_driver.c:1737
I830PreInit (pScrn=0x820e670, flags=<value optimized out>)
    at i830_driver.c:1302
1302       if (!xf86InitialConfiguration (pScrn, FALSE))
Value returned is $24 = 1
(gdb) finish
Run till exit from #0  I830PreInit (pScrn=0x820e670,
    flags=<value optimized out>) at i830_driver.c:1302

GDB never returns from here; this looks like the top of the endless loop.
Comment 4 Grant Likely 2007-03-24 11:52:59 UTC
Oh, wait... after letting it run for a long time, the xserver finally exited on a signal.  Here's a new gdb backtrace and execution up the call stack, including the terminating signal.

(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7ce4cd6 in gettimeofday () from /lib/libc.so.6
#2  0x080f9e7e in I2CUDelay (b=0x821e710, usec=20) at xf86i2c.c:82
#3  0x080f9544 in I2CGetByte (d=0x821c9d0, data=0x821b487 'ÿ' <repeats 17 times>, last=0) at xf86i2c.c:310
#4  0x080f9747 in I2CWriteRead (d=0x821c9d0, WriteBuffer=0xbf9003ea "\200¿hç!\bèê \b", nWrite=0,
    ReadBuffer=0x821b487 'ÿ' <repeats 17 times>, nRead=17) at xf86i2c.c:453
#5  0x080f6241 in DDCRead_DDC2 (scrnIndex=1, pBus=<value optimized out>, start=<value optimized out>, len=64)
    at xf86DDC.c:372
#6  0x080f6427 in xf86DoEDID_DDC2 (scrnIndex=1, pBus=0x821e710) at xf86DDC.c:309
#7  0xb7bb13ac in i830_ddc_get_modes (output=0x821e508) at i830_modes.c:65
#8  0xb7bae680 in i830_lvds_init (pScrn=0x820eae8) at i830_lvds.c:433
#9  0xb7baba06 in I830PreInit (pScrn=0x820eae8, flags=<value optimized out>) at i830_driver.c:676
#10 0x080a4d6e in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4) at xf86Init.c:586
#11 0x08070901 in main (argc=3, argv=0xbf9006a4, envp=0xbf9006b4) at main.c:370
(gdb) up
#1  0xb7ce4cd6 in gettimeofday () from /lib/libc.so.6
(gdb) up
#2  0x080f9e7e in I2CUDelay (b=0x821e710, usec=20) at xf86i2c.c:82
82            X_GETTIMEOFDAY(&cur);
(gdb) up
#3  0x080f9544 in I2CGetByte (d=0x821c9d0, data=0x821b487 'ÿ' <repeats 17 times>, last=0) at xf86i2c.c:310
310         b->I2CUDelay(b, b->RiseFallTime);
(gdb) up
#4  0x080f9747 in I2CWriteRead (d=0x821c9d0, WriteBuffer=0xbf9003ea "\200¿hç!\bèê \b", nWrite=0,
    ReadBuffer=0x821b487 'ÿ' <repeats 17 times>, nRead=17) at xf86i2c.c:453
453                     if (!(r = b->I2CGetByte(d, ReadBuffer, nRead == 1)))
(gdb) up
#5  0x080f6241 in DDCRead_DDC2 (scrnIndex=1, pBus=<value optimized out>, start=<value optimized out>, len=64)
    at xf86DDC.c:372
372             if (xf86I2CWriteRead(dev, W_Buffer,w_bytes, R_Buffer,len)) {
(gdb) up
#6  0x080f6427 in xf86DoEDID_DDC2 (scrnIndex=1, pBus=0x821e710) at xf86DDC.c:309
309         Buffer = DDCRead_DDC2(scrnIndex, pBus,start,64);
(gdb) up
#7  0xb7bb13ac in i830_ddc_get_modes (output=0x821e508) at i830_modes.c:65
65          edid_mon = xf86OutputGetEDID (output, intel_output->pDDCBus);
(gdb) up
#8  0xb7bae680 in i830_lvds_init (pScrn=0x820eae8) at i830_lvds.c:433
433         modes = i830_ddc_get_modes(output);
(gdb) finish
Run till exit from #8  0xb7bae680 in i830_lvds_init (pScrn=0x820eae8) at i830_lvds.c:433
0xb7baba06 in I830PreInit (pScrn=0x820eae8, flags=<value optimized out>) at i830_driver.c:676
676           i830_lvds_init(pScrn);
(gdb) finish
Run till exit from #0  0xb7baba06 in I830PreInit (pScrn=0x820eae8, flags=<value optimized out>)
    at i830_driver.c:676
chosen: dotclock 107520 vco 2150400 ((m 112, m1 19, m2 5), n 3, (p 20, p1 2, p2 10))
0x080a4d6e in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4) at xf86Init.c:586
586             if (xf86Screens[i]->PreInit &&
Value returned is $1 = 1
(gdb) bt
#0  0x080a4d6e in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4) at xf86Init.c:586
#1  0x08070901 in main (argc=3, argv=0xbf9006a4, envp=0xbf9006b4) at main.c:370
(gdb) finish
Run till exit from #0  0x080a4d6e in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4) at xf86Init.c:586
(EE) intel(0): [dri] I830CheckDRIAvailable failed: glx not loaded

Program received signal SIGSEGV, Segmentation fault.
i830_allocate_aperture (pScrn=<value optimized out>, name=0xb7bcd96d "secondary front buffer", size=3276800,
    alignment=65536, flags=0) at i830_memory.c:346
346         for (scan = pI830->memory_list; scan->next != NULL; scan = scan->next) {
(gdb) finish
Run till exit from #0  i830_allocate_aperture (pScrn=<value optimized out>,
    name=0xb7bcd96d "secondary front buffer", size=3276800, alignment=65536, flags=0) at i830_memory.c:346

Backtrace:
0: /opt/xorg/bin/Xorg(xf86SigHandler+0x80) [0x80c2b20]
1: [0xffffe420]
2: /opt/xorg/lib/xorg/modules/drivers//i810_drv.so [0xb7baf940]
3: /opt/xorg/lib/xorg/modules/drivers//i810_drv.so [0xb7bb086e]
4: /opt/xorg/lib/xorg/modules/drivers//i810_drv.so(i830_allocate_2d_memory+0x11f) [0xb7bb0b3f]
5: /opt/xorg/lib/xorg/modules/drivers//i810_drv.so [0xb7bacc2a]
6: /opt/xorg/bin/Xorg(AddScreen+0x1ed) [0x807015d]
7: /opt/xorg/bin/Xorg(InitOutput+0x22e) [0x80a45de]
8: /opt/xorg/bin/Xorg(main+0x281) [0x8070901]
9: /lib/libc.so.6(__libc_start_main+0xd8) [0xb7c7d838]
10: /opt/xorg/bin/Xorg(FontFileCompleteXLFD+0xb1) [0x806fe41]

Fatal server error:
Caught signal 11.  Server aborting


Program received signal SIGABRT, Aborted.
0xffffe410 in __kernel_vsyscall ()
(gdb) bt
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7c90701 in raise () from /lib/libc.so.6
#2  0xb7c91e38 in abort () from /lib/libc.so.6
#3  0x080a3ed5 in ddxGiveUp () at xf86Init.c:1129
#4  0x081bd808 in AbortServer () at log.c:409
#5  0x081bdd27 in FatalError (f=0x81c829c "Caught signal %d.  Server aborting\n") at log.c:555
#6  0x080c2b97 in xf86SigHandler (signo=11) at xf86Events.c:771
#7  <signal handler called>
#8  i830_allocate_aperture (pScrn=<value optimized out>, name=0xb7bcd96d "secondary front buffer", size=3276800,
    alignment=65536, flags=0) at i830_memory.c:346
#9  0xb7baf940 in i830_allocate_memory (pScrn=0x820eae8, name=0x8220b18 "", size=0, alignment=65536, flags=0)
    at i830_memory.c:433
#10 0xb7bb086e in i830_allocate_framebuffer (pScrn=0x820eae8, pI830=0x821cf00, FbMemBox=0x7, secondary=1, flags=0)
    at i830_memory.c:829
#11 0xb7bb0b3f in i830_allocate_2d_memory (pScrn=0x820e670) at i830_memory.c:1000
#12 0xb7bacc2a in I830ScreenInit (scrnIndex=0, pScreen=0x821f978, argc=3, argv=0xbf9006a4) at i830_driver.c:2342
#13 0x0807015d in AddScreen (pfnInit=0xb7bac4c0 <I830ScreenInit>, argc=3, argv=0xbf9006a4) at main.c:784
#14 0x080a45de in InitOutput (pScreenInfo=0x81f8520, argc=3, argv=0xbf9006a4) at xf86Init.c:909
#15 0x08070901 in main (argc=3, argv=0xbf9006a4, envp=0xbf9006b4) at main.c:370
(gdb) c
Continuing.

Program terminated with signal SIGABRT, Aborted.
The program no longer exists.
(gdb)                                            
Comment 5 Grant Likely 2007-03-24 12:28:11 UTC
Created attachment 9277 [details]
Output from xserver built with --enable-debug

I recompiled xserver with debug enabled and attached the output to this bug.  Xorg hung for about 15 minutes before aborting.
Comment 6 Grant Likely 2007-03-27 23:07:25 UTC
Problem tracked down to behaviour of I2CUDelay() function.

I2CUDelay was returning in 10ms; regardless of the time requested.  I2CUDelay uses a busywait loop which calls gettimeofday() until the required time is elapsed.  gtod syscall was not returning a resolution any greater than 10ms.

The Linux kernel was configured without CONFIG_HPET_TIMER.  Without this timer support, gtod falls back to ticks.  HZ=100; therefore, 10ms maximum resolution makes sense.

Enabling CONFIG_HPET_TIMER solved the problem.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.