Altes Script langsamer auf neuem System

Tag.

Problem
Ein Programm das früher auf einem SuSE-System sehr schnell lief braucht nun
auf einem neuen System wesentlich länger. Die Hardware hat sich bis auf die
neuen Festplatten nicht geändert, es ist 'nur' ein neues Gentoo
draufgekommen.

Aufgabe des Programms ist es ein über die serielle Schnittstelle
angeschlossenes Funkgerät zu steuern. Dazu wird Device::SerialPort
verwendet (gleiche Version wie früher). Ein selbstgeschriebenes Modul
(icomcivio.pm) wird über die PERL5LIB env-variable gefunden, auch das ist
wie früher.

Was heisst langsamer?
Auf der alten Kiste lief das Programm praktisch ohne Verzögerung,
sprich: "Enter gedrückt - Ergebnis da". Jetzt benötigt das Programm ca. 2.1
Sekunden...

Ich habe mal mit dem Profiler geguckt, bin aber bei der Interpretation der
Ausgabe nicht ganz sicher:

$ dprofpp
Total Elapsed Time = 2.117945 Seconds
User+System Time = 0.067945 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
44.1 0.030 0.049 14 0.0021 0.0035 icomcivio::BEGIN
14.7 0.010 0.010 16 0.0006 0.0006 Exporter::import
14.7 0.010 0.059 5 0.0020 0.0119 main::BEGIN
14.7 0.010 0.020 12 0.0008 0.0016 Device::SerialPort::BEGIN
0.00 0.000 0.000 1 0.0000 0.0000 AutoLoader::AUTOLOAD
0.00 0.000 0.000 1 0.0000 0.0000 POSIX::load_imports
0.00 0.000 0.000 1 0.0000 0.0000
Exporter::Heavy::heavy_export_ok_t
ags
0.00 - -0.000 1 - - Exporter::Heavy::_push_tags
0.00 - -0.000 1 - - POSIX::Termios::new
0.00 - -0.000 1 - - POSIX::Termios::getattr
0.00 - -0.000 1 - - POSIX::Termios::getcflag
0.00 - -0.000 1 - - POSIX::Termios::getiflag
0.00 - -0.000 1 - - POSIX::Termios::getlflag
0.00 - -0.000 1 - - POSIX::Termios::getoflag
0.00 - -0.000 1 - - POSIX::Termios::getospeed

Bedeutet dies nun das zum Laden von icomcivio 44% der Zeit benötigt wird,
oder zum Ausführen?
Wie kann ich genauer gucken welche Sub in dem Modul da so lange Zeit
braucht? Ich habe den Verdacht das es das Locking der seriellen
Schnittstelle ist, bin aber noch nicht in die Tiefe gestiegen.

Danke für Hinweise.

Gruß,
Ekki

Re: Altes Script langsamer auf neuem System

"Ekki Plicht (DF4OR)" writes:

> Tag.
>
> Problem
> Ein Programm das früher auf einem SuSE-System sehr schnell lief braucht nun
> auf einem neuen System wesentlich länger. Die Hardware hat sich bis auf die
> neuen Festplatten nicht geändert, es ist 'nur' ein neues Gentoo
> draufgekommen.
>
> Aufgabe des Programms ist es ein über die serielle Schnittstelle
> angeschlossenes Funkgerät zu steuern. Dazu wird Device::SerialPort
> verwendet (gleiche Version wie früher). Ein selbstgeschriebenes Modul
> (icomcivio.pm) wird über die PERL5LIB env-variable gefunden, auch das ist
> wie früher.
>
> Was heisst langsamer?
> Auf der alten Kiste lief das Programm praktisch ohne Verzögerung,
> sprich: "Enter gedrückt - Ergebnis da". Jetzt benötigt das Programm ca. 2.1
> Sekunden...
>
> Ich habe mal mit dem Profiler geguckt, bin aber bei der Interpretation der
> Ausgabe nicht ganz sicher:
>
> $ dprofpp
> Total Elapsed Time = 2.117945 Seconds
> User+System Time = 0.067945 Seconds
> Exclusive Times
> %Time ExclSec CumulS #Calls sec/call Csec/c Name
> 44.1 0.030 0.049 14 0.0021 0.0035 icomcivio::BEGIN
> 14.7 0.010 0.010 16 0.0006 0.0006 Exporter::import
> 14.7 0.010 0.059 5 0.0020 0.0119 main::BEGIN
> 14.7 0.010 0.020 12 0.0008 0.0016 Device::SerialPort::BEGIN
> 0.00 0.000 0.000 1 0.0000 0.0000 AutoLoader::AUTOLOAD
> 0.00 0.000 0.000 1 0.0000 0.0000 POSIX::load_imports
> 0.00 0.000 0.000 1 0.0000 0.0000
> Exporter::Heavy::heavy_export_ok_t
> ags
> 0.00 - -0.000 1 - - Exporter::Heavy::_push_tags
> 0.00 - -0.000 1 - - POSIX::Termios::new
> 0.00 - -0.000 1 - - POSIX::Termios::getattr
> 0.00 - -0.000 1 - - POSIX::Termios::getcflag
> 0.00 - -0.000 1 - - POSIX::Termios::getiflag
> 0.00 - -0.000 1 - - POSIX::Termios::getlflag
> 0.00 - -0.000 1 - - POSIX::Termios::getoflag
> 0.00 - -0.000 1 - - POSIX::Termios::getospeed
>
> Bedeutet dies nun das zum Laden von icomcivio 44% der Zeit benötigt wird,
> oder zum Ausführen?
> Wie kann ich genauer gucken welche Sub in dem Modul da so lange Zeit
> braucht? Ich habe den Verdacht das es das Locking der seriellen
> Schnittstelle ist, bin aber noch nicht in die Tiefe gestiegen.
>

