dbrep Module nach restart von fhem immer auf disconnected

[jailbreaker07]

Hallo,

Ich habe das Problem das nach einen restart von Fhem meine dbrep Instanzen immer auf disconnect gehen. Wenn ich unter def die Datenbank logdb neu eintragen dann initialisiert sich das Modul, sobald ich z.b countEntries ausführe geht das Modul direkt wieder auf disconnected. Wenn ich garnichts  mache dann bleiben die dbrep Module auf disconnected, wenn ich öfter mal die Definition neu eintrage geht es irgendwann wieder..... wenn es einmal geht da laufen die dbrep Instanzen ohne Probleme bis zum nächsten restart..... Mein Ziel ist es das die dbrep Modul nach eine restart direkt wieder connecten.....

Code Auswählen Erweitern

Internals:
   DATABASE   fhem
   DEF        logdb
   FUUID      5c44a29d-f33f-0405-ad45-eefb16c44ff76281
   LASTCMD    insert 2019-04-15,21:00:00,134.5
   MODEL      Client
   NAME       logdb_strom_WP
   NOTIFYDEV  global,logdb_strom_WP
   NR         516
   NTFY_ORDER 50-logdb_strom_WP
   ROLE       Client
   STATE      disconnected
   TYPE       DbRep
   UTF8       0
   VERSION    8.13.0
   .attraggr:
   .attrminint:
   HELPER:
     DBLOGDEVICE logdb
     IDRETRIES  -135
     I_DEVICE   Verbrauch_Monat_WP_doif
     I_EVENT    manual
     I_READING  Verbrauch
     I_TIMESTAMP 2019-04-15 21:00:00
     I_TYPE     manual
     I_UNIT     
     I_VALUE    134.5
     DBREPCOL:
       COLSET     1
       DEVICE     64
       EVENT      512
       READING    64
       TYPE       64
       UNIT       32
       VALUE      128
   READINGS:
     2019-04-17 05:19:01   state           disconnected
   dbloghash:
     .triggerUsed 1
     COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
     CONFIGURATION ./dbsynology.conf
     DEF        ./dbsynology.conf .*:.*
     FUUID      5c44a297-f33f-0405-eba5-375314849666f35f
     MODE       asynchronous
     MODEL      MYSQL
     NAME       logdb
     NR         184
     NTFY_ORDER 50-logdb
     PID        1023
     REGEXP     .*:.*
     STATE      connected
     TYPE       DbLog
     UTF8       0
     VERSION    3.13.1
     dbconn     mysql:database=fhem;host=192.168.1.20;port=3306
     dbuser     fhemuser
     .attraggr:
     .attrminint:
     .userReadings:
       HASH(0x55c565487d38)
     HELPER:
       COLSET     1
       DEVICECOL  64
       EVENTCOL   512
       OLDSTATE   connected
       READINGCOL 64
       TYPECOL    64
       UNITCOL    32
       VALUECOL   128
     READINGS:
       2019-04-17 06:37:36   CacheUsage      3
       2019-04-17 06:37:35   NextSync        2019-04-17 06:38:05 or if CacheUsage 500 reached
       2019-04-17 06:37:36   notify_processing_time 0.0004
       2019-04-17 06:37:35   state           connected
     cache:
       index      41302
       .memcache:
         41300      2019-04-17 06:37:36|WP_HTTPMod|HTTPMOD|FBH_VL: 29.3|FBH_VL|29.3|
         41301      2019-04-17 06:37:36|WP_HTTPMod|HTTPMOD|SO_RL_2: 17.0|SO_RL_2|17.0|
         41302      2019-04-17 06:37:36|WP_HTTPMod|HTTPMOD|SO_VL: 9.8|SO_VL|9.8|
Attributes:
   allowDeletion 1
   device     Verbrauch_Monat_WP_doif
   fastStart  1
   group      Datenbank
   reading    Verbrauch
   room       JCT
   timeout    86400
   timestamp_begin current_month_begin
   timestamp_end current_month_end
   verbose    2

Code Auswählen Erweitern

