Ankündigung

**pfischi** · 04.12.2018, 19:39

Ich schau’s mir an. Am besten bis zum Fix das Plugin abschalten. Danke für den Hinweis und das unfreiwillige debuggen

**pfischi** · 04.12.2018, 22:16

Also ich habe das nochmal überprüft,

die Anzahl der Threads ist normal. An jedem Speaker muss man sich mit mehreren Events registrieren, um alle Daten zu erhalten. Ich zähle pro Speaker 10 Threads bei mir. Ist also normal. Solange die Anzahl der Threads nicht ansteigt, ist alles ok. Ich konnte bei mir nichts festellen, habe es aber im Dauertest und ein Auge drauf.

Gruss,

Stefan

**Msinn** · 04.12.2018, 22:43

pfischi Kannst Du die Threads sinnvoll benennen? Dann kann man sie in der Auflistung im Backend zum Plugin zuordnen und muss nicht im Ausschlußverfahren herausfinden wo sie herkommen.

**pfischi** · 04.12.2018, 22:48

Zitat von Msinn Beitrag anzeigen

pfischi Kannst Du die Threads sinnvoll benennen? Dann kann man sie in der Auflistung im Backend zum Plugin zuordnen und muss nicht im Ausschlußverfahren herausfinden wo sie herkommen.

Ja, soweit dies unter meiner Kontrolle ist. Manches kommt direkt aus dem SoCo-Framework (Teil des Plugins). Ich mache morgen mal was fertig und stelle es zur weiteren Fehleranalyse bereit.
Gleichzeit habe ich die letzte Stunde einen Stresstest bei mir gemacht: alle 10 Sekunden werden die Registrierungen der Speaker erneuert, was normalerweise aller 120 Sekunden passiert. Die Anzahl der Threads bleibt gleich.

Gruss,

Stefan

**pfischi** · 05.12.2018, 17:29

Im Sonos-Thread diskutieren wir auch gerade über das Sonos-Plugin. Eventuell hat sich da bei mir ein Memory-Leak eingeschlichen. Ich kann mir vorstellen, dass das hier auch ein Problem darstellt.

Gruss,

Stefan

**android** · 07.12.2018, 08:22

Das Sonos-Plugin erzeugt zwar viele Threads, aber der Absturz wird bei mir durch das sml-Plugin verursacht.

**bmx** · 07.12.2018, 11:59

Woraus schließt Du, das das SML Plugin für den Absturz verantwortlich ist?

**android** · 07.12.2018, 12:02

Ohne sml-Plugin läuft mein System Wochen ohne Absturz, mit nur ca. zwei Tage.

Die Anzahl der Threads scheint vor dem Absturz auch nicht anzusteigen.

Der Systemload ging auf 112%.

**smai** · 07.12.2018, 12:58

Zitat von android Beitrag anzeigen

Der Systemload ging auf 112%.

Wie misst du diesen?

Ich bin kein Linux-Experte, aber ps -T -p <pid> oder top -H -p <pid> soll gemäss meinen Recherchen einzelne Threads auflisten. Vielleicht siehst du so, welcher Thread schuld ist.

**android** · 07.12.2018, 13:00

Habe das nachträglich über das smarthomeNG Systemitem "systemload" gesehen...

Werde das mal probieren. Aber muss erstmal ein Testsystem zum Nachstellen aufsetzen, will nicht immer mein produktivsystem lahm legen

**smai** · 07.12.2018, 13:14

Wenn SHNG selbst hängt, würde ich auf dessen Werte nicht mehr vertrauen, speziell nicht auf die in der Datenbank gespeicherten. Es ist ja fraglich, wann die DB zuletzt beschrieben werden konnte.

Wenn ich den SHNG Code sowie die Python Doku richtig verstehe, ist das auch nicht ein Prozentwert (etwa der Prozessorlast) sondern die Anzahl Prozesse in der Run Queue.

**android** · 07.12.2018, 14:45

Habe das mal so intepretiert. Der Wert ist ja eine Dezimalzahl die bei mir normalerweise bis zu 0.3-0.4 geht und in dem Fall 1.12 war. Der Zeitpunkt passte zumindest zu dem Zeitpunkt, wo zuletzt noch items u.Ä. aktualisiert wurden.

**smai** · 07.12.2018, 15:02

Zitat von android Beitrag anzeigen

Der Zeitpunkt passte zumindest zu dem Zeitpunkt, wo zuletzt noch items u.Ä. aktualisiert wurden.

