CC1101 Timing Probleme

rolandw · November 17, 2020, 3:32pm

Hallo zusammen,

seit ein paar Tagen habe ich immer mal wieder Timing Probleme:

11/12/20 08:24:25.090 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/12/20 10:03:07.443 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/13/20 00:00:53.795 Info: Backing up database…
11/13/20 11:52:44.645 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/13/20 13:43:28.048 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/13/20 16:49:49.235 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/13/20 22:17:38.936 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/13/20 23:12:00.382 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/14/20 00:00:53.754 Info: Backing up database…
11/14/20 15:35:19.499 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/15/20 00:01:53.749 Info: Backing up database…
11/15/20 13:03:21.984 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/15/20 13:27:53.823 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/15/20 14:40:28.093 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/16/20 00:01:53.746 Info: Backing up database…
11/16/20 10:31:46.954 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/16/20 11:02:09.064 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/17/20 00:00:53.759 Info: Backing up database…
11/17/20 14:43:33.923 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?

Aktuell funktioniert eigentlich alles, nur es macht mir etwas Sorgen, warum auf einmal dieser Fehler auftritt ohne dass ich an der Konfiguration oder dem Standort des Pi etwas geändert hätte.

Aufgefallen ist es mir, weil ich in jetzt häufiger in die Logs geschaut habe, nachdem Ende letzter Woche auf einmal ein Thermostat komplett durch den Wind war und nur noch zwischen Auto, Manuell und Boost hin- und her gewechselt ist - ggf. ist das aber auch eine andere Baustelle gewesen und es hatte sich was in Openhab verklemmt - ich habe den Pi einmal neu gestartet und dann war wieder alles gut.

pmayer · November 17, 2020, 3:50pm

Wie ist denn die Systemauslastung zur Zeit wo der Fehler auftaucht? Was ist es für ein Pi? 1/2/3/4?
Welches CC1101 Modul setzt du ein?

rolandw · November 17, 2020, 3:55pm

Zum Zeitpunkt als der Fehler auftrat habe ich leider keine Info über die Systemauslastung, aktuell sieht man eigentlich nur homegear und den java Prozess von openhab wenn man ‘top’ aufruft.

Es ist ein Pi3 und das Modul ist das aus deinem Shop, welches du mit freundlicherweise anfangs zum Test überlassen hattest.

pmayer · November 17, 2020, 3:56pm

Ach, danke - das hatte ich nicht mehr auf dem Schirm, sorry.

Hmm, die Kiste langweilt sich.
Vielleicht hat @sathya ne Idee…

rolandw · November 18, 2020, 8:14am

Heute morgen standen auch wieder zwei Thermostate auf ‘Auto’, obwohl ich alle auf ‘Manuell’ betreibe und auch keine Befehle oder Regeln habe, die sie auf einen anderen Modus stellen. Seltsamerweise hatte ich in der 2-wöchigen-Testphase keinerlei solche Probleme und seitdem hat sich an Hardware und Homegear nichts geändert, ich habe lediglich minimale Veränderungen in den Regeln von Openhab zur zeitlichen Steuerung der Temperatur vorgenommen, aber die funktionieren soweit und können aus meiner Sicht ja auch nicht zu so seltsamen Phänomenen führen, die nur manchmal auftreten - das wirkt ja fast so, als wenn die Thermostate teilweise falsche Signale bekommen würden … Es waren übrigens diesmal andere Thermostate als der, der letzte Woche wild zwischen Auto - Boost und Manuell wechselte, scheint als auch nicht daran zu liegen, dass ein einzelner Thermostat Probleme macht.

rolandw · November 19, 2020, 7:43pm

Ich habe nochmal etwas weiter analysiert:

Heute ist das Problem um 14:40 wieder aufgetreten laut homegear.err und ich habe nun mal in homegear.log geschaut, was denn so um diese Zeit los war:

