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

[abc2006]

Okay, hab den Fehler gefunden .. hoffentlich blick ich bei den Dateien jetzt noch durch xD

Code Auswählen Erweitern

2017-12-17 04:00:02|alarmbot|TELEGRAMBOT||state|message calcVL:
Aussentemperatursensor überprüfen!!|
2017-12-17 04:00:02|PID.FUBO|PID20||desired|31.5|

der Zeilenumbruch erzeugt den Fehler.
Hat sich für mich erledigt, weil ich  (vorhin schon ) alle bots vom Log ausgeschlossen habe.
Kannst du das aber trotzdem irgendwie abfangen? so dass es zb umgewandelt wird in ein lesbares \n, wenn/falls die Datenbank damit nicht umgehen kann?

ich.. versuch mal, die restlichen Dateien jetzt zu importieren

Grüße,
Stephan

[abc2006]

So, ich habe mich jetzt durchgewühlt.. fürchte, ich hab ein paar duplikate und ein paar Lücken erzeugt.
Werde jetzt umstellen auf exportFile mit purgeCache, dafür das limit etwas höher.
und im Zweifel, das hatte ich nämlich nicht bedacht, können die Dateien mit
cat zusammengefügt werden ...

Grüße,
stephan

[DS_Starter]

Hallo Stephan,

da hast du dich ja klasse durchgearbeitet 

fürchte, ich hab ein paar duplikate und ein paar Lücken erzeugt.

Die Duplikate kannst du vllt. mit der neuen DbRep-Funktion delSeqDoublets wieder loswerden.

Kannst du das aber trotzdem irgendwie abfangen? so dass es zb umgewandelt wird in ein lesbares \n, wenn/falls die Datenbank damit nicht umgehen kann?

Das gibt es bereits ! Dazu aktivierst du dir das Attribut useCharfilter=1. Damit werden Steuerzeichen entfernt und Umlaute umgesetzt.
Es wirkt momentan nur beim loggen, ich werde die Filtermöglichkeit noch in die importCachfile Funktion einbauen. Setze dir dieses Attribut am Besten. Dann sollte so etwas wie du erlebt hast nicht mehr vorkommen.

Gibt es eine Möglichkeit, Dateien, deren Inhalt *doch* committed werden konnte, wieder zu entfernen? Oder ein Datenbank-Handle, welches sich mit jedem erfolgreichen Zugriff ändert, so dass man es zur Serienidentifikation von fehlgeschlagenen commits verwenden kann?

So etwas kann ich nicht realisieren. Um doppelte DB-Einträge zu verhindern, ist ein primary key das probate Mittel. Dann kann man auch wiederholt ein File importieren ohne dass mehrfach identische Einträge angelegt werden.

e) was hältst du davon, wenn ein Fehler auftritt, die fehlerhafte Zeile 1:1 ins Log zu schreiben?

Habe nochmal nachgeschaut .... es wird jetzt schon mit verbose level 3 im Logfile wenn ein Datensatz nicht weggeschrieben werden konnte.
Allerdings muss das DB-Interface diese Info liefern, sonst kann nichts protokolliert werden.

LG,
Heiko

[DS_Starter]

Hallo zusammen,

anbei die Version 3.5.0.

Der Zeichenfilter (einschalten mit dem Attribut useCharfilter ) wirkt nun auch bei importCacheFile und addCacheLine.
Der Filter wird nun direkt auf den zu verarbeitenden Event angewendet. Es werden unerwünschte Steuerzeichen im Event ausgesondert.
Die commandref ist diesbezüglich etwas erweitert.

Grüße
Heiko

[abc2006]

Habe nochmal nachgeschaut .... es wird jetzt schon mit verbose level 3 im Logfile wenn ein Datensatz nicht weggeschrieben werden konnte.
Allerdings muss das DB-Interface diese Info liefern, sonst kann nichts protokolliert werden.

Hi,
vielleicht haben wir uns da missverstanden: es ging nicht darum, *dass* ein Datensatz nicht weggeschrieben werden konnte (das stand ja drin), sondern *welcher* Datensatz nicht geschrieben werden konnte... das hätte mir vermutlich etwa 6h arbeit gespart heute
Zumal ich diese blöden Meldungen *eigentlich* eh nicht speichern wollte 