Genau das hatte ich befürchtet - das ist ja eigentlich zu früh. Zumal es auch noch ein Durchschnitt der vorangehenden 15 Minuten ist.
Interessanter wäre ja der Zustand zum Zeitpunkt des Hängens bzw. eigentlich sogar danach.

Wie viele Cores hat denn dein NUC? Der Wert der Run Queue ist nämlich im Verhältnis zu den Anzahl Cores zu setzen.
Also bei einem Core wäre 1.12 tatsächlich eine Überlastung (und damit quasi 112% Load), bei zwei Cores wären es aber nur 56%.

**android** · 10.12.2018, 21:02

Hab 4 cores. Hab momentan leider keine Zeit, nochmals Tests mit sml Plugin zu machen. Hoffe komme da nach Weihnachten mal zu.

**jzehnter** · 23.04.2019, 19:56

Hi,

ich klinke mich mal hier ein, da ich vermutlich ein identisches oder selbes Problem hab.

Ich konnte es aber bereits auf das SML-Plugin eingrenzen.
Umgebung:

VMware auf HP MicroServer G1610T Gen8
VM mit Debian 9.8 (frisch aufgesetzt vor 2 Wochen)
2 CPU´s, 3 GB RAM (1 GB SWAP) , 50GB HDD
SmartHomeNG
- Version: 1.5.1 - 1.5.1.master (d2a248c0)
- Plugin: 1.5.1.master (248c6068)
  - backend (aktiv)
  - cli (aktiv, nur für Debugging)
  - influxdata (aktiv zum Export)
  - knx (aktiv für Bus-Zugriff)
  - mail (aktiv)
  - network (aktiv, aber nicht in Nutzung
  - onewire (aktiv für Temperatur auf KNX-Bus)
  - SML (aktiv mit lokalen USB-Lesekopf für EHM eHZ-ED300L)
  - sqlite_visu2_8 (aktiv, aber derzeit nur loggen ohne weitere Auswertung)
  - visu_smartvisu (aktiv, ohne Nutzung)
  - visu_websocket (aktiv, ohne Nutzung)
  - webservices (aktiv, in Nutzung für Pushen der Füllstandsüberwachung per Arduino)
- Python: 3.5.3 final
  - pyserial: 3.4

plugins.yml:

Code:

sml: class_name: Sml class_path: plugins.sml serialport: /dev/ttyUSB0 cycle: 120 # host = 192.168.2.1 # port = 1234 # device = raw | hex | <known-device>

Code:

Items mit SML:

Code:

Energie:

    Strom:

        Zaehler:
            name: Zaehler
            remark: Informationen zum Stromzaehler selbst

            Hersteller:
                name: Hersteller des Zaehler
                remark: Herstellername des Stromzählers
                # SML
                sml_obis: 129-129:199.130.3*255

            Seriennummer:
                name: Seriennummer des Zaehler
                remark: Seriennummer/Server-ID des Stromzählers
                # SML
                sml_obis: 1-0:0.0.9*255

        Bezug:

            Live:
                name: Aktueller Bezug in Watt-Stunden
                type: num
                sqlite: 'true'
                # SML
                sml_obis: 1-0:15.7.0*255

                Einheit:
                    name: Einheit des Strombezugs
                    type: num
                    sqlite: 'true'
                    # SML
                    sml_obis: 1-0:15.7.0*255
                    sml_prop: unitName

            Total:
                name: Gesamter Bezug in kWh
                type: num
                sqlite: 'true'
                # SML
                sml_obis: 1-0:1.8.0*255

        Einspeisung:
            name: Item-Gruppe zur Strom-Einspeisung

            Live:
                name: Aktueller Einspeisung in Watt-Stunden
                type: num
                sqlite: 'true'
                # SML
                sml_obis: 1-0:16.7.0*255

                Einheit:
                    name: Einheit der Stromlieferung
                    type: num
                    sqlite: 'true'
                    # SML
                    sml_obis: 1-0:16.7.0*255
                    sml_prop: unitName

            Total:
                name: Gesamte Einspeisung in kWh
                type: num
                sqlite: 'true'
                # SML
                sml_obis: 1-0:2.8.0*255

Verhalten:

Mit zunehmender Betriebsdauer steigt zunächst die Load an und bleibt dann dauerhaft auf über 10-25.
Die Load steigt in der Regel bereits nach ca. 2 Stunden an.
Das Backend wird mit der Zeit (5-24h) deutlich langsamer. Alles weitere funktioniert aber noch ohne Probleme.

Parallel lässt sich beobachten, dass der SmartHomeNG-Prozess zunehmend RAM maußert.
Zu Beginn des Dienststart sind es ca. 50-150 MB. Nach 3 Tagen waren es nun 1,5 GB RAM.
Parallel verursacht der Prozess über 100%-CPU-Last (top/glances).

Nach 24h melden dann jegliche Plugins bei deren Aktionen im Log "Zu viele offene Dateien" und dies ist dann auch deutlich an der Bedienbarkeit und an den geloggten Werten in z. B. der Influx-DB zu spüren. Das ist meiner Meinung nach eine Folge der starken Auslastung.

Analysen:

Das ganze hatte ich schon auf meiner vorherigen SmartHomeNG-Installation (Version 1.4.2), nachdem ich das SML-Plugin aktiviert hatte und meinen Stromzähler EHM eHZ-ED300L mit meinem EM-Log IR-Lesekopf hatte. Damals hatte ich es aber auf ein möglicherweise defekten Dateisystem in der VM aufgrund eines Hardware-Ausfalls geschoben.
Das kann ich aber der neuen VM allerdings ausschließen.

Wenn das SML-Plugin nicht aktiv ist, steigt die Last nicht an.
Auch wenn die Berechtigungen auf /dev/ttyUSB0 nicht stimmen und somit keinerlei SML-Abfragen stattfinden, gibt es keine Probleme.
Ich lasse das Plugin nun aber nochmals zum Reproduzieren ab heute deaktiviert.

Im Log sind zum SML-Plugin pro cycle folgende Outputs zu finden:

Code:

2019-04-19  23:54:12 WARNING  Sml          Skipping unkown field 0x1e
2019-04-19  23:54:12 WARNING  Sml          Can not parse entity at position 126, byte 11: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 05 ff 01 72 62 00 01 65 06 91 b4 b5 01 01 83 02 66 3a 50 f2 91 aa 2c f3 28 08 ef ee 14 71 b9 f0 ef 65 5c 8b fb c8 ca 04 fd c2 8e 2b 87 82 3a 29 29 4d dd d7 3f b3 e1 5d e9 f5...
2019-04-19  23:54:12 WARNING  Sml          Item Energie.Strom.Einspeisung.Live.Einheit: value W does not match type num. Via Sml None
2019-04-19  23:54:12 DEBUG    Sml          Item Energie.Strom.Einspeisung.Live = 259.7 via Sml None None
2019-04-19  23:54:12 DEBUG    Sml          Item Energie.Strom.Bezug.Total = 18145150.6 via Sml None None
2019-04-19  23:54:12 DEBUG    Scheduler    Sml next time: 2019-04-19 23:56:12+02:00

Die Warnung bezüglich des falschen Types habe ich zwischenzeitlich behoben.
Mit der 1. und 2. Warning kann ich allerdings grad nichts anfangen.

Ich habe nun nochmal einen Start mit DEBUG-Level vom SML-Plugin gemacht:

Code:

2019-04-23  20:50:03 DEBUG    Sml          Data: [TRUNCATED]
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x02\x08\x01\xff', 'unitName': 'Wh', 'signature': None, 'value': 230879951, 'valTime': None, 'valueReal': 23087995.1, 'status': None, 'unit': 30, 'obis': '1-0:2.8.1*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x02\x08\x00\xff', 'unitName': 'Wh', 'signature': None, 'value': 230879951, 'valTime': None, 'valueReal': 23087995.1, 'status': 65922, 'unit': 30, 'obis': '1-0:2.8.0*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x01\x08\x02\xff', 'unitName': 'Wh', 'signature': None, 'value': 0, 'valTime': None, 'valueReal': 0.0, 'status': None, 'unit': 30, 'obis': '1-0:1.8.2*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x01\x08\x01\xff', 'unitName': 'Wh', 'signature': None, 'value': 181556339, 'valTime': None, 'valueReal': 18155633.900000002, 'status': None, 'unit': 30, 'obis': '1-0:1.8.1*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x01\x08\x00\xff', 'unitName': 'Wh', 'signature': None, 'value': 181556341, 'valTime': None, 'valueReal': 18155634.1, 'status': 65922, 'unit': 30, 'obis': '1-0:1.8.0*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Item Energie.Strom.Bezug.Total = 18155634.1 via Sml None None
2019-04-23  20:50:03 DEBUG    Scheduler    Sml next time: 2019-04-23 20:52:03+02:00
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x81\x81\xc7\x82\x05\xff', 'unitName': None, 'signature': None, 'value': b'f:P\xf2\x91\xaa,\xf3(\x08\xef\xee\x14q\xb9\xf0\xefe\\\x8b\xfb\xc8\xca\x04\xfd\xc2\x8e+\x87\x82:))M\xdd\xd7?\xb3\xe1]\xe9\xf5\x89wKS\xda4\x01', 'valTime': [None, 110546951], 'valueReal': b'f:P\xf2\x91\xaa,\xf3(\x08\xef\xee\x14q\xb9\xf0\xefe\\\x8b\xfb\xc8\xca\x04\xfd\xc2\x8e+\x87\x82:))M\xdd\xd7?\xb3\xe1]\xe9\xf5\x89wKS\xda4\x01', 'status': None, 'unit': None, 'obis': '129-129:199.130.5*255', 'scaler': None}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x81\x81\xc7\x82\x03\xff', 'unitName': None, 'signature': None, 'value': b'EMH', 'valTime': None, 'valueReal': b'EMH', 'status': None, 'unit': None, 'obis': '129-129:199.130.3*255', 'scaler': None}
2019-04-23  20:50:03 DEBUG    Sml          Entry {'objName': b'\x01\x00\x10\x07\x00\xff', 'unitName': 'W', 'signature': None, 'value': 3693, 'valTime': None, 'valueReal': 369.3, 'status': None, 'unit': 27, 'obis': '1-0:16.7.0*255', 'scaler': -1}
2019-04-23  20:50:03 DEBUG    Sml          Item Energie.Strom.Einspeisung.Live = 369.3 via Sml None None
2019-04-23  20:50:04 WARNING  Sml          Item Energie.Strom.Einspeisung.Live.Einheit: value W does not match type num. Via Sml None
2019-04-23  20:50:04 DEBUG    Sml          Entry {'objName': b'\x01\x00\x00\x00\t\xff', 'unitName': None, 'signature': None, 'value': b'\t\x01EMH\x00\x00R\xff&', 'valTime': None, 'valueReal': b'\t\x01EMH\x00\x00R\xff&', 'status': None, 'unit': None, 'obis': '1-0:0.0.9*255', 'scaler': None}
2019-04-23  20:50:04 DEBUG    Sml          Entry {'objName': b'\x01\x00\x02\x08\x02\xff', 'unitName': 'Wh', 'signature': None, 'value': 0, 'valTime': None, 'valueReal': 0.0, 'status': None, 'unit': 30, 'obis': '1-0:2.8.2*255', 'scaler': -1}
2019-04-23  20:50:04 DEBUG    Sml          cycle takes 0.8754785060882568 seconds

