Re: powersaved, swsuspend, hotplug und ipw2100

Hallo, On Sat, Jun 19, 2004 at 11:48:31AM +0200, Stefan Müller wrote:

Linux laptop3 2.6.5-7.75-default #1 Mon Jun 14 10:44:37 UTC 2004 i686 i686 i386 GNU/Linux

Hat sich trotzdem verklemmt. Oder soll man die Module statt sie ganz zu entfernen dann trotzdem noch unloaden?

nein, die AGP-Module lassen sich nicht entladen, wenn sie einmal geladen sind. Trotzdem seltsam, da ich seit dem entscheidenden swsuspend-Fix auf keiner Maschine mehr Probleme *wegen den AGP Modulen* hatte.

Ich habe übrigens einen von den neuen Pentium M mit 2MB cache. Die CPU wurde nicht erkannt. speedstep-centrino: found unsupported CPU with Enhanced SpeedStep: send /proc/cpuinfo to Jeremy Fitzhardinge

Ich vermute mal, daß du somit auch keinerlei CPU frequency scaling hast (schlecht, wenn man extra einen Pentium M hat, um Batterie zu sparen :-) versuche mal POWERSAVE_CPUFREQD_MODULE="acpi" in /etc/sysconfig/powersave/common, danach powersaved neu starten oder sogar neu booten (damit keine Modul-"Altlasten" geladen sind), damit sollte zumindest das gehen.

Ich weiß nicht, ob das eine Rolle spielt.

nein, das sollte damit nichts zu tun haben.

...

Da fehlen mir die Meldungen *vor*, *während* und *nach* dem suspend, also nicht erst dann, wenn es nicht mehr geht.

Jun 18 12:03:57 laptop3 kernel: ipw2100: Intel(R) PRO/Wireless 2100 Network Driver, 0.42 Jun 18 12:03:57 laptop3 kernel: ipw2100: Copyright(c) 2003-2004 Intel Corporation Jun 18 12:03:57 laptop3 kernel: Detected ipw2100 PCI device at 0000:02:03.0, dev: eth1, mem: 0xFAFFC000-0xFAFFCFFF -> e2d61000, irq: 7 Jun 18 12:03:57 laptop3 kernel: eth1: Using hotplug firmware load. Jun 18 12:03:57 laptop3 kernel: hostap_crypt: registered algorithm 'WEP' Jun 18 12:03:57 laptop3 kernel: NET: Registered protocol family 17 Jun 18 12:03:57 laptop3 kernel: ipw2100: Associated with 'zuhause' at 11Mbps, channel 11 Jun 18 12:03:57 laptop3 kernel: eth1: Association lost. Jun 18 12:03:57 laptop3 kernel: ipw2100: Associated with 'zuhause' at 11Mbps, channel 11

Das war vorher, also alles bestens. Das kam dann. Reicht das an Infos?

ja. Ich habe den Fehler gefunden. Ich erklär mal die Logs (ich habe einige Zeilen gelöscht :-) Sleep-Knopf gedrückt:

Jun 18 12:07:17 laptop3 [powersaved][5185]: Info: button sleep event occured! Jun 18 12:07:17 laptop3 [powersaved][5208]: Info: Program /usr/sbin/powersave_proxy will be executed for event button.sleep! ACPI line: button/sleep SBTN 00000080 00000001, param: 1 Jun 18 12:07:17 laptop3 [powersave_proxy][5208]: INFO: button.sleep

Proxy bemerkt, daß er für das Ereignis "Sleep-Knopf" die Aktion "suspend" machen soll:

Jun 18 12:07:17 laptop3 [powersave_proxy][5208]: INFO: execute action suspend for event BUTTON_SLEEP

Proxy hat dem daemon gesagt, daß er einen suspend einleiten soll:

Jun 18 12:07:17 laptop3 [powersaved][5185]: Info: Server has been requested to execute suspend action!

Der daemon starten sein helper-skript (proxy), um im userspace alles vorzubereiten:

