Bei DbRep insert seit kurzen immer die Meldung "...BlockingCall del_DoParse ..."

jailbreaker07 · 30 März 2018, 09:31:31

Hallo,

Mittwoch bin ich mit meiner fhem Konfiguration auf einem Intel Nuc7 mit installierten debian umgestiegen.

Manuel füge ich über ein doif regelmäßig über insert Datenbänke ein.....

Seit heute Nacht kommt bei jeden insert folgendes in der Logfile

Code Auswählen

DbRep logdb_strom_monat_A -> BlockingCall del_DoParse pid:3714 Timeout: process terminated

Was genaue bedeutet das ? Durch google bin ich nicht viel schlauer geworden...... Die Datenbank läuft auf einer Synology...

Gruß

Thorsten

DS_Starter · 30 März 2018, 10:23:28

Hallo Thorsten,

du hast wahrscheinlich vor deinem Insert noch einen DbRep-Vorgang angestartet der mit "delEntries" Daten aus der Datenbank löscht.
Dieser Vorgang ist noch nicht fertg, deswegen wird der Prozess beim Start von "Insert" abgebrochen damit nur ein BlockingCall läuft.

Plane das delete etwas früher ein bzw. schaue mal warum dein delete jetzt solange dauert. Möglicherweise fehlt ein Index auf der DB ->" set <dblog> configCheck" ausführen könnte helfen.

viele Grüße und schönes Ostern,
Heiko

DS_Starter · 30 März 2018, 10:30:41

Ergänzung.... das passiert nur wenn du für beide Aufgaben dasselbe DbRep-Device nutzt.
Lege dir für jede Aufgabe eine separates DbRep an, so mache ich das. Dann beeinflussen die Aufgaben sich nicht gegeneseitig.

jailbreaker07 · 30 März 2018, 11:15:47

Danke das werde ich tun,
mir ist aufgefallen das DbRep die gewünschten Inhalte garnicht mehr löscht (done kommt aber als Rückmeldung..) seitdem ich auf dem Nuc umgestiegen bin... Schreiben tut er aber in die Datenbank....
hmm

DS_Starter · 30 März 2018, 11:21:42

Das Löschen klappt wegen dem oben beschriebenen Sachverhalt nicht mehr.
Wie gesagt, am Besten für beide Aufgaben ein separates Device erstellen.

jailbreaker07 · 30 März 2018, 11:34:25

Ich habe jetzt alles Deaktiviert was auf das entsprechende DbRep zugreift....
Wenn ich Daten per Insert einfügte ist alle ok
DelEntries wie auch CountEntries funktionieren nicht.....
bei exporttofile wird auch nichts übertragen.....

Also zusammengefast schreiben geht lesen und löschen nicht.....
plots zeigen jedoch etwas an....

DS_Starter · 30 März 2018, 11:49:57

Na dann wie üblich verbose hochsetzen und Posten was im Log steht

jailbreaker07 · 30 März 2018, 11:57:03

HAbe den Fehler gefunden,

timestamp_begin ist mit "current_month_begin" gesetzt....
timestamp_end war nicht gesetzt... jetzt habe ich dort "current_month_end" gesetzt und es funktioniert ......

Aber es hat vorher immer funktioniert.... hmm....

DS_Starter · 30 März 2018, 12:25:47

Das muss auch ohne gesetzten timestamp_end klappen.
Verbose 4 setzen und Mal posten was das Log ausschreibt.

jailbreaker07 · 30 März 2018, 19:08:20

Zitat von: DS_Starter am 30 März 2018, 12:25:47
Das muss auch ohne gesetzten timestamp_end klappen.
Verbose 4 setzen und Mal posten was das Log ausschreibt.

Hey,

hier ist das Ergebnis....:

Code Auswählen

