Probleme mit Freezes

PatrickR · 16 November 2021, 09:12:40

Hallo zusammen!

Ich habe seit mehreren Wochen Probleme mit Freezes, nachdem ich über stetiges Nachsteuern über Jahre einen Zustand mit 1-2 Freezes (Threshold 1s) pro Tag hatte (lt. Freezemon). Nun habe ich seit einigen Wochen eine hohe Anzahl an täglichen Freezes, ohne dass ich mich an eine größere Änderung in FHEM erinnern könnte. Diese treten unter anderem dann auf, wenn viele Events in kurzer Zeit auftreten (z. B. UniFi, aber auch HmIP-Geräte). event-on-change-reading ist bei nahezu allen Geräten gesetzt, teilweise mit Thresholds. Ich habe nun über Tage versucht, das Problem zu lösen (u. a. durch Auslagerung von UniFi in eine zweite FHEM-Instanz), aber habe angesichts der Ergebnisse den Eindruck, dass ich an den falschen Schrauben drehe. Daher habe ich bspw. die Zahl der maximalen Events von HMCCURPCPROC noch nicht verkleinert.

Hier ein Beispiel eines Freezes:

Code Auswählen


Di 16.11.2021 07:56:57  freezemon s:07:56:56 e:07:56:57 f:1.733 d:fn-ReadFn(d_rpcHmIP_RF2)

Und das zugehörige Log (zusätzlich untern verlinkt):

Code Auswählen


=========================================================
[Freezemon] freezemon: possible freeze starting at 07:56:56, delay is 1.733 possibly caused by: fn-ReadFn(d_rpcHmIP_RF2) 
2021.11.16 07:56:55.242 5: PRESENCE (P_PR_raw) - received data: absence;rssi=unreachable;model=lan-lepresenced;daemon=lepresenced V0.93dev21
2021.11.16 07:56:55.722 5: getRequest: Received packet: 0027100c1b160080428e0000

2021.11.16 07:56:55.722 5: decode_eibd: byte len: 5 array size: 5
2021.11.16 07:56:55.722 5: SimpleRead msg.type: write, msg.src: 0100c, msg.dst: 03316
2021.11.16 07:56:55.722 5: SimpleRead data: 428e0000
2021.11.16 07:56:55.722 4: SimpleRead: 0100cw03316428e0000