Jun 18 12:07:17 laptop3 [powersaved][5224]: Info: Program /usr/sbin/powersave_proxy will be executed for event global.suspend! ACPI line: , param: 1 Jun 18 12:07:17 laptop3 [powersave_proxy][5224]: INFO: $POWERSAVE_EVENT_GLOBAL_SUSPEND Jun 18 12:07:17 laptop3 [powersave_proxy][5224]: INFO: execute action prepare_suspend for event GLOBAL_SUSPEND

Der Proxy stoppt die "SERVICES_TO_STOP...":

Jun 18 12:07:17 laptop3 [powersave_proxy][5224]: INFO: Service hotplug stopped

Der Proxy entlädt die "MODULES_TO_UNLOAD", das entladen eines Moduls triggert auch einen Hot(un)plug-event, darum die hotplug-meldungen, hotplug ist ja angehalten:

Jun 18 12:07:17 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

"rmmod ehci_hcd"

Jun 18 12:07:17 laptop3 kernel: ehci_hcd 0000:00:1d.7: remove, state 1 Jun 18 12:07:17 laptop3 kernel: usb usb4: USB disconnect, address 1 Jun 18 12:07:17 laptop3 kernel: ehci_hcd 0000:00:1d.7: USB bus 4 deregistered

"rmmod ieee1394" oder "rmmmod ohci1394" (dazu später mehr):

Jun 18 12:07:17 laptop3 kernel: nodemgr: Exiting due to no down Jun 18 12:07:17 laptop3 kernel: ieee1394: Node removed: ID:BUS[0-00:1023] GUID[464fc0001c7f1030] Jun 18 12:07:17 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:07:17 laptop3 last message repeated 4 times

Die Module sind fertig entladen:

Jun 18 12:07:17 laptop3 [powersave_proxy][5224]: WARNING: Modules unloaded Jun 18 12:07:17 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

Nun werden die IDE-Plattencaches geleert:

Jun 18 12:07:17 laptop3 [powersave_proxy][5224]: INFO: We have a disk: /dev/hda, Execute: blockdev --flushbufs /dev/hda Jun 18 12:07:17 laptop3 [powersaved][5223]: Info: END OF PROXY OUTPUT Jun 18 12:07:17 laptop3 [powersaved][5223]: Info: Program /usr/sbin/powersave_proxy for event global.suspend exited with status 0

Der proxy meldet keine Fehler, also macht der daemon weiter und schickt dem Kernel den suspend-Befehl:

Jun 18 12:07:17 laptop3 [powersaved][5223]: DIAG in Function executeEvent, line 1428: SET do suspend to 1 Jun 18 12:07:17 laptop3 [powersaved][5185]: Info: Set machine into suspend (S4) mode! Jun 18 12:08:27 laptop3 kernel: Stopping tasks: ============================================================================================| Jun 18 12:08:27 laptop3 kernel: Freeing memory: .....| Jun 18 12:08:27 laptop3 kernel: .| Jun 18 12:08:27 laptop3 last message repeated 3 times Jun 18 12:08:27 laptop3 kernel: /critical section: Handling highmem Jun 18 12:08:27 laptop3 kernel: counting pages to copy.....[nosave c038c000][nosave c038d000][nosave c038e000]......................................................................................................................................................................................................................................................................... Jun 18 12:08:27 laptop3 kernel: (pages needed: 32278+512=32790 free: 98709) Jun 18 12:08:27 laptop3 kernel: Alloc pagedir Jun 18 12:08:27 laptop3 kernel: .....[nosave c038c000][nosave

Mitten in der Nächsten Zeile ist die Stelle, wo es nach dem suspend direkt beim resume weitergeht. Nach der "]" ist die Speicherkopie erzeugt, die beim resume wieder eingelesen wird. Die Meldungen die beim Suspend danach noch erzeugt werden gehen verloren. "Freeing..." ist schon während des resume.

c038d000][nosave c038e000]Freeing prev allocated pagedir Jun 18 12:08:27 laptop3 kernel: Restoring highmem Jun 18 12:08:27 laptop3 kernel: done, devices

