Powersave-Fehler/ massives syslog nach 9.3-Update auf Toshiba Tecra S1
Hi! Ich hab' mal wieder ein Update gewagt auf meinem Toshiba Tecra S1: SuSE 9.2 auf SuSE 9.3. Nun versucht mir der powersave beliebig oft/ beliebig schnell ins syslog zu schreiben und führt sich damit selbst ad absurdum: 100% CPU-Last und CPU bei vollen 1500MHz statt bei 600MHz. Natürlich Lüfter an usw. bree:~ # rcpowersaved start loading ACPI modules () done Starting powersaved (accessing ACPI events over acpid) done /var/log/messages: Jul 2 02:31:40 bree [powersave][10245]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 2 02:32:10 bree last message repeated 1006775 times Jul 2 02:33:12 bree last message repeated 2070566 times Jul 2 02:34:12 bree last message repeated 2070483 times Jul 2 02:35:13 bree last message repeated 2066511 times Wenn ich powersaved wieder stoppe ist der Spuk vorbei, aber unter KDE bekomme ich Mecker, dass powersaved nicht läuft. Außerdem kann ich mir nicht vorstellen, dass das "normal" sein kann! ;-) Selbstverfreilich hat powersave unter SuSE 9.2 zur Zufriedenheit funktioniert... Hat mal wer 'nen Tip wo ich dran schrauben kann? -- Eat, sleep and go running, David Hücking. Encrypted eMail welcome! GnuPG/ PGP-Key: 0x57809216. Fingerprint: 3DF2 CBE0 DFAA 4164 02C2 4E2A E005 8DF7 5780 9216 -- Weitersagen: GMX DSL-Flatrates mit Tempo-Garantie! Ab 4,99 Euro/Monat: http://www.gmx.net/de/go/dsl
On Sat, Jul 09, 2005 at 12:28:43AM +0200, "David Hücking" wrote:
/var/log/messages: Jul 2 02:31:40 bree [powersave][10245]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 2 02:32:10 bree last message repeated 1006775 times
Das ist der dazugehörige Code: req.tv_sec = config->current_scheme->POLL_INTERVAL / 1000; req.tv_usec = config->current_scheme->POLL_INTERVAL * 1000 % 1000000; gettimeofday(&tv_start, &dummy); for (;;){ do{ temp_fd_set=fd_set_reading; // if no cpufreq and no battery is supported do not poll at all! if (cur_state.BAT_STATE == BAT_NONE_STATE && !CPUFreq_Interface::isSupported() && !acpidDied){ pDebug(DBG_DEBUG, "Select waiting without timeout, polling disabled.\n" "No battery and no cpufreq have been detected.\n"); ret = select (max_FD_value+1, &temp_fd_set, NULL, NULL, NULL); } else{ pDebug(DBG_DEBUG, "Select waiting: %u secs and %u millisecs\n", (unsigned)req.tv_sec, (unsigned)req.tv_usec / 1000); ret = select (max_FD_value+1, &temp_fd_set, NULL, NULL, &req); } if (ret < 0){ if (errno == EINTR){ pDebug(DBG_DEBUG, "Select returned with EINTR, continue\n"); continue; } // be careful after suspend select may return x < 0, but errno is not set! // for now I ignore the set file descriptor(for not waiting endlessly on socket // and continue. Maybe we should try a poll implementation here later... else{ pDebug(DBG_WARN, "Select returned an Error, " "but not interrupted through a signal: %s" " This is not nice, but normal after a suspend2disk\n", strerror(errno)); Das einzige was mir dazu einfallen würde, warum select hier ein "invalid argument" liefern sollte, wäre ein verwirrter Timeout. Was steht denn in POWERSAVED_POLLING_INTERVAL in /etc/sysconfig/powersave/common? Ansonsten starte den powersaved mal mit dem höchsten debuglevel (31), am besten manuell: rcpowersaved stop /usr/sbin/powersaved -x /usr/lib/powersave/scripts -a resmgr -v 31 (nach ein paar sekunden schnell strg-c drücken) danach mal schauen, in welchem select-zweig er war ("Select waiting without timeout" oder "Select waiting: xxx secs and yyy millisecs").
Jul 2 02:33:12 bree last message repeated 2070566 times
Hm, das sind ja nur 35000 Läufe des mainloops pro sekunde, ich muß den Code doch mal optimieren ;-)
Selbstverfreilich hat powersave unter SuSE 9.2 zur Zufriedenheit funktioniert... Hat mal wer 'nen Tip wo ich dran schrauben kann?
Laß uns erst mal die Spuren sichern ;-) -- Stefan Seyfried
On Sat, Jul 09, 2005 at 12:28:43AM +0200, "David Hücking" wrote:
/var/log/messages: Jul 2 02:31:40 bree [powersave][10245]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 2 02:32:10 bree last message repeated 1006775 times
Das ist der dazugehörige Code:
req.tv_sec = config->current_scheme->POLL_INTERVAL / 1000; req.tv_usec = config->current_scheme->POLL_INTERVAL * 1000 % 1000000; gettimeofday(&tv_start, &dummy); for (;;){ do{ temp_fd_set=fd_set_reading;
// if no cpufreq and no battery is supported do not poll at all! if (cur_state.BAT_STATE == BAT_NONE_STATE && !CPUFreq_Interface::isSupported() && !acpidDied){ pDebug(DBG_DEBUG, "Select waiting without timeout, polling disabled.\n" "No battery and no cpufreq have been detected.\n"); ret = select (max_FD_value+1, &temp_fd_set, NULL, NULL, NULL); } else{ pDebug(DBG_DEBUG, "Select waiting: %u secs and %u millisecs\n", (unsigned)req.tv_sec, (unsigned)req.tv_usec / 1000); ret = select (max_FD_value+1, &temp_fd_set, NULL, NULL, &req); } if (ret < 0){ if (errno == EINTR){ pDebug(DBG_DEBUG, "Select returned with EINTR, continue\n"); continue; } // be careful after suspend select may return x < 0, but errno is not set! // for now I ignore the set file descriptor(for not waiting endlessly on socket // and continue. Maybe we should try a poll implementation here later... else{ pDebug(DBG_WARN, "Select returned an Error, " "but not interrupted through a signal: %s" " This is not nice, but normal after a suspend2disk\n", strerror(errno)); OK, den Code rund um die for-Schleife in der powersaved.cpp hatte ich mir auch angeguckt, aber da ich bisher keinen Hintergrund zu all dem habe, was man da
allo! - Das mag ich hier so: nahezu sofort kompetente Antworten und Hilfe(-Versuche)! Super. On Sonntag 10 Juli 2005 22:03, Stefan Seyfried wrote: per select abfragen kann... sicherlich eine längere Aufgabe per Autodidakt da einzusteigen.
Das einzige was mir dazu einfallen würde, warum select hier ein "invalid argument" liefern sollte, wäre ein verwirrter Timeout.
Was steht denn in POWERSAVED_POLLING_INTERVAL in /etc/sysconfig/powersave/common?
david@bree:~> grep POWERSAVED_POLLING_INTERVAL /etc/sysconfig/powersave/common POWERSAVED_POLLING_INTERVAL="" Sollte also der default von 333 sein. Aber mal sehen: Ein POWERSAVED_POLLING_INTERVAL="333" eingetragen und ein rcpowersaved start bringt zwar noch einmalig die Syslog-Meldung: Jul 11 22:39:26 bree [powersave][8462]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 11 22:39:33 bree last message repeated 219312 times Das war's dann aber. Powersaved läuft wie er soll; CPU bei 600MHz und bei Bedarf höher. Der Vollständigkeit halber hier das Ergebnis ohne den Wert in POWERSAVED_POLLING_INTERVAL:
Ansonsten starte den powersaved mal mit dem höchsten debuglevel (31), am besten manuell:
rcpowersaved stop /usr/sbin/powersaved -x /usr/lib/powersave/scripts -a resmgr -v 31
Jul 11 22:02:40 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/common in line 59 or empty value Jul 11 22:02:40 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/common in line 116 or empty value Jul 11 22:02:40 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/common in line 127 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/cpufreq in line 24 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/cpufreq in line 35 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/cpufreq in line 61 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/cpufreq in line 72 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/battery in line 29 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/battery in line 39 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/sleep in line 38 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/sleep in line 53 or empty value Jul 11 22:02:41 bree [powersave][8020]: Info: Error in line 124 of config file /etc/sysconfig/powersave/sleep. Event or setting POWERSAVE_SUSPEND2DISK_UNMOUNT_FATFS does not exist, ignored. Jul 11 22:02:41 bree [powersave][8020]: Info: Error in line 125 of config file /etc/sysconfig/powersave/sleep. Event or setting POWERSAVE_SUSPEND2RAM_UNMOUNT_FATFS does not exist, ignored. Jul 11 22:02:41 bree [powersave][8020]: Info: Error in line 126 of config file /etc/sysconfig/powersave/sleep. Event or setting POWERSAVE_STANDBY_UNMOUNT_FATFS does not exist, ignored. Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/events in line 33 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/events in line 52 or empty value Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function readConfigFile, line 104: in config file /etc/sysconfig/powersave/events in line 53 or empty value Jul 11 22:02:41 bree [powersave][8020]: Debug: Init power management interface! Jul 11 22:02:41 bree [powersave][8020]: Debug: SchemeConfig Constructor Jul 11 22:02:41 bree [powersave][8020]: Info: Scheme scheme_acoustic found. Jul 11 22:02:41 bree [powersave][8020]: Info: Default AC scheme is scheme_performance Jul 11 22:02:41 bree [powersave][8020]: Debug: Init power management interface! Jul 11 22:02:41 bree [powersave][8020]: Debug: SchemeConfig Constructor Jul 11 22:02:41 bree [powersave][8020]: Info: Scheme scheme_performance found. Jul 11 22:02:41 bree [powersave][8020]: Info: Default Battery scheme is scheme_powersave Jul 11 22:02:41 bree [powersave][8020]: Debug: Init power management interface! Jul 11 22:02:41 bree [powersave][8020]: Debug: SchemeConfig Constructor Jul 11 22:02:41 bree [powersave][8020]: Info: Scheme scheme_powersave found. Jul 11 22:02:41 bree [powersave][8020]: Debug: Init power management interface! Jul 11 22:02:41 bree [powersave][8020]: Debug: SchemeConfig Constructor Jul 11 22:02:41 bree [powersave][8020]: Info: Scheme scheme_presentation found. Jul 11 22:02:41 bree [powersave][8020]: Debug: Constructor PM_Interface Jul 11 22:02:41 bree [powersave][8020]: Info: Value: 600000 read out from file: /sys/devices/system/cpu/cpu0/cpufreq/scaling_min_freq! Jul 11 22:02:41 bree [powersave][8020]: Info: Value: 1500000 read out from file: /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq! Jul 11 22:02:41 bree [powersave][8020]: DIAG in Function getSupportedSpeeds, line 370: Speed min: 600000 kHz - Speed max: 1500000 kHz Jul 11 22:02:41 bree [powersave][8020]: Info: Value: 600000 read out from file: /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed! [...] Jede Menge Logfile gelöscht, da <suse-laptop@lists.suse.com>: ezmlm-reject: fatal: Sorry, I don't accept messages larger than 30000 bytes (#5.2.3) Den vollständigen Ausschnitt habe ich mal unter: http://david-huecking.de/powersaved_logfile zur Verfügung gestellt. Jul 11 22:02:42 bree [powersave][8020]: Debug: Select waiting: 1 secs and 240 millisecs Jul 11 22:02:42 bree [powersave][8020]: Debug: Socket FD 3 is set, handling it ... Jul 11 22:02:42 bree [powersave][8020]: Debug: Server received 4 bytes - Request: 255! Jul 11 22:02:42 bree [powersave][8020]: Debug: Send schemes back to client. Jul 11 22:02:42 bree [powersave][8020]: Info: Sending current scheme: 2; AC scheme 1, Battery scheme 2,size: 96 Jul 11 22:02:42 bree [powersave][8020]: Debug: Select waiting: 1 secs and 240 millisecs Jul 11 22:02:43 bree [powersave][8020]: Debug: Timeout. Jul 11 22:02:43 bree [powersave][8020]: Debug: Shall I poll Battery?: FORCE_BATTERY_POLLING: 1; msecs_last_battery_read: 0, Mulitplicator: 5, battery_timeout: 10000 Jul 11 22:02:43 bree [powersave][8020]: Debug: cpu_max: 75 high_cpu_limit: 70 consider_nice: 0 hysteresis: 5 Jul 11 22:02:43 bree [powersave][8020]: Debug: Current: 1; current speed: 1200000 MHz, New: 1, new_speed: 1200000 MHz Jul 11 22:02:43 bree [powersave][8020]: Debug: CPU load: 3, Last CPU load 60, CPULoad diff: -57, last_step: 4, cpu_max: 75, demotion: 58 Jul 11 22:02:43 bree [powersave][8020]: Info: current speed: 1200000KHz new speed: 1000000KHz Jul 11 22:02:43 bree [powersave][8020]: Info: Speed set to: 1000000KHz Jul 11 22:02:43 bree [powersave][8020]: Info: Speed decreased to (1000000) MHz Jul 11 22:02:43 bree [powersave][8020]: Debug: Needed 0 sec and 355 usec time to process functions after select Jul 11 22:02:43 bree [powersave][8020]: Debug: Select waiting: 2 secs and 4294966 millisecs Jul 11 22:02:43 bree [powersave][8020]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 11 22:02:43 bree [powersave][8020]: Debug: Socket FD : 3 is set, ignore it, see warning above. Jul 11 22:02:43 bree [powersave][8020]: Debug: Select waiting: 2 secs and 4294966 millisecs Jul 11 22:02:43 bree [powersave][8020]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 11 22:02:43 bree [powersave][8020]: Debug: Socket FD : 3 is set, ignore it, see warning above. Jul 11 22:02:43 bree [powersave][8020]: Debug: Select waiting: 2 secs and 4294966 millisecs
(nach ein paar sekunden schnell strg-c drücken) danach mal schauen, in welchem select-zweig er war ("Select waiting without timeout" oder "Select waiting: xxx secs and yyy millisecs").
Ein Ctrl+C tat es nicht, sondern nur ein kill -9, aber was soll's. Es ist der Fall "Select waiting: xxx secs and yyy millisecs" im ersten else-Zweig, also wird schonmal angenommen, dass cpufreq polling unterstützt wird?!
Jul 2 02:33:12 bree last message repeated 2070566 times
Hm, das sind ja nur 35000 Läufe des mainloops pro sekunde, ich muß den Code doch mal optimieren ;-)
Die Endlosschleife in ein paar Sekunden muss da schon drin sein! (-:
Selbstverfreilich hat powersave unter SuSE 9.2 zur Zufriedenheit funktioniert... Hat mal wer 'nen Tip wo ich dran schrauben kann?
Laß uns erst mal die Spuren sichern ;-)
Ok, Du hast den Überblick. 8-)
-- Stefan Seyfried
Einen herzlichen Dank und auf zur nächsten Übung (Suspend to RAM und to disk)... Da dies ja der zweite Versuch der Mail ist, hier noch das Erbebnis vom Supend: Beides 2RAM und 2disk funktioniert out of the box. Nach Aufwachen USB und Sound noch da. :-) Gab's da sonst noch typische Schwierigkeiten? Nochmals Dank! - Gute Arbeit! -- Eat, sleep and go running, ;-) David Huecking. Encrypted eMail welcome! GnuPG/ PGP-Fingerprint: 3DF2 CBE0 DFAA 4164 02C2 4E2A E005 8DF7 5780 9216
Hallo, On Mon, Jul 11, 2005 at 11:17:28PM +0200, David Huecking wrote:
allo! - Das mag ich hier so: nahezu sofort kompetente Antworten und Hilfe(-Versuche)! Super.
Nun ja, ich tue was ich kann. Oder anders ausgedrückt: bei einem qualifizierten Bugreport ist es einfach, kompetent zu antworten :-)
On Sonntag 10 Juli 2005 22:03, Stefan Seyfried wrote:
OK, den Code rund um die for-Schleife in der powersaved.cpp hatte ich mir auch angeguckt, aber da ich bisher keinen Hintergrund zu all dem habe, was man da per select abfragen kann... sicherlich eine längere Aufgabe per Autodidakt da einzusteigen.
Ja, der Code ist auch nicht unbedingt durchsichtig, was auch dazu führt, daß ich jedes Mal, wenn jemand die select-loop angefaßt hat, danach wieder aufräumen und Fehler beseitigen muß ;-)
Das einzige was mir dazu einfallen würde, warum select hier ein "invalid argument" liefern sollte, wäre ein verwirrter Timeout.
Was steht denn in POWERSAVED_POLLING_INTERVAL in /etc/sysconfig/powersave/common? david@bree:~> grep POWERSAVED_POLLING_INTERVAL /etc/sysconfig/powersave/common POWERSAVED_POLLING_INTERVAL=""
Sollte also der default von 333 sein.
Aber mal sehen: Ein POWERSAVED_POLLING_INTERVAL="333"
Ja. Du solltest das mit den "Default:"-Kommentaren im Konfigurationsfile beim powersaved nicht zu Ernst nehmen ;-) Das ist mir vor ein paar Wochen auch aufgefallen und die nächste Version hat das nun gefixt, die einkompilierten Defaults stimmen mit denen im Configfile überein (und dort steht für die defaults nur noch "", so wie es sein soll). Konkret: einkompiliert ist / war "2000"
eingetragen und ein rcpowersaved start bringt zwar noch einmalig die Syslog-Meldung: Jul 11 22:39:26 bree [powersave][8462]: WARNING in Function start; line 371: Select returned an Error, but not interrupted through a signal: Invalid argument This is not nice, but normal after a suspend2disk Jul 11 22:39:33 bree last message repeated 219312 times Das war's dann aber. Powersaved läuft wie er soll; CPU bei 600MHz und bei Bedarf höher.
Ja, dadurch daß der timeout kleiner ist, wird der eigentliche bug maskiert vermute ich. Ich untersuche das mal genauer und mache evtl. ein YOU (du bist allerdings bisher der einzige, den das getroffen hat).
Der Vollständigkeit halber hier das Ergebnis ohne den Wert in POWERSAVED_POLLING_INTERVAL: Jul 11 22:02:43 bree [powersave][8020]: Debug: Needed 0 sec and 355 usec time to process functions after select Jul 11 22:02:43 bree [powersave][8020]: Debug: Select waiting: 2 secs and 4294966 millisecs
hier ist das Problem: die Milisekunden hatten einen underflow. Der Code der "schuld" ist: else { req.tv_sec = config->current_scheme->POLL_INTERVAL / 1000 - process_time / (1000*1000); req.tv_usec = (config->current_scheme->POLL_INTERVAL * 1000 % 1000000) - process_time % (1000*1000); pDebug (DBG_DEBUG, "Needed %lu sec and %lu usec time to process functions after select\n", process_time / (1000*1000), process_time % (1000*1000)); } Das Problem ist, daß bei einer "geraden" Sekunde Poll-Interval (2,0 bei dir) req.tv_usec = 0 - process_time wird. Das muß aber positiv bleiben (und vermutlich unter 1000000, aber da bin ich nicht sicher. Der Workaround ist einfach: POLLING_INTERVAL darf kein "gerader Tausender" sein (obwohl 1001 auch Schwierigkeiten macht, sobald process_time > 1msec ist). Mit den "üblichen Werten" zwischen 100 und 500 ist aber alles in Butter.
(nach ein paar sekunden schnell strg-c drücken) danach mal schauen, in welchem select-zweig er war ("Select waiting without timeout" oder "Select waiting: xxx secs and yyy millisecs"). Ein Ctrl+C tat es nicht, sondern nur ein kill -9, aber was soll's.
Ja, da dein STRG-C nur den select-loop unterbrochen hat, und dort -EINTR explizit "kein Fehler" ist => nicht abbricht :-)
Ok, Du hast den Überblick. 8-)
Ich hoffe, du jetzt auch.
Einen herzlichen Dank und auf zur nächsten Übung (Suspend to RAM und to disk)... Da dies ja der zweite Versuch der Mail ist, hier noch das Erbebnis vom Supend: Beides 2RAM und 2disk funktioniert out of the box. Nach Aufwachen USB und Sound noch da. :-) Gab's da sonst noch typische Schwierigkeiten?
Eigentlich nicht. Meine Erfahrung ist: Auf Maschinen, wo suspend to RAM geht, ist es zuverlässig, suspend2disk geht bei mir sowieso immer. Du solltest halt keinen "Blödsinn" machen: - Externe USB/FiWi-Platte während des suspend ab/anstecken - Zwischendurch ein anderes Betriebssystem booten (Windows/Knoppix/Rescue) und _irgendwie_ auf die Platte zugreifen (ich würde nicht mal lesend drauf zugreifen - evtl. wird beim unmount doch das dirty-flag zurückgesetzt) - Prinzipiell ist es kritisch, die Hardware während des suspend zu verändern sei es dock/undock oder anstecken einer Maus (obwohl das wirklich funktionieren sollte). USB/FiWi wird versucht dadurch zu lösen, daß - die Filesysteme möglichst unmounted werden - die Module usb-storage, sbp2 (fiwi) und die hostcontroller entladen werden. Dadurch wird die Hardware "virtuell abgesteckt" Aber wenn du erst gar keinen "Blödsinn" probierst, ist es auch wahrscheinlicher keine Probleme. Man muß ja nicht mit dem Feuer spielen :-)
Nochmals Dank! - Gute Arbeit!
Ich kann immerhin für mich verbuchen, daß der Bug nicht von mir eingebaut, sondern nur gefunden wurde :-) (schon vor 2 Wochen, ich dachte aber nicht, daß er jemand tatsächlich treffen würde). Viel Spaß -- Stefan Seyfried
participants (3)
-
"David Hücking" -
David Huecking
-
Stefan Seyfried