Thanks amit,

Sounds like something's fishy with that second lock. I disabled it in this patch, and lo and behold, up came X.

Looking at the Xorg.0.log, it is definitely running with the psb driver, and the log contains nothing unexpected. (There are some error and warning messages, but nothing we don't already know about.)

So, since this seems to solve the issue (at least for the present), I've uploaded the fixed -psb to Ubuntu Mobile PPA.

I played around with some apps, and everything seems to be working fine. 3D performance is poor, but that's expected since we don't have the 3D driver yet. However, glxgears runs, it's just slow (10.5 fps).

">

">

# echo 1 > /sys/module/drm/parameters/debug

gives us more insight of what is happening inside the kernel...

[drm:drm_stub_open]
[drm:drm_open_helper] pid = 4753, minor = 0
[drm:drm_addmap_core] offset = 0x00000000, size = 0x00002000, type = 2
[drm:drm_addmap_core] 8192 13 f8a37000
[drm:drm_setup]
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_release] open_count = 1
[drm:drm_release] pid = 4753, device = 0xe200, open_count = 1
[drm:drm_fasync] fd = -1, device = 0xe200
[drm:drm_lastclose]
[drm:drm_lastclose] driver lastclose completed
[drm:drm_lastclose] lastclose completed
[drm:drm_stub_open]
[drm:drm_open_helper] pid = 4753, minor = 0
[drm:drm_addmap_core] offset = 0x00000000, size = 0x00002000, type = 2
[drm:drm_addmap_core] 8192 13 f8a37000
[drm:drm_setup]
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_release] open_count = 1
[drm:drm_release] pid = 4753, device = 0xe200, open_count = 1
[drm:drm_fasync] fd = -1, device = 0xe200
[drm:drm_lastclose]
[drm:drm_lastclose] driver lastclose completed
[drm:drm_lastclose] lastclose completed
[drm:drm_stub_open]
[drm:drm_open_helper] pid = 4753, minor = 0
[drm:drm_addmap_core] offset = 0x00000000, size = 0x00002000, type = 2
[drm:drm_addmap_core] 8192 13 f8a37000
[drm:drm_setup]
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0106407, nr=0x07, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086401, nr=0x01, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086401, nr=0x01, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0106407, nr=0x07, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0186415, nr=0x15, dev 0xe200, auth=1
[drm:drm_addmap_core] offset = 0x00000000, size = 0x00002000, type = 2
[drm:drm_mmap_locked] start = 0xb7b39000, end = 0xb7b3b000, page offset = 0xf8a37
[drm:drm_vm_open_locked] 0xb7b39000,0x00002000
[drm:drm_do_vm_shm_nopage] shm_nopage 0xb7b39000
[drm:drm_do_vm_shm_nopage] shm_nopage 0xb7b3a000
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0186415, nr=0x15, dev 0xe200, auth=1
[drm:drm_addmap_core] offset = 0x3fc00000, size = 0x00001000, type = 0
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086426, nr=0x26, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086426, nr=0x26, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086420, nr=0x20, dev 0xe200, auth=1
[drm:drm_addctx] 1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0x40086422, nr=0x22, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0x4008642a, nr=0x2a, dev 0xe200, auth=1
[drm:drm_lock] 1 (pid 4753) requests lock (0x00000000), flags = 0x00000000
[drm:drm_lock] 1 has lock

This first context (whatever it is) has a successful lock here.

[drm:drm_fasync] fd = 10, device = 0xe200
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0246400, nr=0x00, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0x800c64d6, nr=0xd6, dev 0xe200, auth=1
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0086420, nr=0x20, dev 0xe200, auth=1
[drm:drm_addctx] 2
[drm:drm_unlocked_ioctl] pid=4753, cmd=0xc0106403, nr=0x03, dev 0xe200, auth=1
[drm:drm_irq_by_busid] 0:2:0 => IRQ 17
[drm:drm_unlocked_ioctl] pid=4753, cmd=0x40086414, nr=0x14, dev 0xe200, auth=1
[drm:drm_irq_install] drm_irq_install: irq=17
[psb:0x01:psb_irq_postinstall] Setting up MSVDX IRQs.....
[drm:drm_unlocked_ioctl] pid=4753, cmd=0x4008642a, nr=0x2a, dev 0xe200, auth=1
[drm:drm_lock] 2 (pid 4753) requests lock (0x80000001), flags = 0x00000000
[drm:drm_lock] 2 interrupted

