Seite lädt nicht mehr und "modules.websocket.sv Exception"

[ooUrmeloo]

Hallo zusammen,

ich habe seit einiger Zeit folgendes Problem.
Wenn ich eine SmartVisu Seite öffne, dauert es tlw. ewig, bis die Seite lädt - vor allem Plots brauchen tlw. 20-30 sec oder laden gar nicht.
Im log file sehe ich dann auch dutzende Einträge in extrem kurzen Zeitabständen:

2024-01-16  21:54:29 WARNING  modules.websocket.sv Exception in 'await websocket.send(reply)': received 1001 (going away); then sent 1001 (going away) - reply = {"cmd": "series", "series": ....

Zusätzlich finden sich immer wieder viele Einträge bzgl. database:

2024-01-16  10:02:48 NOTICE   plugins.database    Skipping dump, since an other database operation running! Data is buffered and dumped later.

Ich habe vor 2-3 Wochen auf SHNG 1.9.5 (von 1.9.4) und SmartVisu 3.4 (von 3.3.1) aktualisiert, weiß aber nicht sicher, ob es damit zusammen hängt.
Das Verhalten oben beobachte ich allerdings auch erst seit kurzem. Oben genannte Fehlermeldungen hatte ich bisher nie. Das ganze tritt aber auch nicht immer auf. Oft laden die Seiten auch problemlos.
Ich wüsste nicht, was ich sonst geändert hätte, was dieses Verhalten erklären könnte. Ich habe nur einige Zigbee Geräte hinzugefügt und 1-2 neue Plots erstellt.

Hat jemand einen Rat für mich??
Cache habe ich schon mehrfach geleert und auch schon Dienst bzw. den Raspi neu gestartet. Hat immer nur kurz geholfen.
Und hier im Forum habe ich auch nicht direkt was gefunden.

[wvhn]

Es gibt diese Meldungen sehr vereinzelt im Zusammenhang mit großen Datenmengen. Kann es sein, dass Deine Plots ein sich schnell veränderndes item im raw-Modus abbilden? Da sollte es helfen, die Anzahl der Punkte zu beschränken und eine Aggregation (avg, min, max …) zu verwenden.

Gruß
Wolfram

[ooUrmeloo]

Danke für den Hinweis!
Ich bin mal alle Plots durchgegangen und habe bei einigen die Datenpunkte reduziert. 'avg' benutze ich eigentlich schon fast überall.
Ich hatte aber mal die Option "{ rangeSelector: {selected: 'x'}}" bei dem advanced Zoom ausprobiert. Das sollte m.E. ja aber nur die ausgwählte Ansicht beeinflussen, oder?
Die Datenmenge hatte ich dabei gleich gelassen.

Ich beobachte mal, ob sich dadurch was geändert hat und gebe hier nochmal Rückmeldung.

[wvhn]

Die Datenmenge wird nur über den Modus, die Anzahl der Punkte (count) und die Zeitspanne (duration) der Datenreihe bestimmt. Alle Optionen zur Darstellung werden auf dem Client in Highcharts umgesetzt und sind für die Websocket-Verbindung unerheblich.

Onkelandy hatte das Problem auch mal in Verbindung mit einem Log-item. Msinn und AndreK hatten auch erste Maßnahmen umgesetzt. Da die Probleme aber immer nur sporadisch auftreten, konnte die Ursache bisher nicht genau eingegrenzt werden.

Gruß
Wolfram

[AndreK]

Hallo ooUrmeloo,

aus meiner Sicht sind die oben genannten Fehler unabhängig von einander. Der 1001er im Websocket wird protokolliert wenn ein Client "geht". Sollte vorher ein Fehler beim Aufbau der "Series" passieren müsste der Log-Eintrag anders aussehen.

Der Database-Dump wird auf Grund einer anderen Schreib-Aktion verhindert. Wird aber nachgeholt solange hier die Fehlermeldung nicht mehrfach hintereinander kommt sollte das nicht wirklich ein Problem sein.

Hier noch die Frage welche Datenbank setzt Du ein ?
In der Vergangenheit konnte der Fehler auch mit Tabellen von mehreren Tausenddatensätzen pro Chart nicht nachvollzogen werden. Die Datenbankd (in meinem Fall sqlLite) war immer schnell genug.

Die Frage wäre welcher Browser kommt auf welchem Endgerät (Apple / W-Lan-Gerät / kabelgebundener PC) zum Einsatz ?
Falls der Fehler auftritt, kannst Du eventuell in der Browser-Console Auffälligkeiten erkennen ?

Tritt der Fehler auf nach dem der Browser längere Zeit inaktiv war (Tablet mit automatischer Abschaltung zum Strom sparen), oder wird die Visu auf diesem Browser komplett neu geöffnet und benötigt trotzdem ewig ?

Eventuell können wir das Problem mit eine paar weiteren Infos eingrenzen.

Viele Grüße
Andre

[Msinn]

Die erste Meldung (WARNING) sagt aus, dass ein Client (Browser) die Verbindung auf nicht normalem Weg beendet hat.

DIE ZWEITE Meldung (NOTICE) sagt aus (wie Andre bereits schrieb), das die gepufferten Daten (noch) nicht geschrieben werden konnten, weil ein andere Prozess die Datenbank im Moment gesperrt hat, z.B. ein Wardungsjob, der Datensätze löscht, die älter als maxage sind. Dei Meldung kann auch mehrfach hintereinander kommen, falls die Sperrung der Datenbank länger dauert. Anschließend werden dann alle gepufferten Daten geschrieben. Deshalb ist diese Meldung auch nur eine NOTICE und nicht mal eine WARNING.

[ooUrmeloo]

Hallo Andre,

ich versuche mal, Deine Fragen zu beantworten:
database v1.6.9

database:
    driver: sqlite3

Ich habe die Datenmenge pro Plot jetzt überall auf 500 Punkte reduziert. Davor hatte ich tlw. 1000 - je nach Intervall, mehr aber eigentlich nicht.
Endgerät war meistens ein Android Smartphone mit Chrome Browser per WLAN, es kam aber auch schon mal am Windows PC mit Firefox vor (da nutze ich die Visu aber auch seltener). Browser Console habe ich mir zugegebenermaßen noch nie angeschaut. (geht das bei Android überhaupt??)
In letzter Zeit trat es eher auf, wenn ich die Visu komplett neu gestartet hatte. Aber meistens hat es sich schon auf Seiten aufgehängt, auf den Plots eingebunden sind.

Zum Beispiel ist mir auch aufgefallen, dass es bei der Default "stats.sysinfo.system.html" Seite tlw. recht lange dauert. (Plots sind auf default mit 100 Punkten ... aber ok, ich lasse 100 Log-Einträge darstellen ...).
Dabei ist mir übrigens auch aufgefallen, dass meine Threads kontinuierlich ansteigen. Und ich habe jetzt auch vereinzelt Einträge gefunden:

2024-01-21  17:02:22 ERROR    lib.scheduler       Needing more worker threads than the specified maximum of 35!  (67 worker threads active)

Nach der Umstellung auf <= 500 Daten bei den Plots ist zumindest der Websocket Fehler nicht mehr aufgetreten. Der Database Fehler besteht aber weiterhin.

BTW: den Fehler habe ich immer noch dauerhaft in meinem log (ist aber m.E. ein anderes Thema):
https://knx-user-forum.de/forum/supp...53#post1915453

[ooUrmeloo]

Die erste Meldung (WARNING) sagt aus, dass ein Client (Browser) die Verbindung auf nicht normalem Weg beendet hat.

Verstanden ... aber die Warnung wäre mir ja ehrlich gesagt fast egal.
Aber sie korreliert halt immer mit Situationen, in denen eine Seite nicht oder extrem langsam geladen wird.
Ich beende den Browser nicht o.ä. ...

[AndreK]

Hi ooUrmeloo,

das Dein shNg mehr als 35 Worker-Threads bucht lässt vermuten das, dass Problem wo ganz anders liegt. Welcher scheduler/plugin verursacht den die vielen Thread´s.
Evenentuell sind es auch mehrere Tasks die nicht fertig werden !
Kannst Du das im admin-Web-IF nachvollziehen ?

Zum Thema Modbus - ja das sollte ein anderes Thema sein, könnte hier aber über die Worker-Threads mit reinspielen.
Ich kann das in sofern nachvollziehen, dass mein Modus-Plugin in einer Instanz auf einen Wechselrichter auch diverse Fehler schmeißt, hier ein aktueller Log-Auszug :

2024-01-21  22:01:23 ERROR    plugins.modbus_tcp  kostal_wr1@: could not connect to 192.168.178.21:1502
2024-01-21  22:01:45 ERROR    plugins.modbus_tcp  kostal_wr1@: read error: Modbus Error: [Input/Output] Modbus Error: [Invalid Message] No response received, expected at least 8 bytes (0 received) HoldingRegister.6.71 (address.slaveUnit) regCount:8
2024-01-21  22:01:49 ERROR    pymodbus.logging    Connection to (192.168.178.21, 1502) failed: timed out
2024-01-21  22:01:49 ERROR    plugins.modbus_tcp  kostal_wr1@: something went wrong in the poll_device function: Modbus Error: [Connection] Failed to connect[ModbusTcpClient(192.168.178.21:1502)]
2024-01-21  22:01:53 ERROR    pymodbus.logging    Connection to (192.168.178.21, 1502) failed: timed out
2024-01-21  22:01:53 ERROR    plugins.modbus_tcp  kostal_wr1@: could not connect to 192.168.178.21:1502
2024-01-21  22:01:57 ERROR    pymodbus.logging    Connection to (192.168.178.21, 1502) failed: timed out
2024-01-21  22:01:57 ERROR    plugins.modbus_tcp  kostal_wr1@: could not connect to 192.168.178.21:1502
2024-01-21  22:02:02 ERROR    pymodbus.logging    Connection to (192.168.178.21, 1502) failed: timed out
2024-01-21  22:02:02 ERROR    plugins.modbus_tcp  kostal_wr1@: could not connect to 192.168.178.21:1502

Ich polle auf die Wechselrichter (2 Stück) + ein Smartmeter alle 5 Sekunden, ein großer Teil der Werte geht via database-Plugin in die DB. Da läuft so einiges an Traffic.
Es macht auch nur der WR1 Ärger, der zweite nicht und das Smartmeter auch nicht. Das database-Plugin macht das ohne zu meckern mit.
( Der 1. WR kommuziert auch via Modbus-RTU mit dem Smartmeter- eventuell kann der einfach nicht zwei Verbindungen korrekt bedienen ? - das ist mein Problem)

Trotz allem habe ich nicht soviele Worker-Threads ( hab eben nochmal im admin-Interface nachgsehen - in der Spitze sind es heute 7 - und da laufen zeitgesteuert etliche Logiken)

OK, Entwickler-Console auf Android-smartPhone geht nicht ohne weiteres - da wären wir dann beim ADB-debugging - das lohnt sich glaube ich nicht.

Ich vermute auf Grund der vielen Worker-Threads das etwas ganz anderes schief läuft und die Auswirkugen in der VISU/Websocket und dem database-Plugin sichtbar sind.

Kannst Du versuchen die Ursache der vielen Worker-Threads einzugrenzen ? Eventuell durch "abschalten" von Plugins bzw. Logiken.

Viele Grüße
Andre

[ooUrmeloo]

Nach der Umstellung auf <= 500 Daten bei den Plots ist zumindest der Websocket Fehler nicht mehr aufgetreten.

Zu früh gefreut. Gerade eben mit dem Smartphone getestet ... Die kleine stats.sysinfo Seite hat >40s zum Laden gebraucht ...

Screenshot_20240121-222219.pngScreenshot_20240121-222237.png

[ooUrmeloo]

Kannst Du das im admin-Web-IF nachvollziehen ?

Habe ich ehrlich gesagt noch nie gecheckt ... :-/

Wenn Du nur 7 hast, erscheint mir "idle" mit 45 und "modules.http.cherrypy_server" mit 14 threads am auffälligsten ...

   Thread (gesamt: 99) Thread-Id Prozess-Id Aktiv  
asyncio_0 1613747264 13010 Ja  
asyncio_1 1605354560 13011 Ja  
asyncio_2 1578538048 13016 Ja  
asyncio_3 1510347840 13346 Ja  
asyncio_4 1211085888 24152 Ja  
asyncio_5 1157579840 26275 Ja  
idle (45 threads)   Ja  
items.paradigma.Betriebsstunden_Monat_bisher 1442944064 13907 Ja  
items.paradigma.Betriebsstunden_Tag_bisher 1202693184 24511 Ja  
items.paradigma.Betriebsstunden_Woche_bisher 1544180800 13119 Ja  
items.paradigma.Brenner_Starts_Jahr_bisher 1426158656 14207 Ja  
items.paradigma.Brenner_Starts_Monat_bisher 1622139968 13004 Ja  
items.temperatur.aussen.max1d 1149187136 27021 Ja  
items.temperatur.aussen.max1y 1256944704 18568 Ja  
items.temperatur.aussen.max7d 1933571136 12870 Ja  
items.temperatur.aussen.min1d 1384195136 15052 Ja  
items.temperatur.aussen.min1m 1679807552 12965 Ja  
items.temperatur.aussen.min1y 1333838912 15422 Ja  
items.temperatur.aussen.min7d 1324348480 15483 Ja  
items.temperatur.wohnzimmer.max1d 1307300928 15766 Ja  
items.temperatur.wohnzimmer.max1m 1115616320 27935 Ja  
items.temperatur.wohnzimmer.max1y 1944056896 12869 Ja  
items.temperatur.wohnzimmer.max7d 1107223616 27941 Ja  
items.temperatur.wohnzimmer.min1d 1671414848 12964 Ja  
items.temperatur.wohnzimmer.min1m 1265337408 16834 Ja  
items.temperatur.wohnzimmer.min1y 1596961856 13012 Ja  
items.temperatur.wohnzimmer.min7d 1535788096 13289 Ja  
Main 1995446656 12838 Ja  
modules.http.cherrypy_server (14 threads)   Ja  
modules.http.http_server (2 threads)   Ja  
modules.mqtt.paho_client 1757344832 12890 Ja  
modules.websocket.websocket_server 1765737536 12889 Ja  
plugins.database.Remove old 1527395392 13344 Ja  
Scheduler 1964639296 12867 Ja  
TCP_Client (plugins.knx_127.0.0.1:6720) 1646236736 12913 Ja  
temperatur.bad.gradient-eval 1359017024 15144 Ja  
temperatur.baddg.gradient-eval 1493562432 13380 Ja  
temperatur.gaeste.gradient-eval 1409373248 14327 Ja  
temperatur.gaesteankl.gradient-eval 1065260096 31385 Ja  
temperatur.schlafzimmerdg.gradient-eval 1227871296 24137 Ja  
temperatur.wohnzimmerdg.gradient-eval 1090438208 27944 Ja    ​

[AndreK]

Hier stellt sich Frage was 45 idle verursacht hat?

Im Moment weiß ich auch nicht wie man das nachvollziehen kann, da muss ich mal drüber schlafen

Viele Grüße
Andre

[AndreK]

Hi ooUrmeloo,

ich wußte doch da war noch was 😉, ich hatte mal ein Script (auszuführen im Executor-Plugin) erstellt, welches die Worker-Threads und Main-Threads protokolliert
Den Code in das Executor-Plugin einfügen und starten. Es wird dann für 30 Sekunden alle 3 Sekunden in ein Logfile geschrieben. Du kannst die Anzahl Durchläufe erhöhen wenn Du den While Vergleich von 10 einfach höher setzt und /oder das Intervall verkürzen in dem Du time.sleep() verkleinerst. Die Daten landen dann in ./smarthome/var/log/thread.log.

Eventuell bringt das mehr Licht ins Dunkel

import threading
import os
import time
from datetime import datetime
myPath = sh.get_basedir()+'/var/log/'
filler="                                         "
filename = myPath+'thread.log'

act_count = 0
while act_count <=10:
  act_count += 1
  if os.path.exists(filename):
      append_write = 'a' # append if already exists
  else:
      append_write = 'w' # make a new file if not
  file = open(filename,append_write)
  now = datetime.now()
  file.write ('------------------------------------------------'+'\n')
  file.write (now.strftime("%m/%d/%Y, %H:%M:%S")+'\n')
  file.write ('Worker-Threads'+'\n')
  file.write ('=============='+'\n')
  for w in sh.scheduler._workers:
    file.write (w.name + filler[0:len(filler)-len(w.name)] + '   is Alive : ' + str(w.is_alive()) + ' ident : ' + str(w.ident) + '  native_id: '+ str(w.native_id)+'\n')
  file.write ('Main-Threads'+'\n')
  file.write ('=============='+'\n')
  for w in threading.enumerate():
    file.write (w.name + filler[0:len(filler)-len(w.name)] + '   is Alive : ' + str(w.is_alive()) + ' ident : ' + str(w.ident) + '  native_id: '+ str(w.native_id)+'\n')
  file.close()
  time.sleep(3)

Viele Grüße
Andre

[ooUrmeloo]

Danke für die Hilfe!
Das kann ich erst heute Abend probieren ...
Melde mich.

[Msinn]

„Idle“ ist ein Pool von zzt nicht genutzten Worker Threads des shng-Schedulers, aus dem bei Bedarf ein benötiger Thread genommen wird, statt einen neuen zu erzeugen. Ein neuer Worker Thread wird nur erzeugt, wenn der idle-Pool leer ist. Das bedeutet, dass zu einem Zeitpunkt in der Vergangenheit gleichzeitig 45 Worker mehr aktiv waren, als jetzt.

Die 14 Threads von Cherrypy sind keine Threads des shng-Schedulers und sind normal. Die Threads werden vom Webserver genutzt, der die Admin GUI und die Webinterfaces bereit. Stellt.