EDIT:
PK-> würdest du den auf TIMESTAMP anwenden?
Es müsste vielleicht mal ne Wiki-Seite mit den ganzen Datenbankoptimierungen geben... vielleicht fang ich sowas mal an, mir fehlt da aber noch enorm Verständnis.
Ist die Wahrscheinlichkeit, dass zwei Events zum gleichen Zeitpunkt kommen, hinreichend gering?

Grüße,
Stephan

[DS_Starter]

vielleicht haben wir uns da missverstanden: es ging nicht darum, *dass* ein Datensatz nicht weggeschrieben werden konnte (das stand ja drin), sondern *welcher*

Nein, schon richtig verstanden. Es wird auch im Logfile ausgegeben welche Daten Probleme bereiten. Das geht aber nur sofern das DB-.Interface die Information rausbringt. Regelmäßig passiert das wenn ein Datensatz wegen eines gesetzten PK nicht geschrieben werden kann.

PK-> würdest du den auf TIMESTAMP anwenden?
Es müsste vielleicht mal ne Wiki-Seite mit den ganzen Datenbankoptimierungen geben... vielleicht fang ich sowas mal an, mir fehlt da aber noch enorm Verständnis.
Ist die Wahrscheinlichkeit, dass zwei Events zum gleichen Zeitpunkt kommen, hinreichend gering?

ja, habe ich gemacht. Timestamp, device, reading ist mit dabei. Bei mir ist diese Kombination genau richtig.
Ich glaube so eine Wikiseite wurde schon begonnen, habe aber keine Zeit dafür ...

Grüße
Heiko

[abc2006]

Hi,
seit ein paar Minuten habe ich wieder ein Problem:
State vom logdb-Device sagt:

Code Auswählen Erweitern


state
Commit already running - resync at NextSync
2017-12-20 14:44:01


Mein Device sieht wie folgt aus:

Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 0, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./db_fhem.conf
   DEF        ./db_fhem.conf .*:.*
   MODE       asynchronous
   MODEL      MYSQL
   NAME       logdb
   NR         311
   NTFY_ORDER 50-logdb
   PID        8425
   REGEXP     .*:.*
   STATE      Commit already running - resync at NextSync
   TYPE       DbLog
   UTF8       1
   VERSION    3.4.0
   dbconn     mysql:database=fhem;host=localhost;port=3306
   dbuser     fhemuser
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   0
     OLDSTATE   Commit already running - resync at NextSync
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   READINGS:
     2017-12-20 14:46:23   CacheUsage      1060
     2017-12-20 14:46:23   NextSync        2017-12-20 14:47:23 or if CacheUsage 1000 reached
     2017-12-20 14:43:02   lastCachefile   ./log/cache_logdb_2017-12-20_14-43-02 export successful
     2017-12-20 14:46:23   state           Commit already running - resync at NextSync
   cache:
     index      1060
Attributes:
   DbLogSelectionMode Include
   DbLogType  History
   asyncMode  1
   cacheEvents 2
   cacheLimit 1000
   colEvent   0
   room       Logging
   syncInterval 60
   useCharfilter 1
   userReadings DbFileSize:lastReduceLogResult.* { (split(' ',`du -m fhem.db`))[0] }
   verbose    5

configCheck:

Result of connection check

Connection to database fhem successfully done.
Recommendation: settings o.k.

Result of encoding check

Encoding used by Client (connection): UTF8
Encoding used by DB fhem: UTF8
Recommendation: settings o.k.

Result of logmode check

Logmode of DbLog-device logdb is: asynchronous
Recommendation: settings o.k.

Result of table 'history' check

Column width set in DB fhem.history: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Column width used by logdb: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 0, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Recommendation: settings o.k.

Result of table 'current' check

Column width set in DB fhem.current: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Column width used by logdb: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 0, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Recommendation: settings o.k.

Result of check 'Search_Idx' availability

Index 'Search_Idx' exists and contains the recommended fields 'DEVICE', 'READING', 'TIMESTAMP'.
Recommendation: settings o.k.

Result of check 'Report_Idx' availability for DbRep-devices

You use at least one DbRep-device assigned to logdb, but the recommended index 'Report_Idx' is missing.
Recommendation: You can create the index by executing statement 'CREATE INDEX Report_Idx ON `history` (TIMESTAMP, READING) USING BTREE;'
Depending on your database size this command may running a long time.
Please make sure the device 'logdb' is operating in asynchronous mode to avoid FHEM from blocking when creating the index.
Note: If you have just created another index which covers the same fields and order as suggested (e.g. a primary key) you don't need to create the 'Report_Idx' as well !

in der Log-Datei steht kein Hinweis auf einen Fehler, nur quasi die "Antwort" auf mein DOIF/notify, welches die anzahl der Datensätze überwacht und den exportCache sowie den purgeCache anstößt und mir per Telegram eine Info zukommen lässt.

Code Auswählen Erweitern

2034101 2017.12.20 14:43:00.652 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034102 2017.12.20 14:43:01.021 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034103 2017.12.20 14:43:01.196 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034104 2017.12.20 14:43:01.255 1: PERL WARNING: Argument "-62317 W" isn't numeric in subtraction (-) at FHEM/TimeSeries.pm line 247.
2034105 2017.12.20 14:43:01.255 1: PERL WARNING: Argument "-62317 W" isn't numeric in sort at FHEM/TimeSeries.pm line 316.
2034106 2017.12.20 14:43:01.256 1: PERL WARNING: Argument "-62317 W" isn't numeric in numeric lt (<) at FHEM/TimeSeries.pm line 354.
2034107 2017.12.20 14:43:01.282 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034108 2017.12.20 14:43:01.302 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034109 2017.12.20 14:43:01.321 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034110 2017.12.20 14:43:01.339 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034111 2017.12.20 14:43:01.740 5: DbLog logdb -> Number of cache entries reached cachelimit 1000 - start database sync.
2034112 2017.12.20 14:43:02.080 3: DbLog logdb: 3217 cache rows exported to ./log/cache_logdb_2017-12-20_14-43-02.
2034113 2017.12.20 14:43:04.892 1: PERL WARNING: Subroutine myUtilsHZG_Initialize redefined at ./FHEM/99_myUtilsHZG.pm line 14.
2034114 2017.12.20 14:43:04.893 1: PERL WARNING: Subroutine getStoredEnergy redefined at ./FHEM/99_myUtilsHZG.pm line 18.
2034115 2017.12.20 14:43:04.897 1: PERL WARNING: Subroutine controlVL redefined at ./FHEM/99_myUtilsHZG.pm line 77.
2034116 2017.12.20 14:43:04.900 1: PERL WARNING: Subroutine UWP_Garage redefined at ./FHEM/99_myUtilsHZG.pm line 338.
2034117 2017.12.20 14:43:04.907 1: PERL WARNING: Subroutine Heizschleifenbetrieb redefined at ./FHEM/99_myUtilsHZG.pm line 379.
2034118 2017.12.20 14:43:04.910 1: PERL WARNING: Subroutine calcVL redefined at ./FHEM/99_myUtilsHZG.pm line 629.
2034119 2017.12.20 14:43:04.914 1: PERL WARNING: Subroutine Heizkesselbetrieb redefined at ./FHEM/99_myUtilsHZG.pm line 723.
2034120 2017.12.20 14:43:04.917 1: PERL WARNING: Subroutine kessel redefined at ./FHEM/99_myUtilsHZG.pm line 826.
2034121 2017.12.20 14:43:04.919 1: PERL WARNING: Subroutine set_temp_values redefined at ./FHEM/99_myUtilsHZG.pm line 874.
2034122 2017.12.20 14:43:04.921 1: PERL WARNING: Subroutine getHashTemps redefined at ./FHEM/99_myUtilsHZG.pm line 906.
2034123 2017.12.20 14:43:04.923 1: PERL WARNING: Subroutine getResTemps redefined at ./FHEM/99_myUtilsHZG.pm line 965.
2034124 2017.12.20 14:43:04.932 1: PERL WARNING: Subroutine OWtemp redefined at ./FHEM/99_myUtilsHZG.pm line 989.
2034125 2017.12.20 14:43:04.936 1: PERL WARNING: Subroutine move_heat redefined at ./FHEM/99_myUtilsHZG.pm line 1075.
2034126 2017.12.20 14:43:04.993 3: N_backupMyUtils return value: -1
2034127 2017.12.20 14:43:05.026 1: Perfmon: possible freeze starting at 14:43:04, delay is 1.026


mysql tut *nichts*:

Code Auswählen Erweitern

mysql> show full processlist;
+------+----------+-----------+------+---------+------+----------+-----------------------+
| Id   | User     | Host      | db   | Command | Time | State    | Info                  |
+------+----------+-----------+------+---------+------+----------+-----------------------+
| 2497 | fhemuser | localhost | fhem | Sleep   |  821 |          | NULL                  |
| 2520 | root     | localhost | NULL | Query   |    0 | starting | show full processlist |
+------+----------+-----------+------+---------+------+----------+-----------------------+
2 rows in set (0.00 sec)

mysql>


Was kann ich tun?

Grüße,
Stephan

[DS_Starter]

- aktuelles fhem update (heute morgen ) machen
- du machst ein export mit purgecache, dann ist nach dem export der cache leer, richtig ?
- schau in das erzeugte file ob dir etwas auffällt was noch störend sein könnte.oder schicke dax file mal als pm wenn das geht, du das willst

Grüße
Heiko

[abc2006]

Hi,
- update ist gemacht,
- der Cache ist nach dem export und purge leer, ja
- der Fehler tritt jetzt natürlich nicht mehr auf (nach dem shutdown restart).
- in den Logfiles steht nix aussergewöhnliches drin, und sie lassen sich auch einwandfrei mit importCacheFile einlesen.
- ein neustart von mysql hat nicht geholfen
- der neustart von FHEM hats dann gelöst.

Ich melde mich, wenns was neues gibt.
Wenn du *immer noch/trotzdem* ein Logfile haben willst, sag bescheid..

Grüße,
Stephan

[DS_Starter]

da sich die cachefiles einwandfrei einlesen lassen macht es wenig sinn darin noch zu suchen. Wobei nun der charfilter auch beim importcachefile wirkt.  Möglicherweise dann doch einen Blick wert ....
In der eingecheckten version habe ich den charfilter an eine andere stelle gesetzt die sich direkt auf den übermittelten event auswirkt, deswegen war es wichtig das update zu machen. ich habe es bei mir mit künstlich erzeugten daten die einen zeilenumbruch enthielten ausgetestet .... hat einwandfrei funktioniert.

wenn es nochmal auftreten sollte und du dbrep v7.0.0 im einsatz hast dann mch mal ein get blockinginfo. die ausgabe erfolgt gekürzt und blockiert nicht den browser. schau dir auch mal das globale attribut blockingcallmax an. Hast du das gesetzt ?

Edit: was du auch in dieser Situation machen kannst .... ein set reopen


Grüsse,
Heiko

[abc2006]

blockingcallmax -> war gesetzt. auf 2. Warum auch immer, habs jetzt mal auf 5 geändert. Kann natürlich dann direkt der Grund gewesen sein.

Möglicherweise dann doch einen Blick wert .... -> hab die Dateien mal durchgeschaut.. ein Zeilenumbruch isses jedenfalls nicht...

get blockinginfo -> werd ich machen, hab ich diesmal natürlich wieder vergessen. hmpf.

set reopen -> ob ich jetzt ein set reopen mache oder ein shutdown restart... meistens installier ich dann auch noch system-updates und reboote den ganzen Rechner. Versuch ich nächtes mal aber dran zu denken.

Grüße,
Stephan

[DS_Starter]

ja die begrenzung durch blockingcallmax kann sich ungünstig auswirken. ich müsste mal in rudis code reinschauen wie sich der parameter genau auswirkt, begrenzend oder nur verzögernd, bin mir unsicher.
weshalb hast den überhaupt gesetzt ? Hast du probleme mit den forks ?

LG
Heiko

[DS_Starter]

das bringt mich auf die idee das setting von global blockingcallmax im configcheck mit zu überprüfen und den user darauf hinzuweisen falls sehr eng gesetzt..

Grüsse
Heiko

[Pyromane]

ich müsste mal in rudis code reinschauen wie sich der parameter genau auswirkt, begrenzend oder nur verzögernd, bin mir unsicher.

Laut Wiki:

Sofern die maximale parallele Anzahl an BlockingCalls erreicht ist, werden weitere Calls in eine Warteschlange eingereiht und ausgeführt, sobald laufende Calls beendet werden.

https://wiki.fhem.de/wiki/Blocking_Call#Einschr.C3.A4nkungen

Danke für den Hinweis, dessen war ich mir bisher nicht bewusst.

[DS_Starter]

Hallo Pyro,

das erspart mir das nachgrasen im Code. 
Damit ist auch klar dass in dem Fall eine nicht näher festgelegte Verzögerung eintritt.

@alll, anbei ist die erweiterte Version 3.6.0.
Ich habe die blockingCallMax-Prüfung im configCheck mit eingebaut und dabei gleichzeitig auch den configCheck für SQLITE-Datenbanken verfügbar gemacht.

Grüße
Heiko