93_DbLog - Überlegungen zur Optimierung (RPI und andere Systeme)

[JoeALLb]

Nachtrag:
dbLogExclude funktioniert bei mir mit eingetragenem Interval NICHT.

Anbei ein Patch, mit dem ich es für meine Tests erfolgreicht nutzen konnte, dieser Patch
ist jedoch sicherlich noch nicht komplett.
Ich habe hierin einige Prüfungen etwas umgestalten müssen mit dem Vorteil, dass manche Tests nicht mehrfach durchgeführt werden müssen.

@Heiko: Wenn Du nähere Angaben über meine Tests und meine Testumgebung benötigst, kann ich Dir diese gerne per PN zukommen lassen.

Code Auswählen Erweitern

1101a1102
>
1104,1111d1104
<                       $DoIt = 0 if(!$v2[1] && $reading =~ m/^$v2[0]$/); #Reading matcht auf Regexp, kein MinIntervall angegeben
<
<       if(($v2[1] && $reading =~ m/^$v2[0]$/) && ($v2[1] =~ m/^(\d+)$/)) {
<                           #Regexp matcht und MinIntervall ist angegeben
<                           my $lt = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
<                           my $lv = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
<                           $lt = 0 if(!$lt);
<                           $lv = "" if(!$lv);
1113,1116c1106,1108
<                           if(($now-$lt < $v2[1]) && ($lv eq $value)) {
<                               # innerhalb MinIntervall und LastValue=Value
<                               $DoIt = 0;
<                           }
---
>                       if( $reading =~ m/^$v2[0]$/) {
>                         $DoIt = 0;
>                         Log3 $name, 1, "found $dev_name:$reading in DbLogExclude, prevent logging to database. Matching regex: ^".$v2[0].'$ ' if($vb4show);
1117a1110,1143
>                       else
>                       {
>                         Log3 $name, 1, "RR: $dev_name:$reading matched" if($vb4show);
>                         #Reading matched
>                         if ($v2[1] eq ''){  #kein MinIntervall angegeben
>                           Log3 $name, 1, "RR: $dev_name:$reading EINGESCHLOSSEN (nicht excluded), ohne MinInterval" if($vb4show);
>                         }
>                         else{
>                           Log3 $name, 1, "RR: $dev_name:$reading mit  MinInterval" if($vb4show);
>
>                                    ##Log3 $name, 4, "RR: $dev_name: #1#1  -".$v2[1]."-" if($vb4show);
>                                  if($v2[1] =~ m/^(\d+)$/) {
>                                    Log3 $name, 1, "RR: $dev_name:$reading MinIntervall ist eine Zahl " if($vb4show);
>                                    my $lv = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
>                                    $lv = "" if(!$lv);
>                                    if ($lv ne $value){
>                                       Log3 $name, 1, "$dev_name:$reading logging value $value to database, because it is different to old value $lv" if($vb4show);
>                                    }else{
>                                              #Regexp matcht und MinIntervall ist angegeben
>                                              my $lt = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
>                                              $lt = 0 if(!$lt);
>
>                                              if($now-$lt < $v2[1])  {
>                                                Log3 $name, 1, "RR: $dev_name:$reading: innerhalb MinIntervall und LastValue=Value" if($vb4show);
>
>                                                  # innerhalb MinIntervall und LastValue=Value
>                                                  $DoIt = 0;
>                                              }
>                                              else{
>                                                Log3 $name, 1, "$dev_name:$reading: Time since last log shorter than threshold. Time:".($now-$lt)." < Treshold: $v2[1] " if($vb4show);
>                                              }
>                                          }
>                                       }
>                         }
1119a1146
>             }


Edit1: Die verbose4Devs - Logs sollten natürlich noch entfernt/reduziert und fertig übersetzt werden. Das mache ich bei Bedarf gerne.

[DS_Starter]

Hi Joe,

trag erstmal alles zusammen was dir evtl. auffällt. Ich bewerte es und arbeite das dann endgültig ins Modul zu abschließenden Tests ein wenn ich wieder dafür Zeit habe.
So wie ich das sehe hast du die Details in der DbLog_Log Routine geändert. Da müssen wir aufpassen dass sich keine unerwünschten Nebeneffekte einschleichen. Die Routine stammt noch aus dem Modul aus dem vorigen Jahr (dem alten Modul).

Die verbose4Devs - Logs sollten natürlich noch entfernt/reduziert und fertig übersetzt werden. Das mache ich bei Bedarf gerne.

Brauchst du nicht .... erledige ich dann mit.

So, jetzt mache ich mich erstmal vom Acker, lese aber sicherlich mit und schreibe evtl. Nur ist jetzt erstmal FHEM-freie Zeit angesagt 

Bis dann,
Heiko

[JoeALLb]

Hallo Heiko,

alles klar, so wars auch gedacht. Daher hab ich einen Patch und keine neue Version angehängt.
Den Patch brauchte ich nur, damit es für mich erstmal wieder funktioniert.

Ich werde in diesem Punkt sammeln, was ich herausgefunden habe und diesen dann auch aktualisieren.

Findings:

#1 Unterschiedliches Verhalten mit dem min-Interval und ohne. Eigentlich nicht vom Regex gematchten Devices wurden nur durch die Angabe :1000 plötzlich doch geloggt.
    Das gewollte Verhalten (lt. COmmandref) ist aber, dass sich der gematchte Device nur dann loggt, wenn entweder der Wert verändert wurde, oder die Min-Zeit überschritten wurde.
    Um das zu Testen bei einem Residence-Device folgendes Attribut angeben.

Code Auswählen Erweitern

attr rr_ DbLogExclude ((?!precense).)*
    Wenn stattdessen dieses Attribut genutzt wird, werden (mit dem bisherigen Code) plötzlich auch Readings wie durTimerAbsence geloggt.

Code Auswählen Erweitern

attr rr_ DbLogExclude ((?!precense).)*:1000
--> dieses Verhalten korrigiert der oben genannte Patch.

#2 Lösung für

Code Auswählen Erweitern

$lv = "" if(!$lv);
in #288 ergänzt.


sG Joe

Edit: #2 ergänzt

[JoeALLb]

Aktualisierter Patch, der auch Werte mit 0
UND minInterval korrekt loggt.

Code Auswählen Erweitern


1101a1102
>
1104d1104
<                       $DoIt = 0 if(!$v2[1] && $reading =~ m/^$v2[0]$/); #Reading matcht auf Regexp, kein MinIntervall angegeben
1106,1111c1106,1109
<       if(($v2[1] && $reading =~ m/^$v2[0]$/) && ($v2[1] =~ m/^(\d+)$/)) {
<                           #Regexp matcht und MinIntervall ist angegeben
<                           my $lt = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
<                           my $lv = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
<                           $lt = 0 if(!$lt);
<                           $lv = "" if(!$lv);
---
>                         ##Debuggcode
>                         if ($dev_name =~ m/^rr_P/){
>                           $value=0 if($vb4show);  # Debuggcode
>                         }
1113,1116c1111,1113
<                           if(($now-$lt < $v2[1]) && ($lv eq $value)) {
<                               # innerhalb MinIntervall und LastValue=Value
<                               $DoIt = 0;
<                           }
---
>                       if( $reading =~ m/^$v2[0]$/) {  #Reading matched, so prevent Logging
>                         $DoIt = 0;
>                         Log3 $name, 1, "found $dev_name:$reading in DbLogExclude, prevent logging to database. Matching regex: ^".$v2[0].'$ ' if($vb4show);
1117a1115,1144
>                       else {
>                       #Reading matched
>                         Log3 $name, 1, "RR: $dev_name:$reading matched" if($vb4show);
>                         if (!defined($v2[1]) || $v2[1] eq ''){  #kein MinIntervall angegeben
>                           Log3 $name, 1, "RR: $dev_name:$reading Add to Log, no MinInterval" if($vb4show);
>                         }
>                         else {
>                         #Reading NOT matched, so doing further checks
>                            if($v2[1] =~ m/^(\d+)$/) {
>                              Log3 $name, 1, "$dev_name:$reading minInterval found, set to ".$v2[1]."s " if($vb4show);
>                              my $lv = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{VALUE};
> #Neu
>                     #         $lv = "" if(!$lv);   ## falsch bei VALUE=0;
>                  $lv = "" if(!defined($lv));  #versuch der Korrektur #2 in 2.16.7b
>
>                              if ($lv ne $value){
>                                 Log3 $name, 1, "$dev_name:$reading logging value $value to database, because it is different to old value $lv" if($vb4show);
>                              }else{  #Regexp matcht und MinIntervall ist angegeben, prüfen, ob minINterval überschritten ist.
>                                  my $lt = $defs{$dev_hash->{NAME}}{Helper}{DBLOG}{$reading}{$hash->{NAME}}{TIME};
>                                  $lt = 0 if(!$lt);
>                                  if($now-$lt < $v2[1]) {
>                                    Log3 $name, 1, "$dev_name:$reading: prevent logging. Time since last Log too short. ".($now-$lt)." < Treshold: $v2[1] " if($vb4show);
>                                      $DoIt = 0;
>                                  }
>                                  else{
>                                    Log3 $name, 1, "$dev_name:$reading: Add to Log. Old Value = New value, but Time since last log > than minInterval. Time: ".($now-$lt)." > Treshold: $v2[1] " if($vb4show);
>                                  }
>                              }
>                           }
>                         }
1119a1147
>             }



[Muschelpuster]

Moin zusammen,

Nachdem Heiko mich auf diesen Fred geschubst hat, gibt es auch noch einen Wunsch von mir 

Code Auswählen Erweitern

set <name> deleteOldDaysFilter<n> <Device> <Reading>
Es ist ja oft so, dass man wichtige und nicht so wichtige Daten loggt. Dementsprechend möchte man sie auch länger oder nicht so lange aufheben. So wäre es doch toll, wenn man nicht den großen Holzhammer nimmt, sondern gezielt unwichtige Daten früh aussortieren kann. Es würde die DB auch deutlich entlasten, wenn man nicht mit Rücksicht auf die wichtigen Daten jeden Schrott entsprechend lange aufbewahrt. Wenn man nun noch den Readingname mit Wildcards versorgen kann (optimal, weil FHEM-durchgängig natürlich Perl-Regex-Style, für die Programmierung sicher einfacher SQL-Style) dann könnte man mit wenigen Handgriffen (oder eben at's) viele Daten rechtzeitig entsorgen.
Bei reducelog gibt es das ja schon in etwa (eben umgekehrt):

Code Auswählen Erweitern


set <name> reduceLogNbl <n> [average[=day]] [exclude=deviceRegExp1:ReadingRegExp1,deviceRegExp2:ReadingRegExp2,...]
Wäre ja auch ein Weg für deleteOldDays, oder gibt es da schon was und ich finde das nur nicht?

selektive Grüße
Niels

[DS_Starter]

Hallo Niels,

melde mich nochmal hier, dann mache ich wieder Urlaub 
Sowas in der Art hatte JoeAllb auch schon mal angedacht. Umgesetzt haben wir es bisher nicht.
Momentan kannst du aber mit DbRep-Devices arbeiten um selektiv Device/Reading-Kombinationen aus der DB zu löschen. Dabei kannst du auch SQL-Wildcards (% bzw. _) angeben. So mache ich das z.Zt.
Einfach die benötigte Menge DbRep's anlegen, entsprechende Attribute für die zu löschenden Device/Readings setzen, ggf. auch noch die Zeiten begrenzen (um z.B. die Dev/readings zu löschen die älter als x sind) und dann mit At regelmäßig laufen lassen.
Arbeitet non-blocking und bei mit mit MySQL/MariaDB völlig merklos im Hintergrund.

VG
Heiko

[DS_Starter]

Hallo Joe,

ich komme mit deinem Patch auch  #288 nicht klar. Es lässt sich mit Tortoisemerge nicht verarbeiten und zu Fuß ist mir das zu anstrengend 
Kannst du den relevanten Ausschntt aus DbLog (mit ein paar Zeilen davor und danach) einfach hier als Code reinkopieren ? Damit komme ich dann sicher besser klar.

Grüße
Heiko

[JoeALLb]

Hallo Heiko,

schön von Dir zu hören
Jetzt bin nur leider ich unterwegs....

Interessant, denn den Patch habe ich mit Tortoise erstellt.
Ich mus snur zugeben, ich habe in der zwischenzeit herausgefunden, dass der Patch so tatsächlich die Funktion etwas ändert (mehr in die Richtung, wie ich es bräuchte ).
Ich müsste da also nochmal ran und einen oder zwei vergleiche negieren. GGf. fällt mir dann auch ein, wie ich die von mir gewünschte Funktion noch unterbringen kann...
Meine Funktion entspricht praktisch der Anwendung event-on-change kombiniert mit event-min-interval, da ich die Ereignisse aber benötige (für chat, etc..) möchte ich gerne auf die event.* Funktionen verzichten, und dies direkt im Logdevice filtern...
Aber wie gesagt, diese Woche bin ich noch unterwegs, vielleicht kann ich ihn mal eines Abends fertigstellen, wenn ich eine VPN-Verbindung zu meinem Server aufbauen kann (das ist im Ausland leider nicht immer möglich... )


sG
Joe

[DS_Starter]

Ja wie das so ist 

Ok, dann mach erstmal noch deine Checks. Ich habe die Addlog-Funktion schon umgebaut (von wegen <Device>:<Reding> ) und auch noch valueFN geändert damit VALUE bzw. UNIT auch 0 bzw. Leerstring gesetzt werden können.

Niels (Muschelpuster) hat etwas weiter oben auch noch einen Wunsch eingebracht. Vllt.kannst du das ma mit ganz vorn in deiner Liste mit vermerken.
Die neue Version stelle ich dann noch zum Test zur Verfügung.

Bis denne ...
Heiko

[DS_Starter]

Hallo zusammen,

hatte am WE die neue Version 2.16.9 angefertigt, hier nun zum Test.

ChangeLog:

* geändert ist die Syntax für die Addlog-Funktion.
   Damit es eine Vereinheitlichung mit dem Feel zu anderen Modulen gibt, sieht die Syntax nun so aus:
 
  ... addLog devspec:Reading [Value]
 
  Beachtet auch dass es zwischen Reading und dem optionalen Value nun ein Leerzeichen statt Komma gibt. Die generelle Änderung war
  nötig geworden um auch komplexe Angaben wie:

  addLog TYPE=CUL_HM:FILTER=model=HM-CC-RT-DN:FILTER=subType!=(virtual|):(measured-temp|desired-temp|actuator) bzw.
  addLog Dev1,Dev2,Dev3:(measured-temp|desired-temp|actuator) 
 
  abbilden zu können und damit die Devspec-Definition vollumfänglich zu unterstützen.
 
* innerhalb der valueFN-Funktion kann man nun die Werte für $VALUE und $UNIT auf Leerstring '' bzw. 0 setzen um sie so in
  die DB zu übernehmen. Solche Werte, durch Perl als "false" gewertet, wurden bisher ignoriert.
 
Bitte testet die Funktionen wie gehabt, insbesondere das AddLog mit komplexeren Strukturen.
Die Version möchte ich demnächst einchecken wenn nichts negatives auffallen sollte.

Grüße
Heiko

[DS_Starter]

Hallo,

kleiner Querverweis für all diejenigen die sich mit Datenauswertungen befassen.
DbRep wurde aktuell um eine sqlResult sqlCmd-Funktion erweitert (Danke an viegener für den Input !) mit der Benutzer beliebige SQL-Statements absetzen können. https://forum.fhem.de/index.php/topic,53584.msg633861.html#msg633861 (ist noch nicht eingecheckt).

Das gibt es zwar in DbLog ebenfalls, allerdings können die Ergebnisse vielzeilig sein und werden wie bei DbRep üblich, non-blocking ausgeführt.
Darüber hinaus kann man über ein Attribut die Darstellung des Ergebnisses verändern.

viele Grüße

[DS_Starter]

Hallo,

nochmal ein kleiner Querverweis zu DbRep.
DbRep erzeugt ja je nach ausgeführten Statement u.U. viele Readings, die eine entsprechende Eventlast erzeugen wenn man die Events erzeugen lässt um sie mit Notify weiter zu verarbeiten.
Mit der Version 4.14.0 gibt es nun eine User-Schnittstelle über die man eigenen Code zur Ausführung bringen kann OHNE dafür Events erzeugen zu müssen.
Die Erläuterung und ein praktisches Beispiel zur Anwendung findet man hier: https://forum.fhem.de/index.php/topic,53584.msg635077.html#msg635077

schönen Sonntag,
Heiko

[HCS]

Es gibt also nun "set <name> ... ":

* count (alt)                 bzw.    countNbl         (non-blocking)
* reduceLog (alt)         bzw.    reduceLogNbl     (non-blocking)
* deleteOldDays (alt)  bzw.    deleteOldDaysNbl (non-blocking)

Da ich mit deleteOldDays das Problem habe, dass FHEM so lange blockiert ist, dass mir einige Dinge aus dem Tritt geraten (die LaCrosseGateway werden neu connected, da zu lange nichts von ihnen gehört wurde, ...) und ich gerade  deleteOldDaysNbl entdeckt habe, dachte ich, dass das meine Rettung ist.

Es scheint aber mit SQLite nicht ganz zu funktionieren.

deleteOldDaysNbl 27:

Code Auswählen Erweitern

2017.06.01 08:06:47 3: DbLog commonLog -> Deletion of records older than 27 days in database /opt/fhem/dbLog/commonLog.db requested
2017.06.01 08:07:48 2: DbLog commonLog -> Error table history - DBD::SQLite::st execute_array failed: database is locked [err was 5 now 2000000000]
executing 2 generated 2 errors at ./FHEM/93_DbLog.pm line 1409.
2017.06.01 08:07:54 3: DbLog commonLog -> deleteOldDays finished. 100178 entries of database /opt/fhem/dbLog/commonLog.db deleted.
Von 08:06:47 bis 08:07:54 war FHEM dann trotzdem blockiert.

Ansonsten läuft DbLog bei mir seit je her völlig problemlos ohne irgend welche Auffälligkeiten.

[DS_Starter]

Hallo HCS,

bin Grad unterwegs und kann nicht viel schreiben, aber vermutlich lässt du deine DB noch synchron laufen.
Wenn du den asynchmode einschaltest sollte dieses Verhalten nicht mehr mit SQLite auftreten.

VG
Heiko

[HCS]

bin Grad unterwegs und kann nicht viel schreiben

Kein Problem, so eilig ist es nun wirklich nicht

Wenn du den asynchmode einschaltest sollte dieses Verhalten nicht mehr mit SQLite auftreten.

OK, habe ich jetzt eingeschaltet. Klappt schon besser, aber es ist trotzdem noch ein Fehler dabei:

Code Auswählen Erweitern

2017.06.01 11:07:19 3: DbLog commonLog -> Deletion of records older than 26 days in database /opt/fhem/dbLog/commonLog.db requested
2017.06.01 11:08:24 2: DbLog commonLog -> Error table history - DBD::SQLite::st execute_array failed: executing 40 generated 1 errors at ./FHEM/93_DbLog.pm line 1787.

2017.06.01 11:08:24 3: DbLog commonLog -> deleteOldDays finished. 114681 entries of database /opt/fhem/dbLog/commonLog.db deleted.

Ich lasse es mal so weiterlaufen, wird jede Nacht einmal erledigt.
Kannst ja mal schauen, wenn Du Zeit hast, ohne Stress und so ...