Bug 29384

Created attachment 37544 [details] [review]
dmesg after bootup

Created attachment 37545 [details] [review]
dmesg after resuspend

Of course I have the problem with delayed resuspend "atombios stuck", too.

Did the patch in bug 27744 help?  If not, can you use git bisect between 2.6.34 and 2.6.35 and track down which commit causes the problem?

Thank you for your help.
But the answer is "No". I doesn't fix the slow resuspend (instead it feels slower, no wonder...) and also not the slow TTY-Switch between the terminals if /def/fb* is used. Both problems still exist.

To be honestly. Making a delay just longer doesn't look like a well solution.

Here is my dmesg output, maybe it helps (last lines):
PM: early resume of devices complete after 0.753 msecs
ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:1a.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
HDA Intel 0000:00:1b.0: setting latency timer to 64
ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
pci 0000:00:1e.0: setting latency timer to 64
ehci_hcd 0000:00:1d.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: irq 45 for MSI/MSI-X
ahci 0000:00:1f.2: setting latency timer to 64
pci 0000:00:1f.3: PCI INT C -> GSI 18 (level, low) -> IRQ 18
radeon 0000:02:00.0: setting latency timer to 64
HDA Intel 0000:02:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: setting latency timer to 64
ath9k 0000:05:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: irq 46 for MSI/MSI-X
sd 0:0:0:0: [sda] Starting disk
[drm] Clocks initialized !
[drm] ring test succeeded in 1 usecs
[drm] ib test succeeded in 0 usecs
usb 2-1.5: reset high speed USB device using ehci_hcd and address 3
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1.00: configured for UDMA/133
[drm:atom_op_jump] *ERROR* atombios stuck in loop for more than 5secs aborting
[drm:atom_execute_table_locked] *ERROR* atombios stuck executing CB5A (len 67, WS 0, PS 0) @ 0xCB89
PM: resume of devices complete after 7531.240 msecs
Restarting tasks ... done.
video LNXVIDEO:00: Restoring backlight state
	[ pm_notifier_block : 170 ] event :4

atl1c 0000:03:00.0: irq 47 for MSI/MSI-X
ADDRCONF(NETDEV_UP): eth0: link is not ready
ADDRCONF(NETDEV_UP): wlan0: link is not ready
EXT4-fs (sda1): re-mounted. Opts: commit=0
EXT4-fs (sda2): re-mounted. Opts: commit=0
ath9k: Two wiphys trying to scan at the same time
ath9k: Two wiphys trying to scan at the same time
wlan0: deauthenticating from 00:1c:10:36:48:42 by local choice (reason=3)
wlan0: authenticate with 00:1c:10:36:48:42 (try 1)
wlan0: authenticated
wlan0: associate with 00:1c:10:36:48:42 (try 1)
wlan0: RX AssocResp from 00:1c:10:36:48:42 (capab=0x431 status=0 aid=1)
wlan0: associated
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan0: no IPv6 routers present

Just to notice:
Switch from X11 to TTY1-6 is also still affected.
Switch from TTY1-6 to X11 is, like before, normal - this means: immediately

Switching from a TTY without access to /dev/fb* to a TTY with access (running fbida or mplayer) is immediately. Switching from a TTY with access (running fbida or mplayer) is slow. Closing fbida with "q" is also slow.
Closing of mplayer with "strg+c" is not possible. mplayer is it totally freaking out.

Notice:
With the patch resuspend need ~7 seconds.
Withtout the patch resuspend needs ~ 3 seconds.

With old kernel 2.6.34 resuspend need ~ 1 second.

Can you use git bisect between 2.6.34 and 2.6.35 and track down which commit causes the problem?

I am awfully sorry, but I am not familiar with git/git-bitsect.
Of course I will try every patch you can over and give you as much as possible details about the effect.

(In reply to comment #9)
> I am awfully sorry, but I am not familiar with git/git-bitsect.
> Of course I will try every patch you can over and give you as much as possible
> details about the effect.

It's very easy. Assuming you have a git tree checked out:

git bisect start
git bisect good v2.6.34
git bisect bad v2.6.35

After that git will walk you through the rest.  It will check out the appropriate commit, at which point you can compile it, test it, and if it's good, run:
git bisect good
and if it's bad:
git bisect bad
and git will select the next commit and the process continues.  If there is a commit that doesn't boot or build, you can skip it with:
git bisect skip

See this page for more info:
http://www.kernel.org/pub/software/scm/git/docs/git-bisect.html

I will try this, but I will have first freetime at weekend.
Here another very interesting fact:

I've I boot up the machine, then -> pm-suspend ->resuspend "stuck atombios"
Result:
I have no problem with switching between the TTY1-6 and X11, also fbida and mplayer work like the should! But I *MUST* use pm-suspend at first to "Suspend to RAM" for a first time. After this first "Suspend to RAM" everything works perfect, only the "stuck atombios"-message delays the resuspend.

WTF?

Okay, let's go:
$ mkdir project; cd project/linux-2.6
$ git clone git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git linux-2.6
$ git bisect start -- drivers/gpu/drm/radeon /*thought this must be a bug in "radeon"*/
$ git bisect good v.2.6.34
$ git bisect bad v2.6.35
Bisecting: 79 revisions left to test after this (roughly 6 steps)
[ce8a3eb20c4cb7d9e0c33e7560070688cd9066fc] drm/radeon/kms/pm: make pm spam debug only


This told me, that are 79 patches in "radeon" and gave me the first one. Because I am new with "git" I decided to start not in the middle (around patch 40), instead with the first patch (want to see how it works). The result is that both bugs 29384 and 27744 are inside!

See new dmesg after resuspend:

PM: early resume of devices complete after 0.837 msecs
ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:1a.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
HDA Intel 0000:00:1b.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: irq 29 for MSI/MSI-X
ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
ehci_hcd 0000:00:1d.0: setting latency timer to 64
pci 0000:00:1e.0: setting latency timer to 64
ahci 0000:00:1f.2: setting latency timer to 64
pci 0000:00:1f.3: PCI INT C -> GSI 18 (level, low) -> IRQ 18
radeon 0000:02:00.0: setting latency timer to 64
HDA Intel 0000:02:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: setting latency timer to 64
ath9k 0000:05:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: irq 30 for MSI/MSI-X
sd 0:0:0:0: [sda] Starting disk
[drm] Clocks initialized !
[drm] ring test succeeded in 1 usecs
radeon 0000:02:00.0: no free indirect buffer !
[drm:r600_ib_test] *ERROR* radeon: failed to get ib (-16).
[drm:evergreen_resume] *ERROR* radeon: failled testing IB (-16).
usb 2-1.5: reset high speed USB device using ehci_hcd and address 4
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1.00: configured for UDMA/133
PM: resume of devices complete after 2312.599 msecs
Restarting tasks ... done.
video LNXVIDEO:00: Restoring backlight state
	[ pm_notifier_block : 171 ] event :4

atl1c 0000:03:00.0: irq 31 for MSI/MSI-X
ADDRCONF(NETDEV_UP): eth0: link is not ready
ADDRCONF(NETDEV_UP): wlan0: link is not ready
ath9k: Two wiphys trying to scan at the same time
ath9k: Two wiphys trying to scan at the same time
wlan0: deauthenticating from 00:1c:10:36:48:42 by local choice (reason=3)
wlan0: authenticate with 00:1c:10:36:48:42 (try 1)
wlan0: authenticated
wlan0: associate with 00:1c:10:36:48:42 (try 1)
wlan0: RX AssocResp from 00:1c:10:36:48:42 (capab=0x431 status=0 aid=1)
wlan0: associated
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan0: no IPv6 routers present




Error message differs, but there is the same bug!?
I added complete dmesg (bootup,suspend, resuspend).

I think the bug must somewhere else outside "drives/gpu/drm/radeon",  but where?

$ git bisect good v2.6.34 /*of course*/

Created attachment 37667 [details]
complete run of dmesg after bootup, suspend and resuspend

Created attachment 37668 [details]
.config of kernel 2.6.34 with first patch in directory radeon

Reading helps...
bisect looks for revisions, not for single patches.
But that doesn't change the above context.

$ mkdir project; cd project/linux-2.6
$ git clone
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git linux-2.6
$ git bisect start /*now I'am testing everythin*/
$ git bisect good v.2.6.34
$ git bisect bad v2.6.35
Bisecting: 5279 revisions left to test after this (roughly 12 steps)
[e0bc5d4a54938eedcde14005210e6c08aa9727e4] Merge branch 'i2c-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jdelvare/staging

->
Here it compiled the kernel, this kernel works fine!

Bisecting: 2639 revisions left to test after this (roughly 11 steps)
[d30fda355188272430d3865db2ff9e24b4135ae3] posix-cpu-timers: avoid "task->signal != NULL" checks

->
I've got it!
This revision has both bugs!
Added new dmesg_2639revisions_roughly11steps

Created attachment 37675 [details] [review]
dmesg of revision which includes the bug(s)

Please take the bisection to the end.  if a commit is broken, mark it bad (git bisect bad) if it's working, mark it good (git bisect good), if you can't compile it or it won't boot, skip it (git bisect skip). at the end it should identify the exact commit which caused the problem.

'git bisect reset' will reset your tree when you are finished bisecting.

Okay!


[peter@timeline linux-2.6]$ git bisect log
git bisect start '--' 'drivers/gpu/drm/radeon'
# good: [e40152ee1e1c7a63f4777791863215e3faa37a86] Linus 2.6.34
git bisect good e40152ee1e1c7a63f4777791863215e3faa37a86
# bad: [9fe6206f400646a2322096b56c59891d530e8d51] Linux 2.6.35
git bisect bad 9fe6206f400646a2322096b56c59891d530e8d51
# bad: [ce8a3eb20c4cb7d9e0c33e7560070688cd9066fc] drm/radeon/kms/pm: make pm spam debug only
git bisect bad ce8a3eb20c4cb7d9e0c33e7560070688cd9066fc
# good: [f405a1ab2bf316b1969fc5355891e5dff4e1a54c] drivers/gpu/drm: Use kmemdup
git bisect good f405a1ab2bf316b1969fc5355891e5dff4e1a54c
# good: [2aba631c008e7d82e3ec45dd32bec1ea63a963cf] radeon: Unify PM entry paths
git bisect good 2aba631c008e7d82e3ec45dd32bec1ea63a963cf
# good: [539d24181753e40174746d576d415bfb56131975] drm/radeon/kms: more pm fixes
git bisect good 539d24181753e40174746d576d415bfb56131975
# good: [91700f3cac56a1998a56d41e4459a5cebdb4f752] radeon: Split out ring locking and allocation
git bisect good 91700f3cac56a1998a56d41e4459a5cebdb4f752
# good: [ca2af92311eee95820f3b48c35045e5f56bc1477] drm/radeon/kms: fix lock ordering in ring, ib handling
git bisect good ca2af92311eee95820f3b48c35045e5f56bc1477
# bad: [ce8f53709bf440100cb9d31b1303291551cf517f] drm/radeon/kms/pm: rework power management
git bisect bad ce8f53709bf440100cb9d31b1303291551cf517f
# good: [d7311171c4cc8d6231427f7ac5056b939a184b80] drm/radeon/kms/pm: add support for no display power states
git bisect good d7311171c4cc8d6231427f7ac5056b939a184b80
# good: [d7311171c4cc8d6231427f7ac5056b939a184b80] drm/radeon/kms/pm: add support for no display power states
git bisect good d7311171c4cc8d6231427f7ac5056b939a184b80

[peter@timeline linux-2.6]$ git bisect good
ce8f53709bf440100cb9d31b1303291551cf517f is the first bad commit
commit ce8f53709bf440100cb9d31b1303291551cf517f
Author: Alex Deucher <alexdeucher@gmail.com>
Date:   Fri May 7 15:10:16 2010 -0400

    drm/radeon/kms/pm: rework power management
    
    - Separate dynpm and profile based power management methods.  You can select the pm method
      by echoing the selected method ("dynpm" or "profile") to power_method in sysfs.
    - Expose basic 4 profile in profile method
      "default" - default clocks
      "auto" - select between low and high based on ac/dc state
      "low" - DC, low power mode
      "high" - AC, performance mode
      The current base profile is "default", but it should switched to "auto" once we've tested
      on more systems.  Switching the state is a matter of echoing the requested profile to
      power_profile in sysfs.  The lowest power states are selected automatically when dpms turns
      the monitors off in all states but default.
    - Remove dynamic fence-based reclocking for the moment.  We can revisit this later once we
      have basic pm in.
    - Move pm init/fini to modesetting path.  pm is tightly coupled with display state.  Make sure
      display side is initialized before pm.
    - Add pm suspend/resume functions to make sure pm state is properly reinitialized on resume.
    - Remove dynpm module option.  It's now selectable via sysfs.
    
    Signed-off-by: Alex Deucher <alexdeucher@gmail.com>
    Signed-off-by: Dave Airlie <airlied@redhat.com>

:040000 040000 fa3acba12b9886453c2de619577ae633abfc97bc faf940f2c2791f1382ed1abbfa54e22df7e1c936 M	drivers


Here I got the problem with to slow switch between tty1-tty6 if /dev/fb* is in use by a program (example: fbida with an png image)
Is this what you need?





Just a note to the other bug 27744 "stuck atombios"
After:
Bisecting: 39 revisions left to test after this (roughly 5 steps)
[f405a1ab2bf316b1969fc5355891e5dff4e1a54c] drivers/gpu/drm: Use kmemdup
herebiosbug_butnotswitchbug (END) 
I got this dmesg output after resuspend:
PM: early resume of devices complete after 0.838 msecs
ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:1a.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
HDA Intel 0000:00:1b.0: setting latency timer to 64
HDA Intel 0000:00:1b.0: irq 29 for MSI/MSI-X
ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
ehci_hcd 0000:00:1d.0: setting latency timer to 64
pci 0000:00:1e.0: setting latency timer to 64
ahci 0000:00:1f.2: setting latency timer to 64
pci 0000:00:1f.3: PCI INT C -> GSI 18 (level, low) -> IRQ 18
radeon 0000:02:00.0: setting latency timer to 64
HDA Intel 0000:02:00.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: setting latency timer to 64
ath9k 0000:05:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
HDA Intel 0000:02:00.1: irq 30 for MSI/MSI-X
sd 0:0:0:0: [sda] Starting disk
[drm] Clocks initialized !
[drm] ring test succeeded in 1 usecs
radeon 0000:02:00.0: no free indirect buffer !
[drm:r600_ib_test] *ERROR* radeon: failed to get ib (-16).
[drm:evergreen_resume] *ERROR* radeon: failled testing IB (-16).
usb 2-1.5: reset high speed USB device using ehci_hcd and address 3
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1.00: configured for UDMA/133
PM: resume of devices complete after 419.798 msecs
Restarting tasks ... done.
video LNXVIDEO:00: Restoring backlight state
        [ pm_notifier_block : 171 ] event :4

atl1c 0000:03:00.0: irq 31 for MSI/MSI-X
ADDRCONF(NETDEV_UP): eth0: link is not ready
ADDRCONF(NETDEV_UP): wlan0: link is not ready
ath9k: Two wiphys trying to scan at the same time

If I have more time I will try to found the reason for this, too. And post it in 27744.

Does the patch I attached to bug 27744 help?
https://bugs.freedesktop.org/attachment.cgi?id=37733

I will try the patch tomorrow!

I'am sorry, the patch doesn't fix 29384 and 27744.
The system reacts like before, dmesg output is also exactly the same.


To new hints/quesitions:
With 2.6.34 I had no delay while loading the ATOMBIOS, if feels "smooth". I see some kernel-messages at bootup in standard vga-resolution and the kernel switches immidiatley to 1380x768 (my native display resolution).
Instead with 2.6.35 is see the bootup-message from kernel
"Linux agpgart interface v0.103
[drm] Initialized drm 1.1.0 20060810
[drm] radeon defaulting to kernel modesetting.
[drm] radeon kernel modesetting enabled." in resolution  640x480 standard vga,
than I got a blank screen with a delay and some seconds after this I see the next bootup-messages.

Is it correct the the Radeon-Driver in the kernel creat all this frequencq-scaling stuff under /sys with a Evergreen GPU. I tought this is only supported till R700 GPUs?
Of course this could be just some generic stuff.

I mean "immediatley"

In Comment 11 I describe a workaround, which seems to be based on Bug 27744.
Boot up -> pm-suspend -> resuspend -> switching works fine

This requires a plug off power-cord, my laptop must run only on battery at the time! I think this is no wonder, because the bug was introduced with that commit:
Date:   Fri May 7 15:10:16 2010 -0400
drm/radeon/kms/pm: rework power management

Now it gets funny:
If I replug the power-cord, the "slow-switching" appears again!

Okay. All the people with this bug and the stuck-atombios have radeon mobility-cards!

Solution found for bug 29384!
I noticed that everything looks like the kernel uses the new power-managment-stuff also for the Evergreen graphics cards. And this leads to the solution, the power_method "profile" doesn't work correct, the all problems with slow switching while using /dev/fb* with fbi or mplayer are solved with switching the power_method to "dynpm".

$ echo "dynpm" > /sys/class/drm/card0/device/power_method
check with 
$ cat /sys/class/drm/card0/device/power_method" //should report dynpm

Now everything works.
I can load a png-image with fbi on tty1, check dmesg output on tty2, while I am watching a ioQuake3-Demo (of course without hardware-accleration) on X11. If necessary I can use "pm-supend" and wakeup the system again, everything still works.

@Alex Deucher:
Could it be a final solution
a) generally set "dynpm" for all Evergreen chips
or
b) switching of power-managment for Evergreen till is really supported in the kernel