Internals:
   .triggerUsed 1
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./dbsynology.conf
   DEF        ./dbsynology.conf .*:.*
   FUUID      5c44a297-f33f-0405-eba5-375314849666f35f
   MODE       asynchronous
   MODEL      MYSQL
   NAME       logdb
   NR         184
   NTFY_ORDER 50-logdb
   PID        1023
   REGEXP     .*:.*
   STATE      connected
   TYPE       DbLog
   UTF8       0
   VERSION    3.13.1
   dbconn     mysql:database=fhem;host=192.168.1.20;port=3306
   dbuser     fhemuser
   .attraggr:
   .attrminint:
   .userReadings:
     HASH(0x55c565487d38)
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     OLDSTATE   connected
     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   READINGS:
     2019-04-17 06:37:01   CacheUsage      12
     2019-04-17 06:36:35   NextSync        2019-04-17 06:37:05 or if CacheUsage 500 reached
     2019-04-17 06:37:01   notify_processing_time 0.0023
     2019-04-17 06:36:35   state           connected
   cache:
     index      41286
     .memcache:
       41275      2019-04-17 06:36:35|Tuerschloss|CUL_HM|state: unreachable|state|unreachable|
       41276      2019-04-17 06:36:37|WP_HTTPMod|HTTPMOD|FBH_RL: 28.5|FBH_RL|28.5|
       41277      2019-04-17 06:36:37|WP_HTTPMod|HTTPMOD|SO_RL: 9.3|SO_RL|9.3|
       41278      2019-04-17 06:36:46|WP_HTTPMod|HTTPMOD|SO_RL: 9.4|SO_RL|9.4|
       41279      2019-04-17 06:36:46|WP_HTTPMod|HTTPMOD|SO_RL_2: 17.0|SO_RL_2|17.0|
       41280      2019-04-17 06:36:53|Stromzaehler_WP|DOIF|wh: ‪2892720‬|wh|‪2892720‬|
       41281      2019-04-17 06:36:54|Wz_Heizung|CUL_HM|desired-temp: 18.0|desired-temp|18.0|
       41282      2019-04-17 06:36:56|WP_HTTPMod|HTTPMOD|FBH_RL: 28.4|FBH_RL|28.4|
       41283      2019-04-17 06:36:56|WP_HTTPMod|HTTPMOD|SO_RL_2: 16.9|SO_RL_2|16.9|
       41284      2019-04-17 06:37:01|sysmon|SYSMON|ram_free: 3524.13|ram_free|3524.13|
       41285      2019-04-17 06:37:01|sysmon|SYSMON|eth0_diff_RX: 1107.25|eth0_diff_RX|1107.25|
       41286      2019-04-17 06:37:01|sysmon|SYSMON|eth0_diff_TX: 1246.46|eth0_diff_TX|1246.46|
Attributes:
   DbLogSelectionMode Include
   DbLogType  Current/History
   asyncMode  1
   disable    0
   group      Datenbank
   room       JCT
   showNotifyTime 1
   shutdownWait 2
   userReadings DbFileSize:reduceLogState.* { (split(' ',`du -m fhem.db`))[0] }

Vielen Dank für eure Hilfe

Gruß

Thorsten

[Frank_Huber]

Sorgt  das Attribut Faststart nicht dafür dass das DbRep erst beim ersten Gebrauch  initialisiert wird?
Nimm das mal raus und teste nochmal.

Gesendet von meinem Doogee S60 mit Tapatalk

[jailbreaker07]

Habe ich mal getestet... beim Start sind die Module initialized, sobald darauf zugegriffen wird gehen diese auf disconnect.

[DS_Starter]

Guten Morgen,

aus irgendwelchen Gründen dauert das Holen der initialen Informationen sehr lange bzw. bricht ab. Du müsstest mal den verbose Level hochdrehen und ins Log schauen was dort ausgeschrieben wird wenn das Device losgelassen wird.
Wo befindet sich deine Datenbank ?
Ich habe seit einem der letzten Synology Updates ein ähnliches Problem mit MariaDB10 auf der Syno, die MariaDB5 auf der gleichen Maschine läuft weiterhin ohne Probleme.

Bei der MariaDB10 dauert der erste Connect über 160s :

Code Auswählen Erweitern


2019.04.17 08:05:52.049 3: DbRep Rep.CPU - Initial data information retrieved successfully - total time used: 162.532141 seconds
2019.04.17 08:05:52.066 3: DbRep Rep.CPU - Connectiontest to db mysql:database=fhemtest;host=192.168.2.10;port=3307 successful