CPU-Last ist es nicht, das zeigt die die Summe aus User+System Time
an. Die meiste Zeit geht wahrscheinlich beim Warten verloren.
Vielleicht kannst du mit strace erfahren, wo gewartet wird.

Gruß,
Slaven

--
Slaven Rezic - slaven rezic de

tknotes - A knotes clone, written in Perl/Tk.
http://ptktools.sourceforge.net/#tknotes

Re: Altes Script langsamer auf neuem System

Es schrieb Slaven Rezic:

> "Ekki Plicht (DF4OR)" writes:
>> Bedeutet dies nun das zum Laden von icomcivio 44% der Zeit benötigt wird,
>> oder zum Ausführen?
>> Wie kann ich genauer gucken welche Sub in dem Modul da so lange Zeit
>> braucht? Ich habe den Verdacht das es das Locking der seriellen
>> Schnittstelle ist, bin aber noch nicht in die Tiefe gestiegen.
>>
>
> CPU-Last ist es nicht, das zeigt die die Summe aus User+System Time
> an. Die meiste Zeit geht wahrscheinlich beim Warten verloren.
> Vielleicht kannst du mit strace erfahren, wo gewartet wird.

Es liegt tatsächlich am Lockfile. Wenn ich das beim Öffnen der ser.
Schnittstelle deaktiviere läufts schnell wie früher.
Mit strace habe ich noch nicht gearbeitet, aber ich denke nun ist ein guter
Zeitpunkt das mal zu lernen.

Danke für den Hinweis.
Ekki

Re: Altes Script langsamer auf neuem System

Slaven Rezic wrote:

> Vielleicht kannst du mit strace erfahren, wo gewartet wird.

Konnte ich. Und dadurch habe ich nun auch gelernt das ich das Problem auch
so hätte sehen können, nämlich dann wenn ich mir die Sources zu
SerialPort.pm angeguckt hätte. Nagut, dafür habe ich jetzt erste
Erfahrungen mit strace...

Dieses Modul arbeitet so das zunächst das Lockfile geschrieben wird, dann
kommt sleep(2), dann wird die serielle Schnittstelle geöffnet. :-/

Kennt jemand einen plausiblen Grund sowas zu machen?

Was mich nur wundert ist das dieses sleep(2) unter SuSE offenbar nicht
stattgefunden hat. Wie gesagt, da lief das Programm ohne diese Verzögerung.
Vielleicht irgendwelchen subtilen Implementationsunterschiede von
nanosleep() durch das Posix-Modul, was weiss ich.

Ich weiss noch nicht mal ob mich das wirklich interessiert, ich habe zwei
Workarounds: entweder verzichte ich ganz auf das Locking oder ich patche
SerialPort.pm und setze das sleep-Intervall auf einen etwas vernünftigeren
Wert. Vielleicht werde auch mal den Autor von SerialPort.pm anschreiben...

Gruß,
Ekki