Der kernel aktiviert die Device-Treiber wieder (die nicht entladenen):

Jun 18 12:08:27 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1d.0 to 64 Jun 18 12:08:27 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1d.1 to 64 Jun 18 12:08:27 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1d.2 to 64 Jun 18 12:08:27 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1d.7 to 64 Jun 18 12:08:27 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1f.5 to 64 Jun 18 12:08:27 laptop3 kernel: blk: queue dfca3600, I/O limit 4095Mb (mask 0xffffffff) Jun 18 12:08:27 laptop3 kernel: Fixing swap signatures... ok Jun 18 12:08:27 laptop3 kernel: Restarting tasks...<6>usb 2-1: USB disconnect, address 2 Jun 18 12:08:27 laptop3 kernel: done

Die Treiber sind wieder aktiv und bemerken, daß sie wieder da sind:

Jun 18 12:08:27 laptop3 kernel: usb 2-1: new low speed USB device using address 3

Auch der powersaved kriegt das so langsam mit...

Jun 18 12:08:27 laptop3 [powersaved][5185]: Info: Back from suspend again! Jun 18 12:08:27 laptop3 kernel: usb 2-1: Product: USB-PS/2 Optical Mouse Jun 18 12:08:27 laptop3 kernel: usb 2-1: Manufacturer: Logitech Jun 18 12:08:27 laptop3 kernel: input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.1-1

... also wirft er einen resume event...

Jun 18 12:08:28 laptop3 [powersaved][5185]: DIAG in Function executeEvent, line 1450: Executed event: global.resume.suspend Jun 18 12:08:29 laptop3 [powersaved][5185]: WARNING in Function start; line 387: Select returned an Error, but not interrupted through a signal: Success! This is not nice, but normal after a suspend!

... und startet den proxy, um im userspace wieder aufzuräumen:

Jun 18 12:08:29 laptop3 [powersaved][5359]: Info: Program /usr/sbin/powersave_proxy will be executed for event global.resume.suspend! ACPI line: , param: 1

Hotplug ist noch gestoppt:

Jun 18 12:08:31 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:31 laptop3 last message repeated 9 times

der Proxy tritt in aktion:

Jun 18 12:08:32 laptop3 [powersave_proxy][5359]: INFO: global.resume.suspend Jun 18 12:08:32 laptop3 [powersave_proxy][5359]: INFO: execute action restore_after_suspend for event GLOBAL_RESUME_SUSPEND Jun 18 12:08:33 laptop3 [powersave_proxy][5359]: INFO: Adjust clock from: 06/18/04__12:08 Jun 18 12:08:33 laptop3 [powersave_proxy][5359]: INFO: Adjusted clock to: 06/18/04__12:08

Erst lädt er die Module...

Jun 18 12:08:34 laptop3 kernel: ipw2100: Intel(R) PRO/Wireless 2100 Network Driver, 0.42 Jun 18 12:08:34 laptop3 kernel: ipw2100: Copyright(c) 2003-2004 Intel Corporation Jun 18 12:08:34 laptop3 kernel: Detected ipw2100 PCI device at 0000:02:03.0, dev: eth1, mem: 0xFAFFC000-0xFAFFCFFF -> e2940000, irq: 7

... hotplug ist aber noch aus...