2018.03.30 19:06:02 4: DbRep logdb_strom_A - -------- New selection --------- 
2018.03.30 19:06:02 4: DbRep logdb_strom_A - Command: delEntries 
2018.03.30 19:06:02 4: DbRep logdb_strom_A - Timestamp begin human readable: 2018-03-01 00:00:00
2018.03.30 19:06:02 4: DbRep logdb_strom_A - Timestamp end human readable: 2018-03-30 19:06:02
2018.03.30 19:06:02 4: DbRep logdb_strom_A - Aggregation: no
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - Command: delEntries 
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-03-30 00:00:00
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-03-30 19:06:02
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - Aggregation: no
2018.03.30 19:06:02 4: DbRep logdb_strom_A -> Start BlockingCall del_DoParse
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A -> Start BlockingCall del_DoParse
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A - SQL execute: delete FROM history where DEVICE = 'Verbrauch_heute_A_doif' AND READING = 'Verbrauch' AND TIMESTAMP >= '2018-03-30 00:00:00' AND TIMESTAMP <= '2018-03-30 19:06:02' ;
2018.03.30 19:06:02 4: DbRep logdb_strom_A - SQL execute: delete FROM history where DEVICE = 'Verbrauch_Monat_A_doif' AND READING = 'Verbrauch' AND TIMESTAMP >= '2018-03-01 00:00:00' AND TIMESTAMP <= '2018-03-30 19:06:02' ;
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A -> BlockingCall del_DoParse finished
2018.03.30 19:06:02 4: DbRep logdb_strom_A -> BlockingCall del_DoParse finished
2018.03.30 19:06:02 4: DbRep logdb_strom_A -> Start BlockingCall del_ParseDone
2018.03.30 19:06:02 3: DbRep logdb_strom_A - Entries of fhem.history deleted: Verbrauch_Monat_A_doif--Verbrauch--1
2018.03.30 19:06:02 4: DbRep logdb_strom_A -> BlockingCall del_ParseDone finished
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A -> Start BlockingCall del_ParseDone
2018.03.30 19:06:02 3: DbRep logdb_strom_monat_A - Entries of fhem.history deleted: Verbrauch_heute_A_doif--Verbrauch--1
2018.03.30 19:06:02 4: DbRep logdb_strom_monat_A -> BlockingCall del_ParseDone finished
2018.03.30 19:06:04 4: DbRep logdb_strom_A - -------- New selection --------- 
2018.03.30 19:06:04 4: DbRep logdb_strom_A - Command: insert 
2018.03.30 19:06:04 4: DbRep logdb_strom_A - Timestamp begin human readable: 2018-03-01 00:00:00
2018.03.30 19:06:04 4: DbRep logdb_strom_A - Timestamp end human readable: 2018-03-30 19:06:04
2018.03.30 19:06:04 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.03.30 19:06:04 4: DbRep logdb_strom_monat_A - Command: insert 
2018.03.30 19:06:04 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-03-30 00:00:00
2018.03.30 19:06:04 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-03-30 19:06:04
2018.03.30 19:06:04 4: DbRep logdb_strom_A -> Start BlockingCall insert_Push
2018.03.30 19:06:04 4: DbRep logdb_strom_monat_A -> Start BlockingCall insert_Push
2018.03.30 19:06:05 4: DbRep logdb_strom_A -> BlockingCall insert_Push finished
2018.03.30 19:06:05 4: DbRep logdb_strom_A -> Start BlockingCall insert_Done
2018.03.30 19:06:05 4: DbRep logdb_strom_A -> BlockingCall insert_Done finished
2018.03.30 19:06:05 4: DbRep logdb_strom_monat_A -> BlockingCall insert_Push finished
2018.03.30 19:06:05 4: DbRep logdb_strom_monat_A -> Start BlockingCall insert_Done
2018.03.30 19:06:05 4: DbRep logdb_strom_monat_A -> BlockingCall insert_Done finished

Gruß

Thorsten

DS_Starter · 30 März 2018, 19:19:20

Sieht doch gut aus. Die Statements sehen gut aus und auch kein Fehler. Zeitabgrenzung passt auch soweit ich sehe.

Grüsse,
Heiko

jailbreaker07 · 02 April 2018, 08:58:12

Guten morgen,

jetzt war ziemlich lange ruhig was die Datenbank angeht....
jeodch ist anscheinend wieder Schluss damit :-/
Zum testen habe ich nur ein von vier dbRep Device aktiviert gelassen....

Bevor das ganze anfing kam diese Meldung:

Code Auswählen

2018.04.01 23:12:42 2: DbLog logdb - Error: DBI connect('database=fhem;host=192.168.1.20;port=3306','fhemuser',...) failed: Can't connect to MySQL server on '192.168.1.20' (111) at ./FHEM/93_DbLog.pm line 1875.

Code Auswählen