This second lock failed here. This is where we Ctrl-C'ed the X server running under gdb. Now to figure out what this second lock is....

[drm:drm_unlocked_ioctl] ret = -512
[drm:drm_vm_shm_close] 0xb7b39000,0x00002000
[drm:drm_release] open_count = 1
[drm:drm_release] pid = 4753, device = 0xe200, open_count = 1
[drm:drm_release] File f7762a80 released, freeing lock for context 1
[drm:drm_fasync] fd = -1, device = 0xe200
[drm:drm_lastclose]
[drm:drm_lastclose] driver lastclose completed
[drm:drm_irq_uninstall] drm_irq_uninstall: irq=17
[drm:drm_lastclose] lastclose completed

Aha! This shows where things are failing:

(gdb) bt
#0 0xb7fd440e in __kernel_vsyscall ()
#1 0xb7e25bc9 in ioctl () from /lib/libc.so.6
#2 0xb7bc4a1d in drmGetLock (fd=10, context=2, flags=3213662516) at xf86drm.c:1259
#3 0xb7bb951b in psbDRILock (pScrn=0x820bcd0, flags=0) at psb_dri.c:724
#4 0xb7baf983 in psbScreenInit (scrnIndex=0, pScreen=0x821b2d8, argc=6, argv=0xbf8c9b74) at psb_driver.c:1342
#5 0x08073ddb in AddScreen (pfnInit=0xb7baf7f0 , argc=6, argv=0xbf8c9b74) at ../../dix/main.c:769
#6 0x080a6e39 in InitOutput (pScreenInfo=0x81fa640, argc=6, argv=0xbf8c9b74) at ../../../../hw/xfree86/common/xf86Init.c:850
#7 0x08074590 in main (argc=6, argv=0xbf8c9b74, envp=Cannot access memory at address 0x40086432
) at ../../dix/main.c:369

Looking at the drmGetLock() routine in libdrm, what's happening is it's getting stuck in a loop calling ioctl(), which is not succeeding for some reason:

int drmGetLock(int fd, drm_context_t context, drmLockFlags flags)
{
...
while (ioctl(fd, DRM_IOCTL_LOCK, &lock))
;
return 0;
}

So at this point, it's over to amitk to wrestle down where in the kernel things are blowing up.

Thanks to amitk's new kernel update and Mithrandir's new image, we finally have networking.

Here's a backtrace of running gdb against xinit:

cd /etc/X11
xinit /etc/X11/xinit/xinitrc -- /usr/bin/X -config xorg-new.conf
...
(==) Log file: "/var/log/Xorg.0.log", Time: Wed Jan 16 21:00:40 2008
(++) Using config file: "/etc/X11/xorg-new.conf"
(EE) PSB: Failed to load module "Xpsb" (module does not exist, 0)

(gdb)
(gdb) bt
#0 0xb7fa1410 in __kernel_vsyscall ()
#1 0xb7d8f4e2 in sigsuspend () from /lib/libc.so.6
#2 0x08049a97 in ?? ()
#3 0xbf981238 in ?? ()
#4 0x00001142 in ?? ()
#5 0xffffffff in ?? ()
#6 0xb7eab140 in ?? () from /lib/libc.so.6
#7 0x00000000 in ?? ()

And the last several lines from Xorg.0.log:

drmOpenByBusid: drmOpenMinor returns 10
drmOpenByBusid: drmGetBusid reports pci:0000:00:02.0
(II) [drm] loaded kernel module for "psb" driver.
(II) [drm] DRM interface version 1.3
(II) [drm] DRM open master succeeded.
(II) PSB(0): [drm] Using the DRM lock SAREA also for drawables.
(II) PSB(0): [drm] framebuffer handle = 0x3fc00000
(II) PSB(0): [drm] added 1 reserved context for kernel
(II) PSB(0): X context handle = 0x1
(II) PSB(0): [drm] installed DRM signal handler
(II) PSB(0): [drm] Allocated (legacy) device DRM context 2.
(II) [drm] Irq handler installed for IRQ 17.
(II) PSB(0): Creating memory manager.
(II) PSB(0): Debug: serverGeneration
(II) PSB(0): Locking DRI for screen

Looking deeper into why the -psb code would be failing in the memory manager, I noticed that the package was not building libmm at all. Hmm!