Re: Altes Script langsamer auf neuem System

"Ekki Plicht (DF4OR)" writes:

> Slaven Rezic wrote:
>
> > Vielleicht kannst du mit strace erfahren, wo gewartet wird.
>
> Konnte ich. Und dadurch habe ich nun auch gelernt das ich das Problem auch
> so hätte sehen können, nämlich dann wenn ich mir die Sources zu
> SerialPort.pm angeguckt hätte. Nagut, dafür habe ich jetzt erste
> Erfahrungen mit strace...

Mit strace/ktrace/truss kann man manche Probleme sehr schnell finden.
Ein weiteres beliebtes Beispiel sind fehlende Dateien oder falsche
Zugriffsberechtigungen zusammen mit Applikationen, die schlechte oder
gar keine Fehlermeldungen liefern. Oder letztens habe ich damit einen
Memory-Leak in der libc gefunden.

>
> Dieses Modul arbeitet so das zunächst das Lockfile geschrieben wird, dann
> kommt sleep(2), dann wird die serielle Schnittstelle geöffnet. :-/
>
> Kennt jemand einen plausiblen Grund sowas zu machen?
>
> Was mich nur wundert ist das dieses sleep(2) unter SuSE offenbar nicht
> stattgefunden hat. Wie gesagt, da lief das Programm ohne diese Verzögerung.
> Vielleicht irgendwelchen subtilen Implementationsunterschiede von
> nanosleep() durch das Posix-Modul, was weiss ich.
>
> Ich weiss noch nicht mal ob mich das wirklich interessiert, ich habe zwei
> Workarounds: entweder verzichte ich ganz auf das Locking oder ich patche
> SerialPort.pm und setze das sleep-Intervall auf einen etwas vernünftigeren
> Wert. Vielleicht werde auch mal den Autor von SerialPort.pm
> anschreiben...

Nicht nur vielleicht, unbedingt!

Gruß,
Slaven

--
Slaven Rezic - slaven rezic de
babybike - routeplanner for cyclists in Berlin
handheld (e.g. Compaq iPAQ with Linux) version of bbbike
http://bbbike.sourceforge.net

Re: Altes Script langsamer auf neuem System

Slaven Rezic wrote:
> "Ekki Plicht (DF4OR)" writes:
>>
>> Ich weiss noch nicht mal ob mich das wirklich interessiert, ich habe zwei
>> Workarounds: entweder verzichte ich ganz auf das Locking oder ich patche
>> SerialPort.pm und setze das sleep-Intervall auf einen etwas vernünftigeren
>> Wert. Vielleicht werde auch mal den Autor von SerialPort.pm
>> anschreiben...
>
> Nicht nur vielleicht, unbedingt!

Auf meine Frage zu Problemen bei 'make test' unter Cygwin hat
der Autor/Maintainer vor einigen Wochen leider nicht geantwortet.
Vielleicht hat Ekki ja mehr Glueck. Wenn ja, wuerde ich gern davon
hoeren, denn das wuerde meinen momentanen Eindruck, dass die
Entwicklung/Pflege des Moduls etwas eingeschlafen ist, widerlegen.

Gruss
Johannes

Re: Altes Script langsamer auf neuem System

johannes@v.loewis.de (Johannes von Loewis) writes:

> Slaven Rezic wrote:
> > "Ekki Plicht (DF4OR)" writes:
> >>
> >> Ich weiss noch nicht mal ob mich das wirklich interessiert, ich habe zwei
> >> Workarounds: entweder verzichte ich ganz auf das Locking oder ich patche
> >> SerialPort.pm und setze das sleep-Intervall auf einen etwas vernünftigeren
> >> Wert. Vielleicht werde auch mal den Autor von SerialPort.pm
> >> anschreiben...
> >
> > Nicht nur vielleicht, unbedingt!
>
> Auf meine Frage zu Problemen bei 'make test' unter Cygwin hat
> der Autor/Maintainer vor einigen Wochen leider nicht geantwortet.
> Vielleicht hat Ekki ja mehr Glueck. Wenn ja, wuerde ich gern davon
> hoeren, denn das wuerde meinen momentanen Eindruck, dass die
> Entwicklung/Pflege des Moduls etwas eingeschlafen ist, widerlegen.

Wenn ein Eintrag auf rt.cpan.org auch nicht (sofort) zur Behebung des
Problems führt, so ist es wenigstens Dokumentation, dass das Problem
existiert. Andere User mit dem selben Problem könnten davon
profitieren.