2018.04.02 08:44:58 1: DbRep logdb_strom_A -> BlockingCall del_DoParse pid:18845 Timeout: process terminated
2018.04.02 08:47:19 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:47:19 4: DbRep logdb_strom_monat_A - Command: delEntries 
2018.04.02 08:47:19 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:47:19 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59
2018.04.02 08:47:19 4: DbRep logdb_strom_monat_A - Aggregation: no
2018.04.02 08:47:21 3: DbRep logdb_strom_monat_A - WARNING - old process 18960 will be killed now to start a new BlockingCall
2018.04.02 08:47:21 1: DbRep logdb_strom_monat_A -> BlockingCall del_DoParse pid:18960 Timeout: process terminated
2018.04.02 08:47:21 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:47:21 4: DbRep logdb_strom_monat_A - Command: insert 
2018.04.02 08:47:21 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:47:21 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59
2018.04.02 08:49:30 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:49:30 4: DbRep logdb_strom_monat_A - Command: delEntries 
2018.04.02 08:49:30 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:49:30 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59
2018.04.02 08:49:30 4: DbRep logdb_strom_monat_A - Aggregation: no
2018.04.02 08:49:32 3: DbRep logdb_strom_monat_A - WARNING - old process 19214 will be killed now to start a new BlockingCall
2018.04.02 08:49:32 1: DbRep logdb_strom_monat_A -> BlockingCall del_DoParse pid:19214 Timeout: process terminated
2018.04.02 08:49:32 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:49:32 4: DbRep logdb_strom_monat_A - Command: insert 
2018.04.02 08:49:32 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:49:32 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59
2018.04.02 08:51:27 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:51:27 4: DbRep logdb_strom_monat_A - Command: delEntries 
2018.04.02 08:51:27 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:51:27 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59
2018.04.02 08:51:27 4: DbRep logdb_strom_monat_A - Aggregation: no
2018.04.02 08:51:29 3: DbRep logdb_strom_monat_A - WARNING - old process 19342 will be killed now to start a new BlockingCall
2018.04.02 08:51:29 1: DbRep logdb_strom_monat_A -> BlockingCall del_DoParse pid:19342 Timeout: process terminated
2018.04.02 08:51:29 4: DbRep logdb_strom_monat_A - -------- New selection --------- 
2018.04.02 08:51:29 4: DbRep logdb_strom_monat_A - Command: insert 
2018.04.02 08:51:29 4: DbRep logdb_strom_monat_A - Timestamp begin human readable: 2018-04-02 00:00:00
2018.04.02 08:51:29 4: DbRep logdb_strom_monat_A - Timestamp end human readable: 2018-04-02 23:59:59

Gruß

Thorsten

DS_Starter · 02 April 2018, 09:18:27

Hallo Thorsten,

das die BlockingCalls von "delEntries" und "insert" sich gegenseitig wegschießen kommt von dem schon weiter oben erläuterten Zusammenhang.
Das kannst du mit mehreren DbReps, eines für jede Aufage, vermeiden.

Aber das eigentliche Problem scheint die Datenbank zu sein. die reagiert nicht schnell genug oder überhaupt nicht wie der DbLog-Error vermuten lässt.

Es ist fraglich ob man mit FHEM-Mitteln die Ursache dafür finden kann.
Anhaltspunkte:

Wo läuft die DB ?
Hast du mal mit einem SQL-Client (HeidiSQL, phpMyAdmin) versucht zuzugreifen ?
Ist genügend Plattenplatz für die DB verfügbar ?
Logfile von MySQL mal angeschaut / ausgewertet ?

Grüße,
Heiko

jailbreaker07 · 02 April 2018, 12:37:29

Zitatdas die BlockingCalls von "delEntries" und "insert" sich gegenseitig wegschießen kommt von dem schon weiter oben erläuterten Zusammenhang.
Das kannst du mit mehreren DbReps, eines für jede Aufage, vermeiden.

Das werde ich noch entsprechend ändern... Das würde das Problem aktuell lösen.... das löschen von einem Datensatz dauert 10 Sekunden bis wieder done erscheint.. Und das kann nicht normal sein....

ZitatHast du mal mit einem SQL-Client (HeidiSQL, phpMyAdmin) versucht zuzugreifen ?

Mit phpMyAdmi- über die Synology geht ein Zugriff....

ZitatIst genügend Plattenplatz für die DB verfügbar ?

Das muss ich noch irgendwie herausfinden....

ZitatLogfile von MySQL mal angeschaut / ausgewertet ?

Bin dabei die zu suchen ...grr....

Wie gesagt alles andere geht .... geschrieben wird und Plots werden erzeugt...

Gruß

Thorsten
Seitdem ich alle vie DbRep Device's ausgeschaltet habe ist das Logfile auch schön leer.....

DS_Starter · 02 April 2018, 13:12:30

Zitatdas löschen von einem Datensatz dauert 10 Sekunden bis wieder done erscheint

Das ist eindeutig zu lange. Bei mir geht sowas in 0.00xx Sekunden. Hab die DB auch auf der Syno.
Stell dir mal das Attr showproctime=1 ein um die Abarbeitungszeiten zu sehen. Index vorhanden ? (DbLog -> configCheck)

ZitatBin dabei die zu suchen ...grr...

Im DbRep ein "get ... dbvars" ausführen. Das Reading "VAR_log_error" zeigt dir das error-logfile.

ZitatSeitdem ich alle vie DbRep Device's ausgeschaltet habe ist das Logfile auch schön leer.....

Das geht auch mit attr verbose =1 / 0

ZitatMit phpMyAdmi- über die Synology geht ein Zugriff....

Ok, nicht das es Netzwerkprobleme zwischen dem NUC und der Syno gibt. Nur mal als Ansatzpunkt. Der fehlerhafte Verbindungsaufbau bei DbLog ist seltsam ...

Grüße
Heiko