2021.11.16 07:56:55.722 4: KNXd: C0100cw03316428e0000
2021.11.16 07:56:55.722 5: KNX_Parse -enter: IO-name: KNXd, dest: 03316, msg: C0100cw03316428e0000
2021.11.16 07:56:55.722 4: KNX_Parse -process: IO-name: KNXd, device-name: UG.AZ.Steckdosen13bis18, rd-name: power, gadCode: 03316, cmd: w
2021.11.16 07:56:55.723 5: KNX_decodeByDpt -enter: model: dpt14.056, code: dpt14, value: 428e0000, length-value: 8
2021.11.16 07:56:55.723 5: KNX_limit: DIR: DECODE FACTOR: 1 OFFSET: 0
2021.11.16 07:56:55.723 5: KNX_decodeByDpt -exit: model: dpt14.056, code: dpt14, value: 428e0000, state: 71.000 W
2021.11.16 07:56:55.723 4: KNX_Parse (wp): UG.AZ.Steckdosen13bis18, READINGNAME: power, VALUE: 71.000 W, SENDER: 0100c
2021.11.16 07:56:55.723 5: KNX_parse -exit
2021.11.16 07:56:55.724 5: createNotifyHash
2021.11.16 07:56:55.932 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:55.932 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:55.932 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:55.932 4: DbLog DbLog -> number of events received: 2 of device: UG.AZ.Steckdosen13bis18
2021.11.16 07:56:55.933 4: DbLog DbLog -> check Device: UG.AZ.Steckdosen13bis18 , Event: power: 71.000 W
2021.11.16 07:56:55.933 5: KNX_DbLog_split -enter: device= UG.AZ.Steckdosen13bis18 event= power: 71.000 W
2021.11.16 07:56:55.933 5: KNX_DbLog_split -exit: device= UG.AZ.Steckdosen13bis18, reading= power, value= 71.000, unit= W
2021.11.16 07:56:55.933 5: DbLog DbLog -> parsed Event: UG.AZ.Steckdosen13bis18 , Event: power: 71.000 W
2021.11.16 07:56:55.933 4: DbLog DbLog -> check Device: UG.AZ.Steckdosen13bis18 , Event: state: 71.000 W
2021.11.16 07:56:55.933 5: KNX_DbLog_split -enter: device= UG.AZ.Steckdosen13bis18 event= state: 71.000 W
2021.11.16 07:56:55.933 5: KNX_DbLog_split -exit: device= UG.AZ.Steckdosen13bis18, reading= state, value= 71.000, unit= W
2021.11.16 07:56:55.933 5: DbLog DbLog -> parsed Event: UG.AZ.Steckdosen13bis18 , Event: state: 71.000 W
2021.11.16 07:56:55.935 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:55.936 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:55.942 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/UG.AZ.Steckdosen13bis18/power => 71.000 W (qos: 0, retain: 1
2021.11.16 07:56:55.947 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/UG.AZ.Steckdosen13bis18/state => 71.000 W (qos: 0, retain: 1
2021.11.16 07:56:55.948 5: End notify loop for UG.AZ.Steckdosen13bis18
2021.11.16 07:56:55.949 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read called
2021.11.16 07:56:55.954 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read stopped after 70 events read: no data
2021.11.16 07:56:55.961 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:55.961 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:55.961 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:55.961 4: DbLog DbLog -> number of events received: 1 of device: hmiphap2
2021.11.16 07:56:55.961 4: DbLog DbLog -> check Device: hmiphap2 , Event: 0.CARRIER_SENSE_LEVEL: 10
2021.11.16 07:56:55.961 5: DbLog DbLog -> parsed Event: hmiphap2 , Event: 0.CARRIER_SENSE_LEVEL: 10
2021.11.16 07:56:55.961 5: DbLog DbLog -> DbLogInclude of "hmiphap2": 0.DUTY_CYCLE_LEVEL,0.CARRIER_SENSE_LEVEL
2021.11.16 07:56:55.961 4: DbLog DbLog -> added event - Timestamp: 2021-11-16 07:56:55, Device: hmiphap2, Type: HMCCUDEV, Event: 0.CARRIER_SENSE_LEVEL: 10, Reading: 0.CARRIER_SENSE_LEVEL, Value: 10, Unit: 
2021.11.16 07:56:55.975 5: End notify loop for hmiphap2
2021.11.16 07:56:56.147 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.147 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.147 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.147 4: DbLog DbLog -> number of events received: 5 of device: OG.SZ.RolladenR
2021.11.16 07:56:56.147 4: DbLog DbLog -> check Device: OG.SZ.RolladenR , Event: 0.RSSI_PEER: -63
2021.11.16 07:56:56.147 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenR , Event: 0.RSSI_PEER: -63
2021.11.16 07:56:56.147 4: DbLog DbLog -> check Device: OG.SZ.RolladenR , Event: 0.RSSI_DEVICE: -78
2021.11.16 07:56:56.147 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenR , Event: 0.RSSI_DEVICE: -78
2021.11.16 07:56:56.147 4: DbLog DbLog -> check Device: OG.SZ.RolladenR , Event: 4.PROCESS: moving
2021.11.16 07:56:56.147 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenR , Event: 4.PROCESS: moving
2021.11.16 07:56:56.147 4: DbLog DbLog -> check Device: OG.SZ.RolladenR , Event: 4.SECTION: 3
2021.11.16 07:56:56.147 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenR , Event: 4.SECTION: 3
2021.11.16 07:56:56.147 4: DbLog DbLog -> check Device: OG.SZ.RolladenR , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:56.147 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenR , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:56.148 5: structure OG.SZ.Rolladen: event from OG.SZ.RolladenR: setting state to closed
2021.11.16 07:56:56.149 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.150 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.150 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.150 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.151 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.157 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenR/0.RSSI_PEER => -63 (qos: 0, retain: 1
2021.11.16 07:56:56.162 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenR/0.RSSI_DEVICE => -78 (qos: 0, retain: 1
2021.11.16 07:56:56.167 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenR/4.PROCESS => moving (qos: 0, retain: 1
2021.11.16 07:56:56.172 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenR/4.SECTION => 3 (qos: 0, retain: 1
2021.11.16 07:56:56.176 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenR/4.ACTIVITY_STATE => 1 (qos: 0, retain: 1
2021.11.16 07:56:56.184 5: End notify loop for OG.SZ.RolladenR
2021.11.16 07:56:56.372 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.372 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.372 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.372 4: DbLog DbLog -> number of events received: 2 of device: OG.BZ.Rolladen
2021.11.16 07:56:56.372 4: DbLog DbLog -> check Device: OG.BZ.Rolladen , Event: 0.RSSI_DEVICE: -72
2021.11.16 07:56:56.372 5: DbLog DbLog -> parsed Event: OG.BZ.Rolladen , Event: 0.RSSI_DEVICE: -72
2021.11.16 07:56:56.372 4: DbLog DbLog -> check Device: OG.BZ.Rolladen , Event: 0.RSSI_PEER: -65
2021.11.16 07:56:56.372 5: DbLog DbLog -> parsed Event: OG.BZ.Rolladen , Event: 0.RSSI_PEER: -65
2021.11.16 07:56:56.373 5: structure OG.Rolladen: event from OG.BZ.Rolladen: setting state to closed
2021.11.16 07:56:56.374 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.374 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.374 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.374 4: DbLog DbLog -> number of events received: 1 of device: OG.Rolladen
2021.11.16 07:56:56.374 4: DbLog DbLog -> check Device: OG.Rolladen , Event: state: closed
2021.11.16 07:56:56.374 5: DbLog DbLog -> parsed Event: OG.Rolladen , Event: state: closed
2021.11.16 07:56:56.375 5: structure HA.Rolladen: event from OG.Rolladen: setting state to undefined, cause different states: open,closed
2021.11.16 07:56:56.375 5: RG_structure_async_delay: not on any display, ignoring notify
2021.11.16 07:56:56.386 5: End notify loop for OG.Rolladen
2021.11.16 07:56:56.387 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.388 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.394 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.BZ.Rolladen/0.RSSI_DEVICE => -72 (qos: 0, retain: 1
2021.11.16 07:56:56.399 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.BZ.Rolladen/0.RSSI_PEER => -65 (qos: 0, retain: 1
2021.11.16 07:56:56.407 5: End notify loop for OG.BZ.Rolladen
2021.11.16 07:56:56.581 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.581 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.581 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.581 4: DbLog DbLog -> number of events received: 6 of device: OG.KZ.RolladenL
2021.11.16 07:56:56.581 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: 3.PROCESS: moving
2021.11.16 07:56:56.581 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: 3.PROCESS: moving
2021.11.16 07:56:56.581 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: 3.ACTIVITY_STATE: 1
2021.11.16 07:56:56.581 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: 3.ACTIVITY_STATE: 1
2021.11.16 07:56:56.581 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: 3.LEVEL: 3
2021.11.16 07:56:56.582 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: 3.LEVEL: 3
2021.11.16 07:56:56.582 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: state: 3
2021.11.16 07:56:56.582 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: state: 3
2021.11.16 07:56:56.582 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: 0.RSSI_DEVICE: -64
2021.11.16 07:56:56.582 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: 0.RSSI_DEVICE: -64
2021.11.16 07:56:56.582 4: DbLog DbLog -> check Device: OG.KZ.RolladenL , Event: hmstate: 3
2021.11.16 07:56:56.582 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenL , Event: hmstate: 3
2021.11.16 07:56:56.583 5: structure OG.KZ.Rolladen: event from OG.KZ.RolladenL: setting state to undefined, cause different states: closed,3
2021.11.16 07:56:56.741 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.741 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.741 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.741 4: DbLog DbLog -> number of events received: 1 of device: OG.KZ.Rolladen
2021.11.16 07:56:56.741 4: DbLog DbLog -> check Device: OG.KZ.Rolladen , Event: state: undefined
2021.11.16 07:56:56.741 5: DbLog DbLog -> parsed Event: OG.KZ.Rolladen , Event: state: undefined
2021.11.16 07:56:56.741 5: structure OG.Rolladen: event from OG.KZ.Rolladen: setting state to undefined
2021.11.16 07:56:56.742 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.742 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.742 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.742 4: DbLog DbLog -> number of events received: 1 of device: OG.Rolladen
2021.11.16 07:56:56.742 4: DbLog DbLog -> check Device: OG.Rolladen , Event: state: undefined
2021.11.16 07:56:56.743 5: DbLog DbLog -> parsed Event: OG.Rolladen , Event: state: undefined
2021.11.16 07:56:56.743 5: structure HA.Rolladen: event from OG.Rolladen: setting state to undefined
2021.11.16 07:56:56.743 5: RG_structure_async_delay: not on any display, ignoring notify
2021.11.16 07:56:56.750 5: End notify loop for OG.Rolladen
2021.11.16 07:56:56.751 5: RG_structure_async_delay: not on any display, ignoring notify
2021.11.16 07:56:56.751 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.757 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.Rolladen/state => undefined (qos: 0, retain: 1
2021.11.16 07:56:56.758 5: End notify loop for OG.KZ.Rolladen
2021.11.16 07:56:56.759 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.759 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.760 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.760 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.760 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.761 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:56.767 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/3.PROCESS => moving (qos: 0, retain: 1
2021.11.16 07:56:56.772 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/3.ACTIVITY_STATE => 1 (qos: 0, retain: 1
2021.11.16 07:56:56.773 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.773 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.773 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.773 4: DbLog DbLog -> number of events received: 1 of device: MQTTBridge
2021.11.16 07:56:56.773 4: DbLog DbLog -> check Device: MQTTBridge , Event: outgoing-count: 73176
2021.11.16 07:56:56.773 5: DbLog DbLog -> parsed Event: MQTTBridge , Event: outgoing-count: 73176
2021.11.16 07:56:56.776 5: End notify loop for MQTTBridge
2021.11.16 07:56:56.781 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/3.LEVEL => 3 (qos: 0, retain: 1
2021.11.16 07:56:56.786 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/state => 3 (qos: 0, retain: 1
2021.11.16 07:56:56.791 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/0.RSSI_DEVICE => -64 (qos: 0, retain: 1
2021.11.16 07:56:56.795 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenL/hmstate => 3 (qos: 0, retain: 1
2021.11.16 07:56:56.803 5: End notify loop for OG.KZ.RolladenL
2021.11.16 07:56:56.967 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.967 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:56.967 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:56.967 4: DbLog DbLog -> number of events received: 7 of device: OG.KZ.RolladenR
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: 0.RSSI_DEVICE: -64
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: 0.RSSI_DEVICE: -64
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: 4.PROCESS: moving
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: 4.PROCESS: moving
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: 4.SECTION: 3
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: 4.SECTION: 3
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: 3.LEVEL: 3
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: 3.LEVEL: 3
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: state: 3
2021.11.16 07:56:56.967 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: state: 3
2021.11.16 07:56:56.967 4: DbLog DbLog -> check Device: OG.KZ.RolladenR , Event: hmstate: 3
2021.11.16 07:56:56.968 5: DbLog DbLog -> parsed Event: OG.KZ.RolladenR , Event: hmstate: 3
2021.11.16 07:56:56.968 5: structure OG.KZ.Rolladen: event from OG.KZ.RolladenR: setting state to 3
2021.11.16 07:56:57.130 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.130 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:57.130 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.130 4: DbLog DbLog -> number of events received: 1 of device: OG.KZ.Rolladen
2021.11.16 07:56:57.130 4: DbLog DbLog -> check Device: OG.KZ.Rolladen , Event: state: 3
2021.11.16 07:56:57.130 5: DbLog DbLog -> parsed Event: OG.KZ.Rolladen , Event: state: 3
2021.11.16 07:56:57.131 5: structure OG.Rolladen: event from OG.KZ.Rolladen: setting state to undefined, cause different states: 3,closed
2021.11.16 07:56:57.131 5: RG_structure_async_delay: not on any display, ignoring notify
2021.11.16 07:56:57.132 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.138 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.Rolladen/state => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.139 5: End notify loop for OG.KZ.Rolladen
2021.11.16 07:56:57.141 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.141 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.141 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.142 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.142 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.142 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.142 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.148 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/0.RSSI_DEVICE => -64 (qos: 0, retain: 1
2021.11.16 07:56:57.153 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/4.ACTIVITY_STATE => 1 (qos: 0, retain: 1
2021.11.16 07:56:57.158 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/4.PROCESS => moving (qos: 0, retain: 1
2021.11.16 07:56:57.163 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/4.SECTION => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.167 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/3.LEVEL => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.172 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/state => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.177 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.KZ.RolladenR/hmstate => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.184 5: End notify loop for OG.KZ.RolladenR
2021.11.16 07:56:57.353 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.353 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:57.353 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.353 4: DbLog DbLog -> number of events received: 3 of device: OG.AN.Rolladen
2021.11.16 07:56:57.353 4: DbLog DbLog -> check Device: OG.AN.Rolladen , Event: 4.SECTION: 3
2021.11.16 07:56:57.353 5: DbLog DbLog -> parsed Event: OG.AN.Rolladen , Event: 4.SECTION: 3
2021.11.16 07:56:57.353 4: DbLog DbLog -> check Device: OG.AN.Rolladen , Event: 4.PROCESS: moving
2021.11.16 07:56:57.353 5: DbLog DbLog -> parsed Event: OG.AN.Rolladen , Event: 4.PROCESS: moving
2021.11.16 07:56:57.353 4: DbLog DbLog -> check Device: OG.AN.Rolladen , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:57.353 5: DbLog DbLog -> parsed Event: OG.AN.Rolladen , Event: 4.ACTIVITY_STATE: 1
2021.11.16 07:56:57.354 5: structure OG.Rolladen: event from OG.AN.Rolladen: setting state to undefined, cause different states: closed,3
2021.11.16 07:56:57.355 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.355 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.356 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.362 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.AN.Rolladen/4.SECTION => 3 (qos: 0, retain: 1
2021.11.16 07:56:57.367 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.AN.Rolladen/4.PROCESS => moving (qos: 0, retain: 1
2021.11.16 07:56:57.372 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.AN.Rolladen/4.ACTIVITY_STATE => 1 (qos: 0, retain: 1
2021.11.16 07:56:57.379 5: End notify loop for OG.AN.Rolladen
2021.11.16 07:56:57.544 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.544 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:57.544 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.544 4: DbLog DbLog -> number of events received: 1 of device: OG.SZ.RolladenL
2021.11.16 07:56:57.544 4: DbLog DbLog -> check Device: OG.SZ.RolladenL , Event: 0.RSSI_PEER: -72
2021.11.16 07:56:57.544 5: DbLog DbLog -> parsed Event: OG.SZ.RolladenL , Event: 0.RSSI_PEER: -72
2021.11.16 07:56:57.544 5: structure OG.SZ.Rolladen: event from OG.SZ.RolladenL: setting state to closed
2021.11.16 07:56:57.545 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.552 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/OG.SZ.RolladenL/0.RSSI_PEER => -72 (qos: 0, retain: 1
2021.11.16 07:56:57.559 5: End notify loop for OG.SZ.RolladenL
2021.11.16 07:56:57.559 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read finished
2021.11.16 07:56:57.560 1: [Freezemon] freezemon: Long function call detected ReadFn:d_rpcHmIP_RF2 - 1.610941 seconds
2021.11.16 07:56:57.560 5: getRequest: Received packet: 0027100c1b0d00804251999a

2021.11.16 07:56:57.560 5: decode_eibd: byte len: 5 array size: 5
2021.11.16 07:56:57.560 5: SimpleRead msg.type: write, msg.src: 0100c, msg.dst: 0330d
2021.11.16 07:56:57.560 5: SimpleRead data: 4251999a
2021.11.16 07:56:57.560 4: SimpleRead: 0100cw0330d4251999a

2021.11.16 07:56:57.560 4: KNXd: C0100cw0330d4251999a
2021.11.16 07:56:57.560 5: KNX_Parse -enter: IO-name: KNXd, dest: 0330d, msg: C0100cw0330d4251999a
2021.11.16 07:56:57.561 4: KNX_Parse -process: IO-name: KNXd, device-name: UG.AZ.Steckdose13, rd-name: power, gadCode: 0330d, cmd: w
2021.11.16 07:56:57.561 5: KNX_decodeByDpt -enter: model: dpt14.056, code: dpt14, value: 4251999a, length-value: 8
2021.11.16 07:56:57.561 5: KNX_limit: DIR: DECODE FACTOR: 1 OFFSET: 0
2021.11.16 07:56:57.561 5: KNX_decodeByDpt -exit: model: dpt14.056, code: dpt14, value: 4251999a, state: 52.400 W
2021.11.16 07:56:57.561 4: KNX_Parse (wp): UG.AZ.Steckdose13, READINGNAME: power, VALUE: 52.400 W, SENDER: 0100c
2021.11.16 07:56:57.561 5: KNX_parse -exit
2021.11.16 07:56:57.717 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.717 4: DbLog DbLog -> ###              start of new Logcycle                       ###
2021.11.16 07:56:57.717 4: DbLog DbLog -> ################################################################
2021.11.16 07:56:57.717 4: DbLog DbLog -> number of events received: 2 of device: UG.AZ.Steckdose13
2021.11.16 07:56:57.717 4: DbLog DbLog -> check Device: UG.AZ.Steckdose13 , Event: power: 52.400 W
2021.11.16 07:56:57.717 5: KNX_DbLog_split -enter: device= UG.AZ.Steckdose13 event= power: 52.400 W
2021.11.16 07:56:57.717 5: KNX_DbLog_split -exit: device= UG.AZ.Steckdose13, reading= power, value= 52.400, unit= W
2021.11.16 07:56:57.717 5: DbLog DbLog -> parsed Event: UG.AZ.Steckdose13 , Event: power: 52.400 W
2021.11.16 07:56:57.717 5: DbLog DbLog -> DbLogInclude of "UG.AZ.Steckdose13": status
2021.11.16 07:56:57.717 4: DbLog DbLog -> check Device: UG.AZ.Steckdose13 , Event: state: 52.400 W
2021.11.16 07:56:57.717 5: KNX_DbLog_split -enter: device= UG.AZ.Steckdose13 event= state: 52.400 W
2021.11.16 07:56:57.717 5: KNX_DbLog_split -exit: device= UG.AZ.Steckdose13, reading= state, value= 52.400, unit= W
2021.11.16 07:56:57.717 5: DbLog DbLog -> parsed Event: UG.AZ.Steckdose13 , Event: state: 52.400 W
2021.11.16 07:56:57.717 5: DbLog DbLog -> DbLogInclude of "UG.AZ.Steckdose13": status
2021.11.16 07:56:57.718 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.719 5: RH_HmIP_UNREACH: not on any display, don't trigger
2021.11.16 07:56:57.726 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/UG.AZ.Steckdose13/power => 52.400 W (qos: 0, retain: 1
2021.11.16 07:56:57.731 5: MQTT_GENERIC_BRIDGE:DEBUG:> [MQTTBridge] publish: services/fhem/UG.AZ.Steckdose13/state => 52.400 W (qos: 0, retain: 1
2021.11.16 07:56:57.733 5: End notify loop for UG.AZ.Steckdose13
2021.11.16 07:56:57.733 5: [Freezemon] freezemon: ----------- Starting Freeze handling at 2021.11.16 07:56:57.733 ---------------------
2021.11.16 07:56:57.733 5: [Freezemon] freezemon logging: fn-ReadFn(d_rpcHmIP_RF2)  in all mode, because d_rpcHmIP_RF2 is not ignored
[Freezemon] freezemon: possible freeze starting at 07:56:56, delay is 1.733 possibly caused by: fn-ReadFn(d_rpcHmIP_RF2)

Zu meinem Setup: Ich benutze FHEM seit 2008 und habe entsprechend viele Devices (ca. 380 echte Geräte, meist HmIP, aber auch MQTT, KNX etc.) Den Großteil der Automationen erledige ich mit DOIFs (101 Stück) und wenigen Notifys/Ats. Alle Events echter Geräte werden per MQTT_GENERIC_BRIDGE an den Broker geschickt. Blockierende Module habe ich auf eigene FHEM-Instanzen verlagert, die über MQTT_GENERIC_BRIDGE angebunden wurden. Das Logging übernimmt DbLog (asynchron). FHEM läuft auf einem performanten Server in Docker-Containern.

Für Hinweise zur weiteren Eingrenzung wäre ich dankbar.

Patrick

KölnSolar · 16 November 2021, 12:32:24

Hallo Patrick,
anhand des freezemon-Logs würd ich spekulieren, dass Du gar keine freezes hast. Freezemon meldet ja nicht wirklich zuverlässig/eindeutig.

Hast Du "echte" freezes durch wie auch immer geartete Verzögerungen beobachten können ? Ist es immer d_rpcHmIP_RF2(oder Ähnliches) oder immer etwas anderes ?

Was ist denn d_rpcHmIP_RF2, dass das dieses Verhalten zeigt:

Zitat2021.11.16 07:56:55.949 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read called
2021.11.16 07:56:55.954 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read stopped after 70 events read: no data
.
.
2021.11.16 07:56:57.559 4: HMCCURPCPROC: [d_rpcHmIP_RF2 : 31583] Read finished
2021.11.16 07:56:57.560 1: [Freezemon] freezemon: Long function call detected ReadFn:d_rpcHmIP_RF2 - 1.610941 seconds

Grüße Markus

PatrickR · 16 November 2021, 17:02:42

Hi!

Zitat von: KölnSolar am 16 November 2021, 12:32:24
anhand des freezemon-Logs würd ich spekulieren, dass Du gar keine freezes hast. Freezemon meldet ja nicht wirklich zuverlässig/eindeutig.

Hast Du "echte" freezes durch wie auch immer geartete Verzögerungen beobachten können ? Ist es immer d_rpcHmIP_RF2(oder Ähnliches) oder immer etwas anderes ?

Die Frage ist halt, was ein echter Freeze ist. Wenn FHEM mit dem Lesen des HMIP-Interfaces bzw. der Ausführung der zugehörigen Events beschäftigt ist, kann es ja nach meinem Verständnis nichts anderes tun. Bei Verzögerungen im Bereich von knapp über einer Sekunde wird es vermutlich schwer, echte Auswirkungen zu sehen. FHEMWEB reagiert bei mir etwas schleppend, aber das tut es eigentlich immer und unabhängig von gemeldeten Freezes.

Zitat von: KölnSolar am 16 November 2021, 12:32:24
Was ist denn d_rpcHmIP_RF2, dass das dieses Verhalten zeigt:

Das ist ein HMCCURPCPROC, d. h. ein RPC-Device für eine HMCCU-Verbindung. Ich habe 4 CCUs in FHEM, d_rpcHmIP_RF2 gehört zur zweiten CCU. Bei dem Interface der ersten CCU tritt das Problem aber auch auf. Ich verstehe das Log so, dass die von Freezemon identifizierte Read-Funktion selbst nicht das Problem ist sondern die nachgelagerte Verarbeitung der durch die Updates erzeugten Events, z. B. durch meine Batterie an DOIFs. Das würde auch erklären, warum das Problem vorher bei UniFi auftrat. Um das näher eingrenzen zu können müsste ich aber vermutlich weitere Logmeldungen reinpatchen.

Patrick

KölnSolar · 16 November 2021, 20:13:23

Zitatsondern die nachgelagerte Verarbeitung der durch die Updates erzeugten Events

Das sehe ich anders. Meines Erachtens machen die events kein Problem. Aber das ist nur Glaube. Ich tappe da ohne das KnowHow von Oli auch immer wieder im Dunkeln.

"Einfach" zu erkennende echte freezes äußern sich im Log durch ein "log skips", so z.B.

Code Auswählen

[Freezemon] freezedetect: possible freeze starting at 14:34:36, delay is 3.166 possibly caused by: no bad guy found :-(
2021.11.16 14:34:35.986 5: UPNPController: RenderingControl: urn:upnp-org:serviceId:RenderingControl found. OK.
--- log skips     3.098 secs.
2021.11.16 14:34:39.084 5: UPNPController: warning: Carp, Subscription request failed with error: 500 Can't connect to 192.168.x.y:4711 (No route to host) at ./FHEM/98_UPNPController.pm line 721.
2021.11.16 14:34:39.167 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2021.11.16 14:34:39.167 ---------------------
[Freezemon] freezedetect: possible freeze starting at 14:34:36, delay is 3.166 possibly caused by: no bad guy found :-(

Komplizierter wird es hier

Code Auswählen

[Freezemon] freezedetect: possible freeze starting at 13:28:12, delay is 0.515 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VL) 
2021.11.16 13:28:11.194 4: Connection accepted from WEB_192.168.x.y_49511
2021.11.16 13:28:11.196 5: HEAD.....
2021.11.16 13:28:11.197 4: WEB_192.168.x.y_49511 HEAD ...
2021.11.16 13:28:11.798 4: WEB: ......
.
. ne Menge events...
.
2021.11.16 13:28:11.844 4: Connection closed for WEB_192.168.x.y_49511: EOF
2021.11.16 13:28:11.845 5: Cmd: >{BlockingStart('266388')}<
2021.11.16 13:28:11.848 5: Cmd: >{GPIO4_GetfinishFn('RPi_OW_WWL|28|0317717e8aff|T: 31.75|31.75')}<
2021.11.16 13:28:11.870 4: Connection accepted from WEB_192.168.x.y_49515
2021.11.16 13:28:11.921 5: HEAD ...
2021.11.16 13:28:11.922 4: WEB_192.168.x.y_49515 HEAD ...
2021.11.16 13:28:12.493 4: WEB: ...

2021.11.16 13:28:12.511 4: BlockingCall (GPIO4_Poll): created child (31182), uses telnetForBlockingFn_1636561047 to connect back
2021.11.16 13:28:12.516 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2021.11.16 13:28:12.515 ---------------------
[Freezemon] freezedetect: possible freeze starting at 13:28:12, delay is 0.515 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VL)

Was hier garantiert keinen freeze erzeugt hat war tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VL). Und ich meine, es müssten sogar 2 freezes gewesen sein(jeweils nach 4: WEB_192.168.x.y_4951x HEAD ...) Den Fall guck ich mir mal genauer an, weil sowohl GPIO4, als auch die http-communication von mir sind.

Und in meinem 3. Beispiel weiß ich überhaupt nicht, wieso freezemon einen freeze annimmt:

Code Auswählen

[Freezemon] freezedetect: possible freeze starting at 17:20:15, delay is 2.368 possibly caused by: tmr-CustomReadings_OnTimer(myReadings) 
2021.11.16 17:20:17.250 5: Triggering act_on_SonneOstoff
.
.
2021.11.16 17:20:17.368 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2021.11.16 17:20:17.368 ---------------------
[Freezemon] freezedetect: possible freeze starting at 17:20:15, delay is 2.368 possibly caused by: tmr-CustomReadings_OnTimer(myReadings)

Hier kann ich nur spekulieren, dass der "Auslöser" vor dem Beginn des freezemon-Logs liegt. act_on_SonneOstoff ist ein notify, welches auf ein myReadings-event(myReadings ist ein CustomReadings-device) reagiert.

Ich hab einfach mal die aktuellen Beispiele von mir gepostet, weil ich zu HMCCU rein gar nichts sagen kann, aber vielleicht die Begründungen zu meinen freezemon-Ausgaben etwas Licht ins Dunkel bringen. $:-\$

Grüße Markus

PatrickR · 16 November 2021, 21:40:20

Hi!

Zitat von: KölnSolar am 16 November 2021, 20:13:23
Das sehe ich anders. Meines Erachtens machen die events kein Problem. Aber das ist nur Glaube. Ich tappe da ohne das KnowHow von Oli auch immer wieder im Dunkeln.

Liest Oli hier mit?
Die Events an sich natürlich nicht aber das Processing, das sie auslösen. Vor allem meine Armada von DOIFs oder meine "globale" MQTT_GENERIC_BRIDGE. Aber ich lasse mich gerne überzeugen. Ich trinke gerne Reissdorf

Zitat von: KölnSolar am 16 November 2021, 20:13:23
Ich hab einfach mal die aktuellen Beispiele von mir gepostet, weil ich zu HMCCU rein gar nichts sagen kann, aber vielleicht die Begründungen zu meinen freezemon-Ausgaben etwas Licht ins Dunkel bringen. $:-\$

HMCCU ist m. E. nicht wirklich das Problem. Vorher war es UniFi, nach dessen Auslagerung hat HMCCU gesponnen. Beiden gemein ist, dass sie einige Events erzeugen.

Patrick

KölnSolar · 16 November 2021, 22:19:50

ZitatIch trinke gerne Reissdorf

Ich auch.

ZitatLiest Oli hier mit?

Eher nicht. Macht sich sehr rar in letzter Zeit.

PatrickR · 21 November 2021, 19:23:42

Hi!

So, habe mal etwas am Logging gepatcht. Das Problem ist, dass Rudi in fhem.pl die Notify-Verarbeitung ziemlich gut optimiert hat und dadurch das Überschreiben von Log3 durch Freezemon nicht mehr greift.

Code Auswählen


# egrep -i '(notify loop| Read )' freeze-20211121-182237.log
2021.11.21 18:22:35.606 5: Starting notify loop for UG.KE.Gaszaehler, 3 event(s), first is state-get: 1150.950
2021.11.21 18:22:35.762 5: Starting notify loop for D_UG.KE.Gaszaehler_watchdog, 1 event(s), first is wait_timer: no timer
2021.11.21 18:22:35.769 5: End notify loop for D_UG.KE.Gaszaehler_watchdog. Time elapsed: 0.01s.
2021.11.21 18:22:35.770 5: Starting notify loop for D_UG.KE.Gaszaehler_watchdog, 1 event(s), first is wait_timer: 22.11.2021 12:22:35 cmd_1_2 UG.KE.Gaszaehler
2021.11.21 18:22:35.777 5: End notify loop for D_UG.KE.Gaszaehler_watchdog. Time elapsed: 0.01s.
2021.11.21 18:22:35.821 5: End notify loop for UG.KE.Gaszaehler. Time elapsed: 0.21s.
2021.11.21 18:22:35.822 5: Starting notify loop for UG.AZ.Steckdosen13bis18, 2 event(s), first is power: 265.800 W
2021.11.21 18:22:35.984 5: End notify loop for UG.AZ.Steckdosen13bis18. Time elapsed: 0.16s.

2021.11.21 18:22:35.984 4: HMCCURPCPROC: [d_rpcHmIP_RF : 35989] Read called
2021.11.21 18:22:35.990 4: HMCCURPCPROC: [d_rpcHmIP_RF : 35989] Read stopped after 70 events read: no data
2021.11.21 18:22:35.997 5: Starting notify loop for EG.WZ.Fussbodenheizung2, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:36.158 5: End notify loop for EG.WZ.Fussbodenheizung2. Time elapsed: 0.16s.
2021.11.21 18:22:36.163 5: Starting notify loop for EG.WC.Fussbodenheizung, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:36.329 5: End notify loop for EG.WC.Fussbodenheizung. Time elapsed: 0.17s.
2021.11.21 18:22:36.333 5: Starting notify loop for EG.KU.Fussbodenheizung, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:36.496 5: End notify loop for EG.KU.Fussbodenheizung. Time elapsed: 0.16s.
2021.11.21 18:22:36.501 5: Starting notify loop for EG.FL.Fussbodenheizung, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:36.661 5: End notify loop for EG.FL.Fussbodenheizung. Time elapsed: 0.16s.
2021.11.21 18:22:36.666 5: Starting notify loop for EG.WZ.Fussbodenheizung1, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:36.828 5: End notify loop for EG.WZ.Fussbodenheizung1. Time elapsed: 0.16s.
2021.11.21 18:22:36.851 5: Starting notify loop for EG.XX.Fussbodenheizung, 1 event(s), first is 0.RSSI_DEVICE: -90
2021.11.21 18:22:37.006 5: Starting notify loop for MQTTBridge, 1 event(s), first is outgoing-count: 30526
2021.11.21 18:22:37.009 5: End notify loop for MQTTBridge. Time elapsed: 0.00s.
2021.11.21 18:22:37.015 5: End notify loop for EG.XX.Fussbodenheizung. Time elapsed: 0.16s.
2021.11.21 18:22:37.016 4: HMCCURPCPROC: [d_rpcHmIP_RF : 35989] Read finished

2021.11.21 18:22:37.017 5: Starting notify loop for UG.AZ.Steckdose13, 2 event(s), first is power: 71.000 W
2021.11.21 18:22:37.177 5: End notify loop for UG.AZ.Steckdose13. Time elapsed: 0.16s.

Ich verstehe das als Bestätigung meiner Theorie, dass die Eventverarbeitung die Zeit frisst, teilweise 160ms pro Event. Somit summiert sich das wie im konkreten Fall dann, wenn mehrere Events gleichzeitig auftreten. Werde mir das mal näher ansehen. Das Problem ist hier, dass das Hinschauen, d. h. der Ausbau des Loggings auch Zeit frisst und ich damit das Verhalten ändere. Ich bin aber guter Dinge, dass ich ohne einen Quantentheoretiker auskomme

Patrick

rudolfkoenig · 21 November 2021, 22:47:12

Wieviele NotifyFn Instanzen (d.h. notify, FileLog, watchdog, DOIF, etc) hast Du?

Code Auswählen

fhem> { grep { $modules{$defs{$_}{TYPE}}{NotifyFn} } keys %defs }

Wie oft Ist NOTIFYDEV gesetzt?

Code Auswählen

fhem> count .*:FILTER=NOTIFYDEV=.+

PatrickR · 22 November 2021, 10:51:18

Hallo Rudi,

Zitat von: rudolfkoenig am 21 November 2021, 22:47:12
Wieviele NotifyFn Instanzen (d.h. notify, FileLog, watchdog, DOIF, etc) hast Du?
Code Auswählen Erweitern
fhem> { grep { $modules{$defs{$_}{TYPE}}{NotifyFn} } keys %defs }

213

Zitat von: rudolfkoenig am 21 November 2021, 22:47:12
Wie oft Ist NOTIFYDEV gesetzt?
Code Auswählen Erweitern
fhem> count .*:FILTER=NOTIFYDEV=.+

162

Hierzu muss man allerdings sagen, dass ich einzelne(!) Geräte mit NotifyFn habe, die trotz NOTIFYDEV sehr breit matchen, u. a. mehrere DOIFs und auch eine MQTT_GENERIC_BRIDGE.

Patrick

rudolfkoenig · 22 November 2021, 12:01:40

Bei diesen Mengen (und einen Rechner, was nicht langsamer ist, als ein RPI 1) sollte das Framework selbst nicht die Ursache sein.

PatrickR · 22 November 2021, 12:12:27

Hi!

Zitat von: rudolfkoenig am 22 November 2021, 12:01:40
Bei diesen Mengen (und einen Rechner, was nicht langsamer ist, als ein RPI 1) sollte das Framework selbst nicht die Ursache sein.

Damit wir uns nicht falsch verstehen: Davon ging ich auch nicht aus sondern vermute eher, dass einzelne Handler zu intensiv über die Events nachdenken. Habe aktuell meinen Debuggingcode in fhem.pl noch einmal erweitert, so dass die Übeltäter bald klar sein sollten.

Patrick

PatrickR · 29 November 2021, 22:07:01

Mahlzeit!

So, mal ein kleines Update für die Mitleser und vielleicht mich selbst, wenn ich mal wieder nach Lösungen für ein ähnliches Problem suche. Ich habe die Ursache identifiziert und behoben. Letztendlich war es ein übermütig gewordenes DOIF.

Um das Problem einzugrenzen und meine Theorie der Ursache in der Eventverarbeitung zu bestätigen habe ich fhem.pl gepatcht:

Code Auswählen


3803c3803
<     if($attr{global}{verbose} >= 5) {
---
>     #if($attr{global}{verbose} >= 5) {
3806c3806,3807
<     }
---
>     #}
>     my $notifyLoopStart = Time::HiRes::gettimeofday();
3811a3813
>       my $notifyLoopCallFnStart = Time::HiRes::gettimeofday();
3812a3815,3816
>       my $notifyLoopTime = Time::HiRes::gettimeofday() - $notifyLoopCallFnStart;
>       Log 5, "Notify loop for $dev: End CallFn of $n. Time elapsed: " . sprintf("%.2fs", $notifyLoopTime) if ($notifyLoopTime > 0.01);
3816c3820,3821
<     Log 5, "End notify loop for $dev";
---
>     my $notifyLoopTime = sprintf("%.2fs", Time::HiRes::gettimeofday() - $notifyLoopStart);
>     Log 5, "End notify loop for $dev. Time elapsed: $notifyLoopTime.";

Das ist kein Patch, der in dieser Form dauerhaft in fhem.pl integriert werden sollte, da er die Eventverarbeitung deutlich teurer macht. Er dient nur temporär der Eingrenzung.

Filtert man das Freeze-Log, sieht man Folgendes:

Code Auswählen


2021.11.23 09:35:58.951 4: HMCCURPCPROC: [d_rpcHmIP_RF : 4993] Read called
2021.11.23 09:35:58.956 4: HMCCURPCPROC: [d_rpcHmIP_RF : 4993] Read stopped after 41 events read: no data
2021.11.23 09:35:58.986 5: Notify loop for EG.WZ.Fussbodenheizung2: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.105 5: Notify loop for EG.WZ.Fussbodenheizung2: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.12s
2021.11.23 09:35:59.120 5: End notify loop for EG.WZ.Fussbodenheizung2. Time elapsed: 0.16s.
2021.11.23 09:35:59.140 5: Notify loop for EG.FL.Fussbodenheizung: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.254 5: Notify loop for EG.FL.Fussbodenheizung: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:35:59.269 5: End notify loop for EG.FL.Fussbodenheizung. Time elapsed: 0.15s.
2021.11.23 09:35:59.298 5: Notify loop for EG.KU.Espressomaschine: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.412 5: Notify loop for EG.KU.Espressomaschine: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:35:59.428 5: End notify loop for EG.KU.Espressomaschine. Time elapsed: 0.15s.
2021.11.23 09:35:59.448 5: Notify loop for EG.WZ.Fussbodenheizung1: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.560 5: Notify loop for EG.WZ.Fussbodenheizung1: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:35:59.578 5: Notify loop for EG.WZ.Fussbodenheizung1: End CallFn of MQTTBridge. Time elapsed: 0.01s
2021.11.23 09:35:59.585 5: End notify loop for EG.WZ.Fussbodenheizung1. Time elapsed: 0.15s.
2021.11.23 09:35:59.606 5: Notify loop for EG.KU.Fussbodenheizung: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.717 5: Notify loop for EG.KU.Fussbodenheizung: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:35:59.731 5: End notify loop for EG.KU.Fussbodenheizung. Time elapsed: 0.14s.
2021.11.23 09:35:59.757 5: Notify loop for EG.XX.Fussbodenheizung: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:35:59.869 5: Notify loop for EG.XX.Fussbodenheizung: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:35:59.883 5: End notify loop for MQTTBridge. Time elapsed: 0.00s.
2021.11.23 09:35:59.883 5: Notify loop for EG.XX.Fussbodenheizung: End CallFn of MQTTBridge. Time elapsed: 0.01s
2021.11.23 09:35:59.890 5: End notify loop for EG.XX.Fussbodenheizung. Time elapsed: 0.15s.
2021.11.23 09:35:59.909 5: Notify loop for EG.WC.Fussbodenheizung: End CallFn of D_R_HMIP_Info. Time elapsed: 0.02s
2021.11.23 09:36:00.021 5: Notify loop for EG.WC.Fussbodenheizung: End CallFn of D_S_HM_HMIP_Problems. Time elapsed: 0.11s
2021.11.23 09:36:00.035 5: End notify loop for EG.WC.Fussbodenheizung. Time elapsed: 0.14s.
2021.11.23 09:36:00.035 4: HMCCURPCPROC: [d_rpcHmIP_RF : 4993] Read finished
2021.11.23 09:36:00.035 1: [Freezemon] freezemon: Long function call detected ReadFn:d_rpcHmIP_RF - 1.083899 seconds
2021.11.23 09:36:00.036 5: [Freezemon] freezemon logging: fn-ReadFn(d_rpcHmIP_RF)  in all mode, because d_rpcHmIP_RF is not ignored
[Freezemon] freezemon: possible freeze starting at 09:35:59, delay is 1.035 possibly caused by: fn-ReadFn(d_rpcHmIP_RF)

Die ReadFn von d_rpcHmIP_RF benötigt also tatsächlich über eine Sekunde, aber sie ist nicht das Problem, da sie nur wenige ms (selbst) arbeitet. Den Rest macht die Verarbeitung der erzeugten Events aus. Den Hauptteil gönnt sich das DOIF D_S_HM_HMIP_Problems, das insgesamt 7 x ca. 110ms frisst. In diesem Fall verrät Freezemon also nicht den tatsächlichen Übeltäter, sondern das übergeordnete Objekt, d. h. fn-ReadFn(d_rpcHmIP_RF).

Alternativ hätte man auch mittels apptime (z. B. apptime total oder apptime count) sehen können, dass D_S_HM_HMIP_Problems oft aufgerufen wird und in Summe viel Verarbeitungszeit benötigt.

Ich hoffe, diese Beschreibung hilft vielleicht dem einen oder anderen bei der Eingrenzung ähnlicher Probleme.

Patrick