I've fixed that up and uploaded a new package:

http://people.ubuntu.com/~bryce/Testing/xserver-xorg-video-psb/

This also includes some debugging stuff (necessary only if my theory about libmm is incorrect), drops the Gutsy-specific EXA 2.2 workaround, and adopts the ubuntu-mobile numbering style.

Next step is getting a lpia build of it.

The above line is the last recorded into /var/log/Xorg.0.log. Looking at the driver source, this is printed from function psbDRMIrqInit, which is called from three places:

* psbDeviceLegacyDRIInit() in psb_dvi.c
* psbDRMDeviceInit() in psb_dvi.c
* psbEnterVt() in psb_driver.c

Looking at the surrounding X_INFO messages, the third call doesn't match up. Actually the first call appears to be the best match, although I'm not certain.

In any case, assuming it is psbDeviceLegacyDRIInit() where things are getting stuck, the next executable logic following the IRQ message deals with creating a memory manager:

pDevice->man = mmCreateDRM(pDevice->drmFD);

There's some conditional logic that I'm not sure whether it's getting called. Eventually, the next debug message appears to be in the shadowfb memory allocation section:

PSB_DEBUG(scrnIndex, 3, "Shadow\n");

If not the memory manager creation, then potentially it's getting stuck in xf86InitialConfiguration(), the scanout logic, or the mi layer logic. Unless we can get a backtrace, we'll need to add more debug statements I guess.

mjg59, offered this tip:

bryce: Mount / -o sync
That way you'll get more xorg.log

Since UME uses squashfs, /etc/fstab is not used for mount options. So instead, I guessed that the sync option needs added to /etc/initramfs-tools/disk:

mount -o rw,noatime,nodiratime,sync /dev/${device}2 /persistmnt

Unfortunately, this seems to not have made a difference to the log. Either it isn't sync'ing, or no further log data was available.

Turning NoAccel, SWcursor, and IgnoreACPI on had no effect on the lockup.

Neither did ShadowFB.

Here are the options supported by this driver:

static const OptionInfoRec psbOptions[] = {
{OPTION_SHADOWFB, "ShadowFB", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_NOACCEL, "NoAccel", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_SWCURSOR, "SWcursor", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_EXAMEM, "ExaMem", OPTV_INTEGER, {0}, FALSE},
{OPTION_EXASCRATCH, "ExaScratch", OPTV_INTEGER, {0}, FALSE},
{OPTION_EXACACHED, "ExaCached", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_DRI, "DRI", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_IGNORE_ACPI,"IgnoreACPI", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_NOPANEL, "NoPanel", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_LIDTIMER, "LidTimer", OPTV_BOOLEAN, {0}, FALSE},
{OPTION_NOFITTING, "NoFitting", OPTV_BOOLEAN, {0}, FALSE},
{-1, NULL, OPTV_NONE, {0}, FALSE},
};

I'm running through a list of various troubleshooting tips from X/Debugging. Many of these are probably not even relevant for -psb, but just wanted to run through and try them each at least once to see if they reveal any clues:

1. Attempting to unload "dri" and "glx" options in the "Module" section didn't do anything - the X log says they're required and overrides the unload request.

2. Adding this to the "Device" section:

Option "DRI" "false"

...causes X to fail to startup, with an error that it needs DRI enables for the Poulsbo driver.

3. Adding to the "Device" section:

Option "VBERestore" "false"

...had no effect.

4. Adding to "Extensions"

Option "Composite" "Disable"

...had no effect.

5. Adding to "ServerLayout"

Option "AIGLX" "false"

...had no effect.

In the Xorg.0.log after booting -psb, the exa version listed was compiled for 1.4.0.90, module version 2.2.0. Also, the date on the file matches that of other bits of xserver, and does not match the date on the -psb driver. This isn't what I'd expected, and makes me think it's not a libexa problem after all.

I notice the Xorg.0.log ends with some items about trying to load drm. Nothing that looks like an obvious error, however I'd expect some stuff to follow in the log regarding input devices, EDID info, modelines, etc.

This error is probably not an issue:

(EE) PSB: Failed to load module "Xpsb" (module does not exist, 0)
(WW) PSB(0): Poulsbo Xpsb driver not available. XVideo and 3D acceleration will not work

I believe this just indicates the 3D driver is not present (I don't think this has been delivered yet). I don't think it is related to the lockup.