Bug 10358

Created attachment 9238 [details]
Config file

Created attachment 9239 [details]
Log output

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.

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)                                            

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.

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.