[gelöst] hohe Load, Bitte um Hilfe bei Fehlersuche

[macfly]

Moin zusammen,

meine fhem-Instanz läuft auf einem core-i5 mit 32GB Ram und SSDs (seit .. lange, ich weiß nicht, 7 Jahren?).

Seit 3 Tagen schafft fhem es, einen Kern komplett zu sättigen, also 100% CPU in Top zu erzeugen. Das alleine würde mich nicht stören, allerdings bricht immer wieder die Verbindung zu meinem HmLanGw ab und diverse Geräte landen lt. Logfile im Timeout.

In Verdacht hatte ich die drei Wechselrichter, die ich via modbus-tcp angebunden habe, und die in der dunklen Zeit in den Standby gehen und nicht antworten, also habe ich das modbus-device, an dem alle Wechselrichter via daisy-chain hängen mal gelöscht -> keine besserung.

Syslog des Hosts ist ohne Befund, Platte ist nicht voll, mysql (wohin fhem loggt) antwortet zügig.

wenn exemplarisch im logfile folgendes auftaucht

Code Auswählen Erweitern

2024.01.01 10:29:25 0: IPCAM (IPCAM_Garten) - error while getting snapshot https://xxxx:xxxxx@192.168.100.95//cgi-bin/api.cgi?cmd=Snap&channel=0&rs=wuuPhkmUCeI9WG7C&user=xxxxx&password=xxxxx - start_SSL https://192.168.100.95:443 timed out
und ich dann direkt danach diese URL vom fhem-host via curl aufrufe, bekomme ich problemlos das Bild heruntergeladen.

selbst die http requests zu clever-tanken laufen in einen Timeout, die aber auch auf der Konsole einwandfrei funktionieren.

ein strace auf die perl-prozesse ergibt für fast alle Prozesse:

Code Auswählen Erweitern

pselect6(8, [4], NULL, NULL, {tv_sec=1, tv_nsec=0}, NULL) = 0 (Timeout)
getpid()                                = 26671
pselect6(8, [4], NULL, NULL, {tv_sec=1, tv_nsec=0}, NULL) = 0 (Timeout)
getpid()                                = 26671
... in Endlosschleife
oder

Code Auswählen Erweitern

clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=300000000}, NULL) = 0
pselect6(8, [6], NULL, NULL, {tv_sec=0, tv_nsec=1000000}, NULL) = 0 (Timeout)


bei den neu geforkten Prozessen finde ich sowas:

Code Auswählen Erweitern