Wenn die initialen Informationen geholt sind, funktioniert alles weitere dann wieder einwandfrei.
Gib mal bitte ein paar Infos zu deiner eingesetzten DB.

Der Grund liegt wahrscheinlich darin, dass der Befehl:

Code Auswählen Erweitern

SELECT min(TIMESTAMP) FROM history;

(zu) lange dauert.
Kannst du diesen Befehl mal auf deiner DB ausführen und die Zeit messen ? Er dauert auf meiner MariaDB5 0.0009 s, auf der MariaDB10 über 100s.  Möglicherweise liegt es auch an einem Index, ich muß mir das mal auf dieser DB genauer anschauen.

LG,
Heiko

[DS_Starter]

Ich habe den Befehl

SELECT min(TIMESTAMP) FROM history;

soeben mal auf einer anderen MariaDB10 ausgeführt. Er dauerte nur 0.0010 Sekunden bei 31463560 Datensätzen.
Also irgendwie liegt es spezifisch and der MariaDB10 auf der Syno.

[jailbreaker07]

Hey DSStarter,

Code Auswählen Erweitern

SELECT min(TIMESTAMP) FROM history;

Bei meiner MariaDB10  dauert es 18,2316 Sekunden bei 18.2316  Datensätzen....
Also liegt der Fehler an der Synology? Welchen daten über die Datenbank brauchst du den?


Gruß und danke

Thorsten

[DS_Starter]

Hi Thorsten,

mir reicht erstmal die Info ob du auch MariaDB10 auf Synology nutzt.
Die Anzahl der Datensätze passt irgendwie nicht 

Das Problem will ich heute Abend versuchen auf meiner Maria10 näher einzugrenzen.

LG,
Heiko

[jailbreaker07]

Hallo,

MariaDB10 ist installiert auf der Synology, aber diese wird nicht verwendet.... Verwendet wird nur die MariaDB5...


eine dbrep habe ich mal auf verbose 5 gestellt. Diese war disconnected...nachher war diese dann wieder connectet.....hmm

Dann bis heute Abend

Code Auswählen Erweitern

2019.04.17 09:46:00 3: DbRep logdb_strom_monat_jct - get initial structure information of database "fhem", remaining attempts: -76
2019.04.17 09:46:13 4: DbRep logdb_strom_monat_jct - initialized
2019.04.17 09:46:17 3: DbRep logdb_strom_monat_jct - Connectiontest to database mysql:database=fhem;host=192.168.1.20;port=3306 with user fhemuser
2019.04.17 09:46:22 3: DbRep logdb_strom_monat_jct - WARNING - old process 32283 will be killed now to start a new BlockingCall
2019.04.17 09:46:22 1: DbRep logdb_strom_monat_jct -> BlockingCall DbRep_getInitData pid:32283 Timeout: process terminated
2019.04.17 09:46:22 3: DbRep logdb_strom_monat_jct - get initial structure information of database "fhem", remaining attempts: 3
2019.04.17 09:46:22 3: DbRep logdb_strom_monat_jct - Connectiontest to database mysql:database=fhem;host=192.168.1.20;port=3306 with user fhemuser
2019.04.17 09:46:42 3: DbRep logdb_strom_monat_jct - Initial data information retrieved successfully - total time used: 20.449708 seconds
2019.04.17 09:46:42 3: DbRep logdb_strom_monat_jct - Connectiontest to db mysql:database=fhem;host=192.168.1.20;port=3306 successful
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - -------- New selection ---------
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - Command: countEntries history
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - Timestamp begin epocheseconds: 1555452000
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - Timestamp begin human readable: 2019-04-17 00:00:00
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - Timestamp end epocheseconds: 1555538399
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - Timestamp end human readable: 2019-04-17 23:59:59
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - weekday of start for selection: Mi  ->  wdadd: 432000
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - Aggregation: no
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - IsTimeSet: 1, IsAggrSet: 0
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - Timestamp-Array:
no_aggregation#2019-04-17 00:00:00#2019-04-17 23:59:59
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - Devices for operation - included: Verbrauch_heute_doif , excluded:
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - Readings for operation - included: Verbrauch, excluded: 
2019.04.17 09:46:42 4: DbRep logdb_strom_monat_jct - SQL execute: SELECT COUNT(*) FROM history where DEVICE = 'Verbrauch_heute_doif' AND READING = 'Verbrauch' AND TIMESTAMP >= '2019-04-17 00:00:00' AND TIMESTAMP <= '2019-04-17 23:59:59' ;
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - SQL result: 1
2019.04.17 09:46:42 5: DbRep logdb_strom_monat_jct - SQL result decoded: no_aggregation#ALLREADINGS#1#2019-04-17|