11/19/20 14:40:09.122 Module HomeMatic BidCoS: Info: 11/19/20 14:40:09.121 Packet received (CC1101_WLKN, RSSI: -67 dBm): 0C82A64153CC9EFD137C8169C8
11/19/20 14:40:09.124 Module HomeMatic BidCoS: Info: LOWBAT on channel 1 of HomeMatic BidCoS peer 12 with serial number NEQ1680010 was set to 0x01.
11/19/20 14:40:09.125 Module HomeMatic BidCoS: Info: STATE on channel 1 of HomeMatic BidCoS peer 12 with serial number NEQ1680010 was set to 0xC8.
11/19/20 14:40:09.221 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Info: Sending (CC1101_WLKN): 0A828002FD137C53CC9E00
11/19/20 14:40:09.320 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Info: Sending (CC1101_WLKN): 0BA5A001FD137C53CC9E0103 Planned sending time: 11/19/20 14:40:09.319
11/19/20 14:40:09.323 RPC Server (Port 2001): Info: Client number 172552 is calling RPC method: setValue (2) Parameters:
11/19/20 14:40:09.699 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Info: Sending (CC1101_WLKN): 0CB8B011FD137C2E6D27860409
11/19/20 14:40:09.714 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Warning: Timing problem. Sending took more than 100ms. Do you have enough system resources?
11/19/20 14:40:09.715 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Info: Sending (CC1101_WLKN): 0BA5A001FD137C53CC9E0103 Planned sending time: 11/19/20 14:40:09.519
11/19/20 14:40:09.733 Module HomeMatic BidCoS: TI CC110X “CC1101_WLKN”: Info: Sending (CC1101_WLKN): 0BA5A001FD137C53CC9E0103 Planned sending time: 11/19/20 14:40:09.719
11/19/20 14:40:09.847 Module HomeMatic BidCoS: Info: 11/19/20 14:40:09.846 Packet received (CC1101_WLKN, RSSI: -60 dBm): 0FB880022E6D27FD137C010409203340
11/19/20 14:40:09.847 Module HomeMatic BidCoS: Info: Queue 537 is empty and there are no pending queues.
11/19/20 14:40:09.848 Module HomeMatic BidCoS: Info: BOOST_STATE on channel 4 of HomeMatic BidCoS peer 11 with serial number LEQ0860444 was set to 0x00.
11/19/20 14:40:09.848 Module HomeMatic BidCoS: Info: CONTROL_MODE on channel 4 of HomeMatic BidCoS peer 11 with serial number LEQ0860444 was set to 0x01.
11/19/20 14:40:09.849 Module HomeMatic BidCoS: Info: FAULT_REPORTING on channel 4 of HomeMatic BidCoS peer 11 with serial number LEQ0860444 was set to 0x00.
11/19/20 14:40:09.849 Module HomeMatic BidCoS: Info: PARTY_START_TIME on channel 4 of HomeMatic BidCoS peer 11 with serial number LEQ0860444 was set to 0x00.
11/19/20 14:40:09.849 Module HomeMatic BidCoS: Info: SET_TEMPERATURE on channel 4 of HomeMatic BidCoS peer 11 with serial number LEQ0860444 was set to 0x09.

Zur Aufklärung hier noch die Übersicht, wer sich hinter den Peers 11 und 12 verbirgt:

11 │ Bathroom │ 2E6D27 │ LEQ0860444 │ 0095 │ HM-CC-RT-DN │ *1.3 │ No │ No │ No
12 │ Bathroom Window Sensor │ 53CC9E │ NEQ1680010 │ 00B1 │ HM-Sec-SC-2 │ 2.4 │ No │ No │ Yes

Man sieht (leider etwas schlecht formattiert), dass die Batterie des Fensterkontakts zur Neige geht. Die beiden sind nicht direkt miteinander gekoppelt, sondern ich setze die Temperatur über eine Regel in Openhab runter wenn das Fenster offen ist, also keine direkte Kopplung über Kanäle.
Der Fehler tritt ja erst auf, wenn die Regel die Temperatur an den Thermostat senden will, der hat aber ja offenbar keine Probleme mit der Batterie …
So ganz kann ich mir nicht erklären was da los ist, hat sonst ggf. jemand eine Idee, was die Ursache sein könnte für das Timing Problem?

rolandw · November 19, 2020, 8:09pm

Noch ein Nachtrag:

Öffnen und Schließen des Fenster eben hat beim ersten Mal ausgereicht um den Fehler zu provozieren, zwei weitere Versuche ein paar Minuten später hingegen führten nicht zu weiteren Fehlermeldungen im Log.

Update: Batterien im Fensterkontakt sind erneuert, ich bin gespannt …

rolandw · November 20, 2020, 9:39am

Heute morgen steht wieder ein Thermostat auf “Auto”, der Status hat sich um 05:35 geändert laut log, da war hier noch keiner wach. Kann ich irgendwie raus finden, bspw. anhand der ClientID, ob das vom Thermostat ausging und er das an Homegear gemeldet hat oder ob Homegear der Initiator war? Im Log sieht es nämlich für mich gleich aus, ob ich softwareseitig schalte oder den Knopf am Thermostat nutze, daher weiß ich gerade nicht, was nun Ursache und was Wirkung ist.

11/20/20 05:35:05.431 Module HomeMatic BidCoS: Info: 11/20/20 05:35:05.430 Packet received (CC1101_WLKN, RSSI: -80 dBm): 8AA286102E9CA20000000A249910002B5E5DDF2E6C1E2588A54E8504D5987EEA34741B882ABA29071DFD45CD5F5E3AB320533883D385E62C79AC6D2F94DA08FC527A86102E9CA20000000A249910002B5E5DDF2E6C1E2588A54E8504D5987EEA34741B882ABA29071DFD45CD5F5E3AB320533883D385E62C79AC6D2F94DA08FC24527A86102E9CA20000A4
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: ACTUAL_TEMPERATURE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x0099.
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: BATTERY_STATE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x10.
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: BOOST_STATE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x2B.
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: CONTROL_MODE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x00.
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: FAULT_REPORTING on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x00.
11/20/20 05:35:05.433 Module HomeMatic BidCoS: Info: PARTY_START_DAY on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x1E.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_START_MONTH on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x01.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_START_TIME on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x2B.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_START_YEAR on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x5D.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_STOP_DAY on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x0E.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_STOP_MONTH on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x0E.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_STOP_TIME on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x1F.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_STOP_YEAR on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x6C.
11/20/20 05:35:05.434 Module HomeMatic BidCoS: Info: PARTY_TEMPERATURE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x25.
11/20/20 05:35:05.435 Module HomeMatic BidCoS: Info: SET_TEMPERATURE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x09.
11/20/20 05:35:05.435 Module HomeMatic BidCoS: Info: VALVE_STATE on channel 4 of HomeMatic BidCoS peer 7 with serial number LEQ0859266 was set to 0x00.
11/20/20 05:35:05.582 RPC Server (Port 2001): Info: Client number 187347 is calling RPC method: setValue (2) Parameters:
(String) LEQ0859266:4
(String) AUTO_MODE
(Boolean) 1

pmayer · November 20, 2020, 9:50am

Ich find das super, dass du das so raus suchst. Aber ich glaube da kann maximal @sathya was zu sagen… oder @Sim hast du ne Idee?

Sim · November 24, 2020, 2:20pm

Nee, da fällt mir auch nichts dazu ein. Das ist jetzt auch kein Fehler, wo ich sagen würde: mach mal das aktuelle nightly drauf. In homegear/node-blue hast du dann vermutlich gar keine Logik erstellt?

rolandw · November 24, 2020, 2:40pm

Nein, ich habe mal beruflich mit Node-Red gearbeitet, aber irgendwie ist die Flow-basierte Entwicklung nicht so meins, ich mag Source Code lieber, daher gefiel mir das mit den Regeln in OpenHab besser.

Das Timing Problem ist allerdings seit dem Wechsel der schwachen Batterie am Fensterkontakt am 19.11.2020 bisher nicht wieder aufgetreten. Da es sonst eigentlich täglich mindestens einmal im Error-Log stand, scheint das aus meiner Sicht so wie es bisher aussieht die Ursache gewesen zu sein.

Ist nur noch unklar, warum der Thermostat in der Küche nun schon zwei mal von “Geisterhand” auf AUTO gewechselt ist, da habe ich noch keine Erklärung für bzw. Ursache gefunden. Hast du da ggf. einen Tipp, wie ich raus finden kann, ob das vom Thermostat oder vom Pi ausging, Stichwort: Client-ID, kann man das daran irgendwie erkennen?

sathya · December 30, 2020, 12:37pm

Hallo @rolandw,

falls das Problem doch wieder auftritt, hättest du einen etwas längeren Logabschnitt? Was in dem Log auffällt ist, dass das Gerät 53CC9E (der Fensterkontakt im Bad) offenbar noch nicht vollständig angelernt ist (0BA5A001FD137C53CC9E0103 ist ein Konfigurationspaket zum Abrufen der verknüpften Geräte). Lerne dieses Gerät entweder noch einmal neu ein oder mache ein queues clear im CLI. Letzteres sollte bei einem Fensterkontakt kein Problem sein.

Viele Grüße

Sathya

rolandw · December 30, 2020, 6:04pm

Hallo @sathya,

was noch besteht, ist das Problem, dass manchmal einige Thermostate wie von Geisterhand auf “Auto” umspringen, obwohl sie eigentlich auf “Manuell” stehen - hilft dir dafür ein längeres Log? Wenn ja, soll ich das irgendwie vorfiltern oder einfach alles rein pasten?
Zum Fensterkontakt noch eine Info: der ist nicht direkt mit dem Thermostat gekoppelt, sondern schaltet nur über eine Regel in OpenHab, erklärt das, weshalb er für dich nicht richtig angelernt wirkt oder soll ich trotzdem einmal die Queue löschen?

Gruß Roland

rolandw · January 4, 2021, 3:59pm

@sathya, @pmayer, @Sim
Moin zusammen,

ggf. liegt das Problem der sich von “Geisterhand” auf “Auto” umstellenden Thermostate an der Firmware 1.3 - im Changelog zu 1.4 findet sich zwar nichts dazu, weshalb ich bisher kein Update durchgeführt hatte, aber ich habe in einem anderen Forum einen Beitrag gefunden, in dem der Hersteller das Problem bestätigt (bei 1.3) und mit der nächsten Firmware (also aus damaliger Sicht 1.4) Abhilfe verspricht:
https://homematic-forum.de/forum/viewtopic.php?f=34&t=16762&start=50
Ich habe nun einmal zunächst nur einen der betroffenen Thermostate auf 1.4 aktualisiert und werde mal weiter beobachten, ob es da einen Zusammenhang gibt - ich halte euch auf dem Laufenden …

sathya · January 22, 2021, 5:42pm

Hallo @rolandw,

was noch besteht, ist das Problem, dass manchmal einige Thermostate wie von Geisterhand auf “Auto” umspringen, obwohl sie eigentlich auf “Manuell” stehen - hilft dir dafür ein längeres Log?

Ja, da hilft das Log - schön wäre dazu natürlich die Info, zu welchem Zeitpunkt im Log das Umsprichen auf Auto in etwa erfolgt ist. Aber auch ohne diese Info hilft das Log - unter der Voraussetzung, dass es den Fehlerzeitpunkt enthält.

Vielleicht hat aber ja das Update bereits geholfen.

Zum Fensterkontakt noch eine Info: der ist nicht direkt mit dem Thermostat gekoppelt, sondern schaltet nur über eine Regel in OpenHab, erklärt das, weshalb er für dich nicht richtig angelernt wirkt oder soll ich trotzdem einmal die Queue löschen?

Nein, das erklärt das nicht. Ich würde das Gerät einmal neu anlernen.

Viele Grüße

Sathya