read(7, "1\n", 4096)                    = 2
socket(AF_INET, SOCK_STREAM|SOCK_CLOEXEC, IPPROTO_TCP) = 8
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
ioctl(8, TCGETS, 0x7ffe38513b70)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(8, 0, SEEK_CUR)                   = -1 ESPIPE (Illegal seek)
fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
ioctl(8, TCGETS, 0x7ffe38513b70)        = -1 ENOTTY (Inappropriate ioctl for device)
lseek(8, 0, SEEK_CUR)                   = -1 ESPIPE (Illegal seek)
fcntl(8, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(8, {sa_family=AF_INET, sin_port=htons(55000), sin_addr=inet_addr("192.168.42.224")}, 16) = -1 EINPROGRESS (Operation now in progress)
pselect6(16, NULL, [8], [8], {tv_sec=2, tv_nsec=0}, NULL) = 0 (Timeout)
fcntl(8, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(8, F_SETFL, O_RDWR)               = 0
close(8)                                = 0
write(7, "{BlockingStart('76')}\n", 22) = 22
pselect6(8, [7], NULL, NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
write(7, "{VIERA_GetDone('EG.Stube.TV|erro"..., 61) = 61
pselect6(8, [7], NULL, NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
close(7)                                = 0
exit_group(0)                           = ?


(EG.Stube.TV ist der Fernseher, der gerade aus ist).


Hat jemand Tipps, wie ich hier weiter nach Fehler suchen kann? Gibt es ein analogon zu mysql-slow-query-log für fhem, wo alle "langsamen" requests/actions geloggt werden?


vielen Dank fürs Lesen bis hierher und allen ein friedliches neues Jahr,
Friedhelm

[macfly]

Freezemon ist sich auch unsicher, was da abgeht, wenn ich das richtig interpretiere ...

Du darfst diesen Dateianhang nicht ansehen.

[macfly]

auszug aus dem Logfile, wo man sieht, dass fhem die Verbindung z.B. zum Venuscontroller (192.168.42.173) verliert:

Code Auswählen Erweitern

2024.01.01 14:57:05 1: [Freezemon] freezemon: possible freeze starting at 14:56:57, delay is 8.438 possibly caused by: tmr-HMUARTLGW_StartInit(HMLANGW) tmr-CODE(0x55ec43fbceb0)(ProcessReque
stQueue) tmr-HMLAN_KeepAliveCheck(hmusb) tmr-HttpUtils_TimeoutErr(N/A) tmr-KLF200Node_UpdateStatus(DG.Dachboden.Fenster) tmr-HMUARTLGW_CheckCmdResp(HMLANGW) tmr-HttpUtils_TimeoutErr(N/A) tm
r-DbLog_execMemCacheAsync(logdb) tmr-plex_refreshSubscriptions(Plex) tmr-VIERA_GetStatus(EG.Stube.TV) tmr-HOMEPILOTAKTOR_GetStatus(OG.Schlafzimmer.Rolladen) tmr-HOMEPILOTAKTOR_GetStatus(OG.
Kinderzimmer.Rolladen) tmr-CODE(0x55ec44025a30)(GetUpdate) tmr-CODE(0x55ec44025a30)(GetUpdate)
2024.01.01 14:57:06 0: IPCAM (IPCAM_Garten) - error while getting snapshot https://xxx:xxx@192.168.100.95//cgi-bin/api.cgi?cmd=Snap&channel=0&rs=wuuPhkmUCeI9WG7C&user=xxx&password=
xxx - start_SSL https://192.168.100.95:443 timed out
2024.01.01 14:57:06 3: KLF200Node (DG.Dachboden.Fenster) Unknown CommandOriginator ID: 0
2024.01.01 14:57:08 3: CUL_HM set Garten.Heizung_Sw statusRequest noArg
2024.01.01 14:57:11 1: 192.168.42.220:2001 disconnected, waiting to reappear (HMLANGW:keepAlive)
2024.01.01 14:57:11 1: 192.168.42.220:2000 disconnected, waiting to reappear (HMLANGW)
2024.01.01 14:57:12 3: Opening HMLANGW:keepAlive device 192.168.42.220:2001
2024.01.01 14:57:12 1: 192.168.42.220:2000 reappeared (HMLANGW)
2024.01.01 14:57:13 3: HMLANGW:keepAlive device opened
2024.01.01 14:57:14 3: HMUARTLGW HMLANGW BidCoS-port opened
2024.01.01 14:57:14 2: venus: No PINGRESP for last PINGREQ (at 2024-01-01 14:56:44), disconnecting
2024.01.01 14:57:14 1: 192.168.42.173:1883 disconnected, waiting to reappear (venus)
2024.01.01 14:57:14 3: HMUARTLGW HMLANGW:keepAlive KeepAlive-port opened
2024.01.01 14:57:15 1: 192.168.42.173:1883 reappeared (venus)
2024.01.01 14:57:29 1: [Freezemon] freezemon: possible freeze starting at 14:57:21, delay is 8.663 possibly caused by: tmr-FW_closeInactiveClients(N/A) tmr-FRITZBOX_Readout_Start(N/A) tmr-T
PLinkHS110_Get(EG.Kueche.Geschirrspueler) tmr-TPLinkHS110_Get(EG.Stube.Multimedia) tmr-TPLinkHS110_Get(Garten.Pool.Pumpe) tmr-FHEM::readingsWatcher::OnTimer(readingsWatcher) tmr-APCUPSD_Pol
lTimer(USV.APC_XS700)
2024.01.01 14:57:46 1: HMUARTLGW HMLANGW:keepAlive KeepAlive sent 19.545s too late, this might cause a disconnect!
2024.01.01 14:57:46 1: [Freezemon] freezemon: possible freeze starting at 14:57:30, delay is 16.277 possibly caused by: tmr-RESIDENTStk_DurationTimer(Friedhelm_DurationTimer) tmr-RESIDENTSt
k_DurationTimer(Hilke_DurationTimer) tmr-RESIDENTStk_DurationTimer(Bewohner_DurationTimer) tmr-CODE(0x55ec43fbceb0)(ProcessRequestQueue) tmr-CODE(0x55ec462f17d0)(__ANON__) tmr-HUEBridge_Pai
r(deCONZ) tmr-CUL_HM_respPendTout(5B9B19) tmr-HMUARTLGW_CheckCmdResp(HMLANGW) tmr-PRESENCE_StartLocalScan(PRESENCE.Friedhelm) tmr-HMUARTLGW_SendKeepAlive(HMLANGW) tmr-plex_sendDiscover(Plex
) tmr-plex_sendDiscover(Plex) tmr-plex_sendDiscover(Plex) tmr-plex_sendDiscover(Plex) tmr-MQTT2_SERVER_keepaliveChecker(mqtt_server) tmr-HMLAN_clearQ(hmusb) tmr-CUL_HM_readStateTo(Garten.He
izung_Sw) tmr-OctoPrint_GetStatus(PrusaMK3s)
2024.01.01 14:57:46 1: 192.168.42.220:2001 disconnected, waiting to reappear (HMLANGW:keepAlive)
2024.01.01 14:58:00 1: [Freezemon] freezemon: possible freeze starting at 14:57:47, delay is 13.742 possibly caused by: tmr-CODE(0x55ec43fbceb0)(ProcessRequestQueue) tmr-CODE(0x55ec44063110)(ResponseTimeout) tmr-at_Exec(snapshot_IPCAM_Garten) tmr-HMUARTLGW_CheckCmdResp(HMLANGW) tmr-Unifi_DoUpdate(unifi) tmr-DbLog_execMemCacheAsync(logdb) tmr-plex_refreshSubscriptions(Plex) tmr-VIERA_GetStatus(EG.Stube.TV) tmr-HOMEPILOTAKTOR_GetStatus(OG.Schlafzimmer.Rolladen) tmr-at_Exec(Ladestrategie_pruefen) tmr-at_Exec(update_Hausakku) tmr-HOMEPILOTAKTOR_GetStatus(OG.Kinderzimmer.Rolladen) tmr-CODE(0x55ec44025a30)(GetUpdate) tmr-CODE(0x55ec44025a30)(GetUpdate) tmr-PRESENCE_StartLocalScan(PRESENCE.Hilke) tmr-at_Exec(at_VictronKeepalive) tmr-FHEM::SolarForecast::centralTask(SolarForecast) tmr-MQTT2_CLIENT_keepalive(venus) tmr-HMLAN_KeepAlive(hmusb)
2024.01.01 14:58:00 1: 192.168.42.220:2000 disconnected, waiting to reappear (HMLANGW)
2024.01.01 14:58:01 3: logdb - INFO - 248 of 354 events inserted into table >history< due to PK on columns TIMESTAMP,DEVICE,READING
2024.01.01 14:58:10 1: [Freezemon] freezemon: possible freeze starting at 14:58:01, delay is 9.033 possibly caused by: tmr-HttpUtils_TimeoutErr(N/A) tmr-HMUARTLGW_CheckCmdResp(HMLANGW) tmr-HMUARTLGW_CheckCmdResp(HMLANGW) tmr-HttpUtils_TimeoutErr(N/A) tmr-CUL_HM_respPendTout(5B9B19) tmr-HUEBridge_Pair(deCONZ) tmr-HMLAN_clearQ(hmusb) tmr-plex_sendDiscover(Plex) tmr-plex_sendDiscover(Plex) tmr-plex_sendDiscover(Plex) tmr-plex_sendDiscover(Plex) tmr-MQTT2_SERVER_keepaliveChecker(mqtt_server) tmr-CODE(0x55ec45faca80)(__ANON__) tmr-IPCAM::RequestSnapshot(IPCAM_Garten) tmr-HMLAN_KeepAlive(hmusb)
2024.01.01 14:58:21 1: [Freezemon] freezemon: possible freeze starting at 14:58:11, delay is 10.537 possibly caused by: tmr-FHEM::SolarForecast::singleUpdateState(N/A) tmr-CODE(0x55ec43fbceb0)(ProcessRequestQueue) tmr-CODE(0x55ec44063110)(ResponseTimeout) tmr-HttpUtils_TimeoutErr(N/A) tmr-HttpUtils_TimeoutErr(N/A) tmr-PRESENCE_StartLocalScan(Hilke_Arbeitszimmer) tmr-DOIF_TimerTrigger(DOIF.EG.Stube.Kamin.addLog) tmr-at_Exec(at_VictronKeepalive) tmr-BlockingKill(N/A)
2024.01.01 14:58:21 3: Opening HMLANGW:keepAlive device 192.168.42.220:2001
2024.01.01 14:58:21 1: 192.168.42.220:2000 reappeared (HMLANGW)

gleichzeitig habe ich aber ein ping -f zu dieser IP laufen vom fhem-Host aus:

Code Auswählen Erweitern

root@storage:/# ping -f 192.168.42.173
PING 192.168.42.173 (192.168.42.173) 56(84) bytes of data.
.^C
--- 192.168.42.173 ping statistics ---
5880 packets transmitted, 5879 received, 0.0170068% packet loss, time 26965ms
rtt min/avg/max/mdev = 2.076/4.935/138.684/5.739 ms, pipe 9, ipg/ewma 4.586/4.126 ms

das sieht soweit gut aus, oder?

[macfly]

Da sich die Fehler so undifferenziert zeigten (Netzwerktimeout, obwohl ich auf shell keinen Timeout bekomme), habe ich mal weiter rumgeschaut, IOtop, analyse zfs usw.

Dabei war mir im Logfile aufgefallen, dass fhem fast zwei minuten benötigte, um fhem.save zu laden. ein ls zeigte, dass die fhem.save knapp 200mb (!!) groß war.

Texteditor, suche nach Fehler, brachte dann die Erkenntnis, dass von meinem mqtt-server das RETAIN-Attribut kann 199MB groß war, inkl. nicht druckbarer Zeihen.

Ich habe fhem gestoppt, retain komplett gelöscht (brauche ich imho nicht) und schon läuft fhem wieder zügig.

Dies hier nur als PostMortem, falls jemand anders ein ähnliches Problem hat.

[rob]

Hallo Friedhelm.

Wünsche Dir auch ein frohes neues Jahr

Schau mal bitte in diesen Fred rein: https://forum.fhem.de/index.php?msg=1247841
Müsste zu Deiner Schilderung passen. Löschen im Statefile allein reicht auf Dauer nicht, weil es sich ggf. wieder langsam aufblähen kann.
Im MQTT2_Server habe ich dies aktiv:

Code Auswählen Erweitern

attr myMQTT_Server respectRetain 0
Als Interimslösung hatte ich damals via 'periodicCmd' einmal täglich clearRetain ausgeführt. Mit obigem Attribut nicht mehr nötig gewesen.

Viele Grüße
rob