Bug 29874

dmesg and strace?

'strace -o strace.log startx' http://pastebin.com/60bbvYc2
dmesg http://pastebin.com/g4Q754dN

Can you repeat the strace with 'strace -T -f startx'? so that strace will follow the children as well.

The dmesg ends with:

[drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 1sec aborting
[drm:atom_execute_table_locked] *ERROR* atombios stuck executing CC2C (len 62, WS 0, PS 0) @ 0xCC48
[drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 1sec aborting
[drm:atom_execute_table_locked] *ERROR* atombios stuck executing CC2C (len 62, WS 0, PS 0) @ 0xCC48
...

which is a radeon error. Can you include timing info to see if that is coincident with the slow startx?

(In reply to comment #3)
> Can you repeat the strace with 'strace -T -f startx'? so that strace will
> follow the children as well.

http://pastebin.com/Vuqgi5jz

(In reply to comment #4)
> The dmesg ends with:
> 
> [drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 1sec aborting
> [drm:atom_execute_table_locked] *ERROR* atombios stuck executing CC2C (len 62,
> WS 0, PS 0) @ 0xCC48
> [drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 1sec aborting
> [drm:atom_execute_table_locked] *ERROR* atombios stuck executing CC2C (len 62,
> WS 0, PS 0) @ 0xCC48
> ...
> 
> which is a radeon error. Can you include timing info to see if that is
> coincident with the slow startx?

how can I do that? dmesg command doesn't print any timing info... sorry

The issue is:

3132  open("/dev/dri/card0", O_RDWR)    = 8 <0.000015>
3132  write(0, "[   502.436] ", 13)     = 13 <0.000008>
3132  write(0, "drmOpenDevice: open result is 8,"..., 38) = 38 <0.000006>
3132  ioctl(8, 0xc0406400, 0xd94d20)    = 0 <0.000006>
3132  ioctl(8, 0xc0406400, 0xd94d20)    = 0 <0.000005>
3132  close(8 <unfinished ...>
...
3132  <... close resumed> )             = 0 <30.083807>

which verifies the same info we got from the Xorg.log.

So we do need to determine if the radeon errors are coincident with that open/close.

Have a look in /var/log/messages to see if they have the timing info.

Here's messages.log with timing info. I copied also lines of the log from a day when was everything OK ( = when X started immediately).

messages.log: http://pastebin.com/hZk3eAGx (I've logged in and started X after cca 9 minutes after boot, that's why 11:23:13->11:31:28)

I also looked at /var/log/errors.log and find out on e.g. 21 Aug there weren't any radeon drm errors.

And I attache /sys/kernel/debug/vgaswitcheroo/switch, when starting X the radeon card is off: 

0:+:Pwr:0000:00:02.0
1: :Off:0000:01:00.0


Edit:
After boot are both of cards on, so I always switch off the ati card before startx. I do that because with switched on ati card battery life decreases 2 times. But now I left the ati card on, started X and it looks fine, X starts normally. In X I can disable ati card by this command 'echo OFF > /sys/kernel/debug/vgaswitcheroo/switch', so X starts fast and I also save battery life. I don't remember, if I had enabled both cards on 21 Aug, but it looks so.

Logs:
/var/log/Xorg.0.log: http://pastebin.com/V98WbQ9d
strace -T -f startx: http://pastebin.com/WHsKYUYu
dmesg: http://pastebin.com/q1MyRXjh
/var/log/messages.log: http://pastebin.com/cqhWHqXh

Where's the problem actually? In intel drivers or radeon drivers?

Yeah, I don't see anything in those logs to explain what might be causing the 30s delay. It's likely to be some manner of resource conflict but I haven't yet dived in to see if that is possible.

Judging from Dave's comments, this should fix the delay during close():

commit 5222454cf941b09205d502242dd1e44fd62aa551
Author: Dave Airlie <airlied@redhat.com>
Date:   Wed Sep 22 12:31:46 2010 +1000

    drm/radeon: don't allow device to be opened if powered down
    
    If the switcheroo has switched the device off, don't let X open it.
    
    Signed-off-by: Dave Airlie <airlied@redhat.com>

[That's in 2.6.36-rc6.]