Now the bad news:
Using dynpm doesn't fix bug 27744
Further information:
http://www.x.org/wiki/radeonBuildHowTo#Troubleshootingradeonpower-management

Created attachment 37899 [details] [review]
possible fix

Does the attached patch fix the issue?

Yes it does! Good work, thank you!
Tested with Kernel 2.6.26-rc1 + patch https://bugs.freedesktop.org/attachment.cgi?id=37899

Switching beetween all TTYs and X11 works fine, with use of /dev/fb* through fbida or mplayer. Suspend with pm-suspend and gnome-power-manager and Resuspend works also fine.

A fair question:
Did my "work" here helped?
A second one:
Will this patch included in 2.6.36-rc2?

Bye and thanks!

PS: Of course I got still the "atombios stuck" message in the output of dmesg, but it seems finally nothing to do with this bug.

(In reply to comment #30)
> Yes it does! Good work, thank you!

good.

> A fair question:
> Did my "work" here helped?

Of course. Thanks for sticking with this.  I know bisecting can be a lot of work.

> A second one:
> Will this patch included in 2.6.36-rc2?

Yes, I've already sent the patch to Dave for 2.6.36 and stable.

Linus didn't included the patch in rc2.
Typicall delay?

(In reply to comment #32)
> Linus didn't included the patch in rc2.
> Typicall delay?

The pull request just went out today, so it should show up as soon as Linus pulls it.

Great!
This bug has one good side, I learned much stuff.