Hier ist der Fehler "Can not parse ..." nicht aufgetreten.
Ein Grep über das aktuelle Log zeigt, aber dass dieser Fehler regelmäßig kommt:

Code:

2019-04-23  19:47:59 WARNING  Sml          Can not parse entity at position 63, byte 14: can't multiply sequence by non-int of type 'float': 77 07 01 00 01 08 02 ff 01 01 62 1e 52 ff 00 56 00 00 00 00 00 01 77 07 01 00 02 08 02 ff 01 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 10 07 00 ff 01 01 62 1b 52 ff 55 00 00 05 ba 01 77...
2019-04-23  20:06:24 WARNING  Sml          Can not parse entity at position 126, byte 11: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 05 ff 01 72 62 00 01 65 06 96 c3 03 01 01 83 02 66 3a 50 f2 91 aa 2c f3 28 08 ef ee 14 71 b9 f0 ef 65 5c 8b fb c8 ca 04 fd c2 8e 2b 87 82 3a 29 29 4d dd d7 3f b3 e1 5d e9 f5...
2019-04-23  20:09:30 WARNING  Sml          Can not parse entity at position 126, byte 11: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 00 00 09 ff 01 01 01 00 01 0b 09 01 45 4d 48 00 00 52 ff 26 01 77 07 01 00 01 08 00 ff 64 01 01 82 01 62 1e 52 ff 56 00 0a d2 49 8b 01 77 07 01 00 02 08 00 ff 64 01 01 82 01 62 1e...
2019-04-23  20:18:03 WARNING  Sml          Can not parse entity at position 63, byte 9: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 03 ff 01 00 01 01 01 04 45 4d 48 01 77 07 01 00 00 00 09 ff 01 01 01 01 0b 09 01 45 4d 48 00 00 52 ff 26 01 77 07 01 00 01 08 00 ff 64 01 01 82 01 62 1e 52 ff 56 00 0a d2 4c...
2019-04-23  20:22:03 WARNING  Sml          Can not parse entity at position 126, byte 17: can't multiply sequence by non-int of type 'float': 77 07 01 00 02 08 00 ff 64 01 01 82 01 62 1e 52 ff 00 56 00 0d c2 f2 cf 01 77 07 01 00 01 08 01 ff 01 01 62 1e 52 ff 56 00 0a d2 4d 7d 01 77 07 01 00 02 08 01 ff 01 01 62 1e 52 ff 56 00 0d c2...
2019-04-23  20:24:03 WARNING  Sml          Can not parse entity at position 166, byte 49: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 02 08 00 ff 64 00 01 01 82 01 62 1e 52 ff 56 00 0d c2 f2 cf 01 77 07 01 00 01 08 01 ff 01 01 62 1e 52 ff 56 00 0a d2 4e 07 01 77 07 01 00 02 08 01 ff 01 01 62 1e 52 ff 56 00 0d c2...
2019-04-23  20:28:03 WARNING  Sml          Can not parse entity at position 63, byte 10: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 01 08 02 ff 01 01 00 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 02 08 02 ff 01 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 10 07 00 ff 01 01 62 1b 52 ff 55 00 00 0f 3c 01 77...
2019-04-23  20:30:03 WARNING  Sml          Can not parse entity at position 63, byte 10: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 01 08 02 ff 01 01 00 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 02 08 02 ff 01 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 10 07 00 ff 01 01 62 1b 52 ff 55 00 00 0f 6e 01 77...
2019-04-23  20:32:03 WARNING  Sml          Can not parse entity at position 63, byte 12: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 01 08 02 ff 01 01 62 1e 00 52 ff 56 00 00 00 00 00 01 77 07 01 00 02 08 02 ff 01 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 10 07 00 ff 01 01 62 1b 52 ff 55 00 00 0f 64 01 77...
2019-04-23  20:32:03 WARNING  Sml          Can not parse entity at position 126, byte 12: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 05 ff 01 72 62 01 00 65 06 96 cb 58 01 01 83 02 66 3a 50 f2 91 aa 2c f3 28 08 ef ee 14 71 b9 f0 ef 65 5c 8b fb c8 ca 04 fd c2 8e 2b 87 82 3a 29 29 4d dd d7 3f b3 e1 5d e9 f5...
2019-04-23  20:40:03 WARNING  Sml          Can not parse entity at position 63, byte 9: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 01 08 02 ff 01 00 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 02 08 02 ff 01 01 62 1e 52 ff 56 00 00 00 00 00 01 77 07 01 00 10 07 00 ff 01 01 62 1b 52 ff 55 00 00 0b 74 01 77...
2019-04-23  20:40:03 WARNING  Sml          Can not parse entity at position 126, byte 9: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 05 ff 01 00 72 62 01 65 06 96 cd 3f 01 01 83 02 66 3a 50 f2 91 aa 2c f3 28 08 ef ee 14 71 b9 f0 ef 65 5c 8b fb c8 ca 04 fd c2 8e 2b 87 82 3a 29 29 4d dd d7 3f b3 e1 5d e9 f5...
2019-04-23  20:42:03 WARNING  Sml          Can not parse entity at position 4005, byte 18: Try to read 5 bytes, but only have 2: 77 07 01 00 02 08 00 ff 64 01 01 82 01 62 1e 52 ff 56 00 0d...
2019-04-23  20:48:03 WARNING  Sml          Can not parse entity at position 4047, byte 15: Try to read 5 bytes, but only have 5: 77 07 01 00 02 08 01 ff 01 01 62 1e 52 ff 56 00 0d c2 f2 cf...
2019-04-23  20:52:03 WARNING  Sml          Can not parse entity at position 126, byte 11: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 81 81 c7 82 05 ff 01 72 62 00 01 65 06 96 d0 09 01 01 83 02 66 3a 50 f2 91 aa 2c f3 28 08 ef ee 14 71 b9 f0 ef 65 5c 8b fb c8 ca 04 fd c2 8e 2b 87 82 3a 29 29 4d dd d7 3f b3 e1 5d e9 f5...
2019-04-23  20:54:03 WARNING  Sml          Can not parse entity at position 252, byte 12: unsupported operand type(s) for ** or pow(): 'int' and 'bytes': 77 07 01 00 02 08 01 ff 01 01 62 1e 00 52 ff 56 00 0d c2 f2 cf 96 1b 1b 1b 1b 01 01 01 01 76 07 00 08 02 2a 30 19 62 00 62 00 72 63 01 01 76 01 01 07 00 08 06 96 ba b3 0b 09 01 45 4d 48 00 00...

Hat jemand von euch eine Idee woran das liegen könnte?
Falls weitere Infos benötigt werden, gerne Bescheid geben.

Ankündigung

Absturzuntersuchung

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar