Geschwindigkeit Rega Scripte

[Henke]

Testet das mal mit "schnell = false" und "schnell = true" als externen Rega Aufruf z.B. mit dem SDV oder auch mit "Script testen".
Das Erzeugen der Rückgabe xml Struktur kostet bei bestimmten großen Daten recht viel Zeit.

Code: Alles auswählen

boolean schnell = true;

string out = "";
var ii = 0;
while ( ii < 2000)
{
	out  = out # '"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",';
	ii = ii + 1;
}

Write(out);
if ( schnell )
{
	out = "";
} 

[Black]

Was ist bei dir denn langsam bzw schnell? So von der Größenordnung her

Black

[Henke]

SDV unter Windows, Rega auf auf CCU3

07:12:00:321 CCU Laufzeit 4,843 sec
07:12:48:254 CCU Laufzeit 0,532 sec

und das liegt nicht am parsen des SDV

[jmaus]

Und du schreibst "bei bestimmten großen Daten". Was soll mir das sagen? Bitte mehr technische Details und Beschreibungen wenn du das hast, denn nur diesen Skript zu zeigen und ein Statement rauszuhauen hilft nicht ggf. den Performance Engpass zu finden.

[Henke]

Mir als Entwickler reicht eine reproduzierbare Fehlerbeschreibung eigentlich immer, ein Testprogramm bekomme ich nie.
Dann schmeiße ich den Debugger an und....

Aber auch so, war das nicht schwer:

Mit schnell = false;

out = out # '"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",'; ! -> 4,8 sec
out = out # 'AAAAAA, BBBBBBBBBBBBB, CCCCCCCCCCCCCCCCCC, DDDDDDDDDDDDDDDD, EEEEEEEEEEEEEEE FFFFFFFFFFFFFFFFFFFFFFF EEEEEEEEE'; ! -> 0,58 sec
out = out # '""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""'; ! nach 15 sec KILLED

Die " sind zumindest eines der Probleme.

[Henke]

Darauf gekommen bin ich bei dem Versuch herauszufinden wann die Rega eine Zeitsteuerung überspring. Dazu hatte ich eines meiner Scripte genommen das viel Zeit brauchte und stellte fest, das es als Script innerhalb eines CCU Programms nicht hilfreich war, da es plötzlich statt 9 sec noch nicht mal 1 brauchte. Da wollte ich natürlich wissen, warum...

Zur Zeitsteuerung:
Ich kann zwar die Ausführungszeiten durch lang laufende Scripte verschieben, aber bisher wird jedes ordnungsgemäß ausgeführt. Da habe ich also keinen Tipp.

[jmaus]

Mit schnell = false;

Code: Alles auswählen

out  = out # '"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",'; ! -> 4,8 sec
out  = out # 'AAAAAA, BBBBBBBBBBBBB, CCCCCCCCCCCCCCCCCC, DDDDDDDDDDDDDDDD, EEEEEEEEEEEEEEE FFFFFFFFFFFFFFFFFFFFFFF EEEEEEEEE'; ! -> 0,58 sec
out  = out # '""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""'; ! nach 15 sec KILLED

Nunja, das wird dann wohl vermutlich der Parser der Skriptsprache sein der da versucht die tokens anhand der Anführungszeichen zu separieren um herauszufinden bis wohin der String wirklich geht. Weiss nicht ob ich da was verbessern/optimieren kann. Du solltest dafür aber definitiv ein entsprechendes Bug/Issue Ticket im RaspberryMatic GitHub aufmachen wo du das nochmal ausführlich beschreibst und dann kann ich mir das bei gelegenheit gerne mal im ReGaHss Quellcode anschauen ob mir was auffällt.

Die ReGa ist einfach so alt und so kaputt das man die eigentlich wegwerfen müsste, aber das ansich ist eben ein unmögliches unterfangen. Probier aber mal folgendes:

Code: Alles auswählen

out # ^"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",^;

Vielleicht bringt das ja was?!?

[jmaus]

Ok, nun hab ich das mal selbst kurz getestet und hier scheint in der Tat etwas faul zu sein bzw. aktuell danach zu riechen. Folgendes abgewandeltes Testskript habe ich verwendet:

Code: Alles auswählen

time start = system.Date();
WriteLine("START: " # start);

string out = "";
var ii = 0;
while ( ii < 2000)
{
  out  = out # '""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""'; ! SLOW
  !out  = out # "''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''"; ! SLOW
  !out  = out # ^""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""^; ! SLOW
  !out  = out # '"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",'; ! FASTER
  !out  = out # 'AAAAAA, BBBBBBBBBBBBB, CCCCCCCCCCCCCCCCCC, DDDDDDDDDDDDDDDD, EEEEEEEEEEEEEEE FFFFFFFFFFFFFFFFFFFFFFF EEEEEEEEE'; ! FASTEST
  !out  = out # 'AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA'; ! FASTEST                                   

  ii = ii + 1;                                
}

! Write(out);
!out = ""; ! comment out for speed?!?!
                           
time end = system.Date();
WriteLine("DONE.: " # end);

Zwei Dinge die hierbei auffallen sind:

1. Die Zeitausgaben bei START und DONE sind immer gleich egal wie langsam/schnell das abgearbeitet wird, d.h. egal welche der oberen "out = out # ..." Zeilen ich auskommentiere. Ergo liest sich das für mich das hier der Zeitversatz nicht von der Ausführung innerhalb der ReGa kommt. So zumindest aktuell der Eindruck.
2. Es ist in der Tat so, das selbst im "Skript testen" Fenster die Ausgaben von START/DONE schneller auftauchen (egal welche out-Zeile auskommentiert ist) wenn man unten die Variable final auf "" oder einen kürzeren String setzt.

Auf Grund dieser Auffälligkeiten bzw. kurzen Analysen ist daher aktuell meine Vermutung, das das doch nicht von ReGa selbst bzw. deren Skriptparser herrührt (da eben START/DONE Zeitangaben immer unauffällig kurz bzw. nah eineinander sind, ergo er nicht in der Schleife selbst beschäftigt ist), sondern vmtl. von einer nachgelagerten Schnittstelle herrührt die anscheinend damit beschäftigt sein wird all diese Anführzeichen (egal ob einfach oder doppelt) zu escapen, d.h. z.B. aus einem " dann ein \" oder %22 oder gar " oder ähnliches macht und dann am schluss der string damit um ein vielfaches aufgebläht wird. Und das das ganze dann schneller geht wenn man am Schluss diese lange variable quasi leert spricht auch dafür, weil dann eben dieser nicht mehr aufwendig escaped werden muss. Aktuelle vermuting ist tclrega ist hier irgendwie involviert...

Spricht aber definitiv dafür das man dafür mal ein Issue Ticket im RaspberryMatic GitHub dazu aufmachen sollte um diese Erkenntnisse niederzuschreiben um dann systematisch nach dem Grund zu suchen wer hier für diese längere Verarbeitungszeit wirklich verantwortlich ist und ob man das irgendwie beschleunigt bekommt.

[Henke]

Ich rufe bei meinen Test die Rega über Port 8181 (da extern) auf und habe das Parsen der Rückgabe nach "<xml>" deaktiviert und diese Zeiten nicht mitzuübernehmen. Daher würde ich den Fehler definitiv eher in der Rega vermuten.
Meine nächste Vermutung ist, das nicht die Länge des Stings, sonder eher die Art des Ersetzens das Problem ist. Gefühlt ist das ein Laufzeitfehler bei dem entweder nach jeder Ersetzung von vorne Anfangen wird und/oder zu viel Speicher verschoben wird.
Einfach mal testen ob eine veränderte Kopie schneller ist.

[jmaus]

Ich rufe bei meinen Test die Rega über Port 8181 (da extern) auf und habe das Parsen der Rückgabe nach "<xml>" deaktiviert und diese Zeiten nicht mitzuübernehmen. Daher würde ich den Fehler definitiv eher in der Rega vermuten.

Also ich hab mir das nun nochmal angeschaut und mal diesen Skript direkt auf der Zentrale an Port 8183 mit folgendem bash/curl Skript schicken lassen:

Code: Alles auswählen

#!/bin/sh                                                                                                                                                 
                                                                                                                                                          
read -r -d '' VAR <<- EOM                                                                                                                                 
  time start = system.Date();                                                                                                                             
  WriteLine("START: " # start);                                                                                                                           
                                                                                                                                                          
  string out = "";                                                                                                                                        
  var ii = 0;                                                                                                                                             
  while ( ii < 2000)                                                                                                                                      
  {                                                                                                                                                       
    out  = out # '""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""'; ! SLOW                 
    !out  = out # "''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''''"; ! SLOW                
    !out  = out # ^""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""""^; ! SLOW                
    !out  = out # '"device":{"12345":{"title":"0-Außen Beleuchtung","mac":"xxxxxxxxxxxxxsss","iface":"HmIP-RF","type":"HmIP-BSM",'; ! FASTER             
    !out  = out # 'AAAAAA, BBBBBBBBBBBBB, CCCCCCCCCCCCCCCCCC, DDDDDDDDDDDDDDDD, EEEEEEEEEEEEEEE FFFFFFFFFFFFFFFFFFFFFFF EEEEEEEEE'; ! FASTEST             
    !out  = out # 'AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA'; ! FASTEST             
                                                                                                                                                          
    ii = ii + 1;                                                                                                                                          
  }                                                                                                                                                       
                                                                                                                                                          
  ! Write(out);                                                                                                                                           
  !out = ""; ! comment out for speed?!?!                                                                                                                  
                                                                                                                                                          
  time end = system.Date();                                                                                                                               
  WriteLine("DONE.: " # end);                                                                                                                             
EOM                                                                                                                                                       
                                                                                                                                                          
time curl -q http://localhost:8183/hm.exe --data-raw "${VAR}" | wc -c                                                                                                                          

Und was soll ich sagen? Es ist genauso wie ich mir gedacht hatte: Durch diese vielen Anführungszeichen bzw. Sonderzeichen die am Schluss in der Ausgabevariable "out" landen kommt es zu einer massiven vergrößerung der Datenmenge die am Schluss zum Client via HTTP / Netzwerk übertragen werden müssen.

Hier z.B. das Ergebnis des Skriptes so wie es oben gezeigt ist:

Code: Alles auswählen

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 1290k  100 1289k  100  1193   792k    733  0:00:01  0:00:01 --:--:--  793k
1320251
real	0m 1.63s
user	0m 0.00s
sys	0m 0.00s

Wie man sehen kann werden dort rund 1,3 MB an Daten zurückgeliefert und die müssen halt erst einmal beim Client ankommen. Und auf meiner Test-RM dauert daher die Ausführung des "curl" befehles rund 1,6 Sekunden wie man sehen kann.

Lässt man nun jedoch am schluss die "out" Variable eben wie besagt leeren vor Beendigung des Skriptes kommt das hier raus:

Code: Alles auswählen

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  1443  100   251  100  1192   3478  16521 --:--:-- --:--:-- --:--:-- 20041
251
real	0m 0.08s
user	0m 0.01s
sys	0m 0.01s

Ergo braucht dann das curl kommando lediglich 8 Millisekunden, eben einfach weil der Rückgabedatenstrom dann gerademal 251 bytes sind.

Konkret sehen dann die Rückgabedaten wie folgt aus:

Code: Alles auswählen

<xml><exec>/hm.exe</exec><sessionId></sessionId><httpUserAgent>User-Agent: curl/8.2.1</httpUserAgent><start>16:52:13 29.09.2023</start><out></out><ii>2000</ii><end>16:52:13 29.09.2023</end></xml>

"out" ist also leer. Wohingehend in dem oberen Fall ohne leeren von "out" die Ausgabe eben wie folgt aussieht:

Code: Alles auswählen

<xml><exec>/hm.exe</exec><sessionId></sessionId><httpUserAgent>User-Agent: curl/8.2.1</httpUserAgent><start>16:54:18 29.09.2023</start><out>&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot;&quot; [...]</out></out><ii>2000</ii><end>16:54:18 29.09.2023</end></xml>

D.h. es werden also run 1,3MB an "&quot;" in der XML Struktur mit zurückgegeben und die müssen wie schon erwähnt ja erst einmal beim Client ankommen. Und wie man an den Werten von <start> und <end> sehen kann liegt es eben nicht an der Verarbeitung von ReGaHss oder ähnliches. Dieser Unterschied wird also einfach eine Konsequenz der Datenmenge sein.

Was man ehrlicherweise aber auch sagen muss ist, das hier der Netzwerkspeed der Auslieferung der Daten selbst via localhost wie oben gezeigt wohl bei ca. 800k/sek. liegt. Es sollte da also in der Tat ggf. noch etwas Luft nach oben gehen was die Aufbereitung und auslieferung der Daten über den ReGaHss Webserver angeht. Auch sehe ich in weiteren Tests wenn ich einfach mal die Datenmenge noch wesentlich erhöhe das dann die CPU Auslastung der ReGaHss ziemlich in die Höhe geht und auch die Memory Auslastung. Der integrierte Webserver der ja in ReGaHss ziemlich rudimentär umgesetzt ist wird also mit solchen Datenmengen ggf. ein Problem haben und vielleicht kann man hier wirklich noch etwas rausholen. Müsste ich mir in der Tat dann mal in Ruhe im Quellcode anschauen.