Jun 18 12:08:34 laptop3 kernel: eth1: Using hotplug firmware load. Jun 18 12:08:34 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:34 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:34 laptop3 [powersaved][5185]: Info: Server has been pinged, ping will be ignored! Jun 18 12:08:34 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:36 laptop3 last message repeated 2 times Jun 18 12:08:37 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:38 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:39 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:41 laptop3 last message repeated 2 times Jun 18 12:08:42 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:43 laptop3 kernel: ipw2100: attempt to use fw ordinals before they have been loaded. Jun 18 12:08:44 laptop3 kernel: eth1: Firmware not available or load failed Jun 18 12:08:44 laptop3 kernel: eth1: ipw2100_get_firmware failed: -2 Jun 18 12:08:44 laptop3 kernel: eth1: Failed to power on the adapter. Jun 18 12:08:44 laptop3 kernel: eth1: Failed to start the firmware. Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 kernel: ipw2100: probe of 0000:02:03.0 failed with error -5 Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

weitere Module (firewire):

Jun 18 12:08:44 laptop3 kernel: ieee1394: Initialized config rom entry `ip1394' Jun 18 12:08:44 laptop3 kernel: ohci1394: $Rev: 1203 $ Ben Collins Jun 18 12:08:44 laptop3 kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[11] MMIO=[faffd800-faffdfff] Max Packet=[2048] Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 kernel: ehci_hcd 0000:00:1d.7: EHCI Host Controller Jun 18 12:08:44 laptop3 kernel: PCI: Setting latency timer of device 0000:00:1d.7 to 64 Jun 18 12:08:44 laptop3 kernel: ehci_hcd 0000:00:1d.7: irq 11, pci mem e2942c00 Jun 18 12:08:44 laptop3 kernel: ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 4 Jun 18 12:08:44 laptop3 kernel: PCI: cache line size of 32 is not supported by device 0000:00:1d.7 Jun 18 12:08:44 laptop3 kernel: ehci_hcd 0000:00:1d.7: USB 2.0 enabled, EHCI 1.00, driver 2003-Dec-29 Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

ehci_hcd:

Jun 18 12:08:44 laptop3 kernel: usb usb4: Product: EHCI Host Controller Jun 18 12:08:44 laptop3 kernel: usb usb4: Manufacturer: Linux 2.6.5-7.75-default ehci_hcd Jun 18 12:08:44 laptop3 kernel: usb usb4: SerialNumber: 0000:00:1d.7 Jun 18 12:08:44 laptop3 kernel: hub 4-0:1.0: USB hub found Jun 18 12:08:44 laptop3 kernel: hub 4-0:1.0: 6 ports detected Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

Die Module sind geladen:

Jun 18 12:08:44 laptop3 [powersave_proxy][5359]: DIAG: Modules loaded Jun 18 12:08:44 laptop3 kernel: usb 2-1: USB disconnect, address 3 Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start

Die gestoppten Dienste (hotplug...) werden wieder gestartet:

Jun 18 12:08:44 laptop3 [powersave_proxy][5359]: DIAG: Service hotplug started again

warum diese Meldung noch kommt, ist mir etwas unklar, aber ich vermute, die sind so etwa gleichzeitig und syslog sortiert die falsch, oder das starten von Hotplug geht nicht ganz verzögerungsfrei:

Jun 18 12:08:44 laptop3 /sbin/hotplug-stopped[0]: hotplugging not enabled. Run rchotplug start Jun 18 12:08:44 laptop3 last message repeated 2 times Jun 18 12:08:44 laptop3 [powersaved][5358]: Info: END OF PROXY OUTPUT

Proxy ist fertig...

Jun 18 12:08:44 laptop3 [powersaved][5358]: Info: Program /usr/sbin/powersave_proxy for event global.resume.suspend exited with status 0

...und alles war i.O.

Jun 18 12:08:45 laptop3 kernel: usb 2-1: new low speed USB device using address 4 Jun 18 12:08:45 laptop3 kernel: usb 2-1: Product: USB-PS/2 Optical Mouse Jun 18 12:08:45 laptop3 kernel: usb 2-1: Manufacturer: Logitech Jun 18 12:08:45 laptop3 kernel: input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:1d.1-1 Jun 18 12:08:45 laptop3 /etc/hotplug/usb.agent[5606]: need a device for this command

und hier geht auch hotplug wieder:

Jun 18 12:08:45 laptop3 /sbin/hotplug[5683]: /etc/hotplug/ieee1394.agent: line 22: VENDOR_ID: Bad invocation:

...

...

Das Problem scheint zu sein, daß das hotplugging nach dem suspend nicht mehr funktioniert. Einsetzen der Module per Hand hilft auch nicht und

hotplug sollte wieder gestartet werden.

Ich fasse den Ablauf nochmal kurz zusammen: 1. Dienste anhalten 2. Module entladen 3. suspend / resume 4. Module laden 5. Dienste starten. Das ist in auch prinzipiell OK, denn ich kann die dienste ja erst wieder starten, wenn auch die benötigten Module wieder geladen sind. Dummerweise brauchen wir aber hotplug, um die Module wieder zu laden, nicht nur für ipw2100 sondern für z.B. alle Netzwerkkartenmodule, da das Interface von Hotplug hochgefahren wird, wenn das Modul eingefügt wird. Also braucht hotplug eine Sonderbehandlung. Wieso muss hotplug überhaupt angehalten werden? Das entladen eines Moduls triggert einen Hotplug-event, der oftmals auf umwegen zum umgehenden neu- Laden des Moduls führt. Der einfachste Ausweg ist, Hotplug anzuhalten. Die schnelle Lösung für dich ist, in /usr/sbin/powersave_proxy in der Funktion "restore_after_suspend()" *vor* "Load Modules" ein /etc/init.d/hotplug start einzutragen, damit das rechtzeitig gestartet wird. In den bisher unveröffentlichten neueren powersave-Versionen ist das noch besser gelöst, indem hotplug früher gestartet wird, aber nur wenn er auch wirklich beim suspend angehalten wurde, aber diese Überprüfung ist praktisch irrelevant, einfach vor Zeile 637 das "hotplug start" einfügen und es sollte funktionieren.

Ja, das habe ich auch mal probiert, aber danach ging die Karte auch nicht. Wahrscheinlich hat es sich da dann verklemmt, weil die Module teilweise schon geladen waren, auch neuladen half nicht.

Tja, und dann gibt es auch noch Hardware, die nach dem resume nicht mehr will, auch wenn die Module neu geladen werden. Wenn es dumm läuft, ist der ipw2100 so einer. Dann müssen wir das wohl debuggen, aber schauen wir erst mal, vielleicht reicht der hack in powersave_proxy ja schon. Oder vielleicht muss es ja gar nicht mehr entladen werden? Ich habe das aber noch nicht ausprobiert.

...

geht es vor dem suspend denn?

Ja, vorher alles prima, danach alles mysteriös =;-).

Ok, ging es denn mit dem alten kernel nach dem suspend? Damit wir die Schuldigen einkreisen können :-)

Nee, das habe ich alles mit YOU runtergeladen und installiert und die Karte funktioniert.

gut.

...

oder es ist sonst was faul...

Ja, wahrscheinlich.

Nunja, einen stark Verdächtigen haben wir schon mal. So, und nun zur Belohnung für alle, die bis hierher durchgehalten haben noch etwas nützliches für alle: Das Modul "ohci1394" muss mit dem neuen Kernel nicht mehr vor dem suspend entladen werden. Im Gegenteil, es schadet eher, denn es gibt noch ein paar mysteriöse Nebenwirkungen, wenn man es nach dem resume nochmals entfernt und wieder einfügt. Also sollte es aus "MODULES_TO_UNLOAD..." herausgenommen werden. Meine /etc/sysconfig/powersave/common enthält momentan POWERSAVE_UNLOAD_MODULES_BEFORE_SUSPEND="ohci_hcd b44 ehci_hcd bcm4400 ipw2100 button" button brauche ich auf vielen Maschinen, damit der Powerbutton nach dem resume noch funktioniert. Wenn wir das haben, dann schauen wir mal, was es mit deinen AGP Module auf sich hat... :-) Viel Erfolg -- Stefan Seyfried