Gruß,
Slaven

--
Slaven Rezic - slaven rezic de

Visualize XML files in a Tk text widget:
http://search.cpan.org/search?mode=module&query=Tk::XMLViewe r

Re: Altes Script langsamer auf neuem System

Slaven Rezic wrote:

> Wenn ein Eintrag auf rt.cpan.org auch nicht (sofort) zur Behebung des
> Problems führt, so ist es wenigstens Dokumentation, dass das Problem
> existiert. Andere User mit dem selben Problem könnten davon
> profitieren.

Richtig, denn dann

1. finden auf diesem Wege die Nutzer zusammen welche dieselben
Probleme haben mit dem Modul, es können sich "Seilschaften"
bilden.

2. hat derjenige, der ggf. das Modul übernimmt, eine
Liste "altbekannter Probleme" (zum Teil Jahre alt)
zur Hand und eine Liste von interessierten Nutzern,
die dann wiederum Beiträge liefern.

in dieser Weise habe ich es jedenfalls erlebt und
empfehle den Weg "nutzt rt.cpan.org auf jeden Fall
zur Dokumentation der Probleme".

Re: Altes Script langsamer auf neuem System

Johannes von Loewis wrote:

> Auf meine Frage zu Problemen bei 'make test' unter Cygwin hat
> der Autor/Maintainer vor einigen Wochen leider nicht geantwortet.
> Vielleicht hat Ekki ja mehr Glueck.

Habe ich wohl nicht. Seit drei Tagen keine Antwort. Vorwerfen kann ich das
allerdings niemandem, ich beantworte Supportmails zu meinem Kram auch
manchmal nur sehr schleppend...

Gruß,
Ekki

Re: Altes Script langsamer auf neuem System

Slaven Rezic wrote:

> Wenn ein Eintrag auf rt.cpan.org auch nicht (sofort) zur Behebung des
> Problems führt, so ist es wenigstens Dokumentation, dass das Problem
> existiert. Andere User mit dem selben Problem könnten davon
> profitieren.

Ack.
Aber es ist ja kein echter Bug, eher broken by design oder so. Das soll so.
Nur warum das so soll versteht keiner.

Gruß,
Ekki

Re: Altes Script langsamer auf neuem System

Slaven Rezic wrote:
> johannes@v.loewis.de (Johannes von Loewis) writes:
>
>> Auf meine Frage zu Problemen bei 'make test' unter Cygwin hat
>> der Autor/Maintainer vor einigen Wochen leider nicht geantwortet.
>> Vielleicht hat Ekki ja mehr Glueck. Wenn ja, wuerde ich gern davon
>> hoeren, denn das wuerde meinen momentanen Eindruck, dass die
>> Entwicklung/Pflege des Moduls etwas eingeschlafen ist, widerlegen.
>
> Wenn ein Eintrag auf rt.cpan.org auch nicht (sofort) zur Behebung des
> Problems führt, so ist es wenigstens Dokumentation, dass das Problem
> existiert. Andere User mit dem selben Problem könnten davon
> profitieren.

Ich habe jetzt einen Bugreport auf rt.cpan.org abgeliefert.
Dabei hat mich ueberrascht, dass dort Bill Birthisel als Maintainer
gefuehrt wird, waehrend am Ende von 'perldoc Device::SerialPort'
Kees Cook als gegenwaertiger Maintainer angegeben ist.

Johannes

Re: Altes Script langsamer auf neuem System

Johannes von Loewis wrote:

> Ich habe jetzt einen Bugreport auf rt.cpan.org abgeliefert.
> Dabei hat mich ueberrascht, dass dort Bill Birthisel als Maintainer
> gefuehrt wird, waehrend am Ende von 'perldoc Device::SerialPort'
> Kees Cook als gegenwaertiger Maintainer angegeben ist.

Laut der Anzeige der Permissions auf PAUSE
ist Kees Cook (COOK) der Hauptmaintainer, Bill Birthisel
(BBIRTH) der Co-Maintainer.
Wenn 'BBIRTH' im RT als Maintainer gelistet wird ist das
erstmal nicht falsch, weil sich im RT die Berechtigungen
auf PAUSE widerspiegeln.
Was mich aber wundert ist daß 'COOK' nicht auf RT als Maintainer
gelistet wird.