[DS_Starter]

Bis heute Abend 
Ich hab schon etwas gesehen:

2019.04.17 09:46:22 3: DbRep logdb_strom_monat_jct - WARNING - old process 32283 will be killed now to start a new BlockingCall
2019.04.17 09:46:22 1: DbRep logdb_strom_monat_jct -> BlockingCall DbRep_getInitData pid:32283 Timeout: process terminated

Wahrscheinlich startest du aus Ungeduld  weil nach dem Anstarten von countEntries nichts passiert, es nochmal an.
Dadurch wird der (zu lange laufende initiale Connect) abgebrochen und neu aufgesetzt.
Einfach nichts tun und warten nach dem ersten Anstarten. 

Den Rest später ...

[jailbreaker07]

Hey,
das Problem tritt wahrscheinlich deshalb auf, weil ich mit einen doif alte Datensätze lösche und die neuen dann 4 Sekunden später einfüge. Das ganze ca alle 180 Sekunden.
Wenn ich das entsprechende doif disable und ich bei den dbrep im initialisierten Zustand Manuel eine Aktion ausführe und ich abwarte, dann steht im state später done.... 

Gruß

Thorsten

[DS_Starter]

Ja genau.
Lösung wäre für beide Aufgaben jeweils ein zugeodnetes DbRep zu verwenden.
Einfach kopieren.

LG

[jailbreaker07]

Hey Heiko,

so habe ich das nun gelöst.....

Code Auswählen Erweitern

([Stromzaehler_JCT:energy]and [00:30-23:59]and [logdb_strom_monat_jct]ne "initialized") 
(setreading $SELF Verbrauch {([Zaehlerstand_doif:Zaehlerstand]-[Zaehlerstand_doif:Zaehlerstand_gestern])})
(set logdb_strom_monat_jct delEntries)
{ fhem "set logdb_strom_monat_jct insert ".$year."-".sprintf("%02d",$month)."-".sprintf("%02d",$mday).",00:00:00,".(ReadingsNum("Verbrauch_heute_doif","Verbrauch",0) ) }
DOELSE

So greifen die doif´s erst auf das dbrep zu wenn es nicht mehr am initialisieren ist.... Hat nach einen neustart von fhem super funktioniert.... Danke für die Hilfe

Gruß

Thorsten

[DS_Starter]

Hallo Thorsten,

prima 
Ich bin auch schon ein Stückchen weiter.
Es ist nicht das Problem der DB, sondern eine ungüstige Indexverwendung. Ich versuche das Statement zu verändern um das Problem an der Wurzel zu beseitigen.
Du könntest einen Test im DbRep machen wenn ich etwas brauchbares habe.

Grüße,
Heiko

[DS_Starter]

Kannst du mal bitte im DbRep ausführen:

Code Auswählen Erweitern

set ... sqlCmd ALTER TABLE `fhemtest`.`history` DROP INDEX `Report_Idx`, ADD INDEX `Report_Idx` (TIMESTAMP,READING) USING BTREE;

Das sollte längere Zeit laufen. Wenn nicht, alternativ dann bitte getrennt durchführen:

Code Auswählen Erweitern

set ... sqlCmd ALTER TABLE `fhemtest`.`history` DROP INDEX `Report_Idx`;
set ... sqlCmd ALTER TABLE ADD INDEX `Report_Idx` (TIMESTAMP,READING) USING BTREE;

Wenn das durch ist, ein

Code Auswählen Erweitern

get ... minTimestamp

ausführen. Jetzt sollte die Abfrage im Millisekundenbereich eine Antwort bringen.

Grüße,
Heiko

[jailbreaker07]

Hey,

Beides geht leider nicht:

Code Auswählen Erweitern

DBD::mysql::st execute failed: Table 'fhemtest.history' doesn't exist at ./FHEM/93_DbRep.pm line 5673.

Gruß

Thorsten


Gesendet von iPhone mit Tapatalk