FHEM Forum

FHEM => Sonstiges => Thema gestartet von: naimo am 08 Dezember 2016, 14:31:35

Titel: Perfmon "possible freeze" jede Minute
Beitrag von: naimo am 08 Dezember 2016, 14:31:35
Hallo Leute,

nachdem ich mit meinem HMLAN-Adapter einige Probleme hatte (sind durch den 10MBit Half Duplex Trick anscheinend behoben) habe ich mich mit apptime und perfmon ein wenig beschäftigt.

Nun ist mir aufgefallen, dass ich minütlich einen "possible freeze" von 3 Sekunden erhalte. Auffällig ist auch, dass im verbose 5 Log immer

2016.12.08 14:20:02.001 1: Perfmon: possible freeze starting at 14:19:59, delay is 3.001
2016.12.08 14:20:02.004 4: SONOS0: Got correct Answer from Subprocess...


auftritt.

Hier noch ein Log mit 15 Zeilen vor und nach dem Freeze:


2016.12.08 14:08:24 4: Connection closed for WEB_127.0.0.1_60976: EOF
2016.12.08 14:08:24 4: Connection accepted from WEB_127.0.0.1_60978
2016.12.08 14:08:24 4: WEB_127.0.0.1_60978 GET /fhem?cmd={ReadingsVal(%22Harmony%22,%22activity%22,%22%22)}&XHR=1; BUFLEN:0
2016.12.08 14:08:24 5: Cmd: >{ReadingsVal("Harmony","activity","")}<
2016.12.08 14:08:24 4: name: /fhem?cmd={ReadingsVal(%22Harmony%22,%22activity%22,%22%22)}&XHR=1 / RL:29 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:08:24 4: Connection closed for WEB_127.0.0.1_60978: EOF
2016.12.08 14:08:24 4: Connection accepted from WEB_127.0.0.1_60980
2016.12.08 14:08:24 4: WEB_127.0.0.1_60980 GET /fhem?cmd={AttrVal(%22Harmony%22,%22room%22,%22%22)}&XHR=1; BUFLEN:0
2016.12.08 14:08:24 5: Cmd: >{AttrVal("Harmony","room","")}<
2016.12.08 14:08:24 4: name: /fhem?cmd={AttrVal(%22Harmony%22,%22room%22,%22%22)}&XHR=1 / RL:38 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:08:24 4: Connection closed for WEB_127.0.0.1_60980: EOF
2016.12.08 14:08:24 4: Connection accepted from WEB_127.0.0.1_60982
2016.12.08 14:08:24 4: WEB_127.0.0.1_60982 GET /fhem?XHR=1&inform=type=status;filter=Harmony;since=1481202502;fmt=JSON&fw_id=654&timestamp=1481202504291; BUFLEN:0
2016.12.08 14:08:28 1: Perfmon: possible freeze starting at 14:08:26, delay is 2.959
2016.12.08 14:08:28 4: Connection accepted from WEB_127.0.0.1_60986
2016.12.08 14:08:28 4: WEB_127.0.0.1_60986 GET /fhem?room=Mama; BUFLEN:0
2016.12.08 14:08:28 5: Cmd: >get Sonos_Unnamed_RoomRC htmlcode<
2016.12.08 14:08:28 1: PERL WARNING: Redundant argument in sprintf at ./FHEM/00_SONOS.pm line 572.
2016.12.08 14:08:28 4: name: /fhem?room=Mama / RL:11197 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:08:28 4: Connection closed for WEB_127.0.0.1_60986: EOF
2016.12.08 14:08:29 4: Connection closed for WEB_127.0.0.1_60982: EOF
2016.12.08 14:08:29 4: Connection accepted from WEB_127.0.0.1_60990
2016.12.08 14:08:29 4: WEB_127.0.0.1_60990 GET /fhem/pgm2/jquery.min.js; BUFLEN:0
2016.12.08 14:08:29 4: WEB_127.0.0.1_60990 => 304 Not Modified
2016.12.08 14:08:29 4: Connection closed for WEB_127.0.0.1_60990: EOF
2016.12.08 14:08:29 4: Connection accepted from WEB_127.0.0.1_60992
2016.12.08 14:08:29 4: WEB_127.0.0.1_60992 GET /fhem/pgm2/fhemweb_colorpicker.js; BUFLEN:0
2016.12.08 14:08:29 4: WEB_127.0.0.1_60992 => 304 Not Modified
--
2016.12.08 14:09:27 4: Connection accepted from WEB_127.0.0.1_33154
2016.12.08 14:09:27 4: WEB_127.0.0.1_33154 GET /fhem/SVG_showLog?dev=SVG_FileLog_Wz.Thermo1_1&logdev=FileLog_Wz.Thermo1&gplotfile=SVG_FileLog_Wz.Thermo1_1&logfile=CURRENT&pos=; BUFLEN:0
2016.12.08 14:09:27 5: plotcommand: get FileLog_Wz.Thermo1 CURRENT INT 2016-12-08_00:00:00 2016-12-09_00:00:01  4:Wz.Thermo1_Clima.measured-temp\x3a:: 4:Wz.Thermo1_Clima.ValvePosition\x3a:0:int 4:Wz.Thermo1_Clima.desired-temp\x3a::
2016.12.08 14:09:27 5: Cmd: >get FileLog_Wz.Thermo1 CURRENT INT 2016-12-08_00:00:00 2016-12-09_00:00:01 4:Wz.Thermo1_Clima.measured-temp\x3a:: 4:Wz.Thermo1_Clima.ValvePosition\x3a:0:int 4:Wz.Thermo1_Clima.desired-temp\x3a::<
2016.12.08 14:09:27 4: FileLog_Wz.Thermo1 get: Input file ./log/Wz.Thermo1-2016.log, from:2016-12-08_00:00:00  to:2016-12-09_00:00:01
2016.12.08 14:09:27 4: FileLog_Wz.Thermo1 get: line 1, regexp:Wz.Thermo1_Clima.measured-temp\x3a, col:3, output lines:184
2016.12.08 14:09:27 4: FileLog_Wz.Thermo1 get: line 2, regexp:Wz.Thermo1_Clima.ValvePosition\x3a, col:3, output lines:91
2016.12.08 14:09:27 4: FileLog_Wz.Thermo1 get: line 3, regexp:Wz.Thermo1_Clima.desired-temp\x3a, col:3, output lines:2
2016.12.08 14:09:27 5: Cmd: >{ "Wz.Thermo1-2016.log" }<
2016.12.08 14:09:27 5: Cmd: >{ "Wohnzimmer: Min $data{min1}, Max $data{max1}, Last $data{currval1}" }<
2016.12.08 14:09:27 4: name: /fhem/SVG_showLog?dev=SVG_FileLog_Wz.Thermo1_1&logdev=FileLog_Wz.Thermo1&gplotfile=SVG_FileLog_Wz.Thermo1_1&logfile=CURRENT&pos= / RL:3366 / image/svg+xml / Content-Encoding: gzip
/
2016.12.08 14:09:27 4: Connection closed for WEB_127.0.0.1_33154: EOF
2016.12.08 14:09:27 4: Connection accepted from WEB_127.0.0.1_33156
2016.12.08 14:09:27 4: WEB_127.0.0.1_33156 GET /fhem?XHR=1&inform=type=status;filter=room=Wohnzimmer;since=1481202566;fmt=JSON&fw_id=840&timestamp=1481202567557; BUFLEN:0
2016.12.08 14:09:31 1: Perfmon: possible freeze starting at 14:09:29, delay is 2.963
2016.12.08 14:09:31 4: Connection accepted from WEB_127.0.0.1_33160
2016.12.08 14:09:31 4: WEB_127.0.0.1_33160 GET /fhem?detail=MediaPC; BUFLEN:0
2016.12.08 14:09:31 4: name: /fhem?detail=MediaPC / RL:4255 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:09:31 4: Connection closed for WEB_127.0.0.1_33160: EOF
2016.12.08 14:09:32 4: Connection accepted from WEB_127.0.0.1_33164
2016.12.08 14:09:32 4: WEB_127.0.0.1_33164 GET /fhem/pgm2/jquery-ui.min.js; BUFLEN:0
2016.12.08 14:09:32 4: WEB_127.0.0.1_33164 => 304 Not Modified
2016.12.08 14:09:32 4: Connection closed for WEB_127.0.0.1_33164: EOF
2016.12.08 14:09:32 4: Connection accepted from WEB_127.0.0.1_33166
2016.12.08 14:09:32 4: WEB_127.0.0.1_33166 GET /fhem/pgm2/fhemweb_fbcalllist.js; BUFLEN:0
2016.12.08 14:09:32 4: WEB_127.0.0.1_33166 => 304 Not Modified
2016.12.08 14:09:32 4: Connection closed for WEB_127.0.0.1_33166: EOF
2016.12.08 14:09:32 4: Connection accepted from WEB_127.0.0.1_33168
2016.12.08 14:09:32 4: WEB_127.0.0.1_33168 GET /fhem/pgm2/ios7Common.css; BUFLEN:0
--
2016.12.08 14:10:30 4: WEB_127.0.0.1_33602 GET /fhem?cmd={AttrVal(%22Kueche.Thermo1_Clima%22,%22room%22,%22%22)}&XHR=1; BUFLEN:0
2016.12.08 14:10:30 5: Cmd: >{AttrVal("Kueche.Thermo1_Clima","room","")}<
2016.12.08 14:10:30 4: name: /fhem?cmd={AttrVal(%22Kueche.Thermo1_Clima%22,%22room%22,%22%22)}&XHR=1 / RL:27 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:10:30 4: Connection closed for WEB_127.0.0.1_33602: EOF
2016.12.08 14:10:30 4: Connection accepted from WEB_127.0.0.1_33604
2016.12.08 14:10:30 4: WEB_127.0.0.1_33604 GET /fhem?XHR=1&inform=type=status;filter=Kueche.Thermo1_Clima;since=1481202629;fmt=JSON&fw_id=1045&timestamp=1481202630759; BUFLEN:0
2016.12.08 14:10:31 4: Connection accepted from WEB_127.0.0.1_33606
2016.12.08 14:10:31 4: WEB_127.0.0.1_33606 POST /fhem?cmd=save&XHR=1&fw_id=1045; BUFLEN:0
2016.12.08 14:10:31 5: Cmd: >save<
2016.12.08 14:10:31 5: Triggering global (1 changes)
2016.12.08 14:10:31 5: Starting notify loop for global, 1 event(s), first is SAVE
2016.12.08 14:10:31 4: name: /fhem?cmd=save&XHR=1&fw_id=1045 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:10:31 4: Connection closed for WEB_127.0.0.1_33606: EOF
2016.12.08 14:10:34 1: Perfmon: possible freeze starting at 14:10:32, delay is 2.967
2016.12.08 14:10:34 4: Connection accepted from WEB_127.0.0.1_33610
2016.12.08 14:10:34 4: WEB_127.0.0.1_33610 GET /fhem?cmd=style%20list; BUFLEN:0
2016.12.08 14:10:34 4: name: /fhem?cmd=style%20list / RL:3145 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:10:34 4: Connection closed for WEB_127.0.0.1_33610: EOF
2016.12.08 14:10:35 4: Connection closed for WEB_127.0.0.1_33604: EOF
2016.12.08 14:10:35 4: Connection accepted from WEB_127.0.0.1_33614
2016.12.08 14:10:35 4: WEB_127.0.0.1_33614 GET /fhem/pgm2/jquery.min.js; BUFLEN:0
2016.12.08 14:10:35 4: WEB_127.0.0.1_33614 => 304 Not Modified
2016.12.08 14:10:35 4: Connection accepted from WEB_127.0.0.1_33616
2016.12.08 14:10:35 4: Connection closed for WEB_127.0.0.1_33614: EOF
2016.12.08 14:10:35 4: WEB_127.0.0.1_33616 GET /fhem/pgm2/jquery-ui.min.js; BUFLEN:0
2016.12.08 14:10:35 4: WEB_127.0.0.1_33616 => 304 Not Modified
2016.12.08 14:10:35 4: Connection closed for WEB_127.0.0.1_33616: EOF
2016.12.08 14:10:35 4: Connection accepted from WEB_127.0.0.1_33618
--
2016.12.08 14:11:34 4: Connection closed for WEB_127.0.0.1_34034: EOF
2016.12.08 14:11:34 4: Connection closed for WEB_127.0.0.1_34036: EOF
2016.12.08 14:11:34 4: WEB_127.0.0.1_34038 GET /fhem/pgm2/fhemweb_fbcalllist.js; BUFLEN:0
2016.12.08 14:11:34 4: WEB_127.0.0.1_34038 => 304 Not Modified
2016.12.08 14:11:34 4: Connection accepted from WEB_127.0.0.1_34040
2016.12.08 14:11:34 4: WEB_127.0.0.1_34040 GET /fhem/pgm2/jquery.min.js; BUFLEN:0
2016.12.08 14:11:34 4: WEB_127.0.0.1_34040 => 304 Not Modified
2016.12.08 14:11:34 4: Connection closed for WEB_127.0.0.1_34038: EOF
2016.12.08 14:11:34 4: Connection closed for WEB_127.0.0.1_34040: EOF
2016.12.08 14:11:34 4: Connection accepted from WEB_127.0.0.1_34042
2016.12.08 14:11:34 4: WEB_127.0.0.1_34042 GET /fhem/pgm2/fhemweb_knob.js; BUFLEN:0
2016.12.08 14:11:34 4: WEB_127.0.0.1_34042 => 304 Not Modified
2016.12.08 14:11:34 4: Connection closed for WEB_127.0.0.1_34042: EOF
2016.12.08 14:11:34 4: Connection accepted from WEB_127.0.0.1_34044
2016.12.08 14:11:37 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:11:37 1: Perfmon: possible freeze starting at 14:11:35, delay is 2.967
2016.12.08 14:11:37 4: WEB_127.0.0.1_34044 GET /fhem/pgm2/fhemweb_readingsGroup.js; BUFLEN:0
2016.12.08 14:11:37 4: WEB_127.0.0.1_34044 => 304 Not Modified
2016.12.08 14:11:37 5: HMLAN/RAW: /E3DDEAD,0000,0193329C,FF,FFB9,6684103DDEAD26ED8706012900

2016.12.08 14:11:37 5: HMLAN_Parse: HMLAN1 R:E3DDEAD   stat:0000 t:0193329C d:FF r:FFB9     m:66 8410 3DDEAD 26ED87 06012900
2016.12.08 14:11:37 5: HMLAN1: dispatch A0D6684103DDEAD26ED8706012900::-71:HMLAN1
2016.12.08 14:11:37 4: Connection accepted from WEB_127.0.0.1_34046
2016.12.08 14:11:37 4: Connection closed for WEB_127.0.0.1_34044: EOF
2016.12.08 14:11:37 4: WEB_127.0.0.1_34046 GET /fhem/pgm2/fhemweb_sortable.js; BUFLEN:0
2016.12.08 14:11:37 4: WEB_127.0.0.1_34046 => 304 Not Modified
2016.12.08 14:11:37 4: Connection accepted from WEB_127.0.0.1_34048
2016.12.08 14:11:37 4: Connection accepted from WEB_127.0.0.1_34052
2016.12.08 14:11:37 4: WEB_127.0.0.1_34048 GET /fhem/pgm2/fhemweb_readingsHistory.js; BUFLEN:0
2016.12.08 14:11:37 4: WEB_127.0.0.1_34048 => 304 Not Modified
2016.12.08 14:11:37 4: Connection closed for WEB_127.0.0.1_34046: EOF
--
2016.12.08 14:12:09 4: parse status message for HUEDevice7
2016.12.08 14:12:09 4: parse status message for HUEDevice5
2016.12.08 14:12:17 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:12:17 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,0193CF34,0009,02

2016.12.08 14:12:17 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:0193CF34 IDcnt:0009 L:2 %
2016.12.08 14:12:17 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:12:17 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:12:22 4: HarmonyMama: send: <iq type='get' id='ping-27'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:12:22 4: Harmony: send: <iq type='get' id='ping-28'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:12:22 5: HarmonyMama: tag: iq, attr:  id='ping-27' type='result'
2016.12.08 14:12:22 5: HarmonyMama: got ping response 27
2016.12.08 14:12:22 5: Harmony: tag: iq, attr:  id='ping-28' type='result'
2016.12.08 14:12:22 5: Harmony: got ping response 28
2016.12.08 14:12:40 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:12:40 1: Perfmon: possible freeze starting at 14:12:38, delay is 2.975
2016.12.08 14:12:42 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:12:42 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,019430E1,0009,02

2016.12.08 14:12:42 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:019430E1 IDcnt:0009 L:2 %
2016.12.08 14:12:42 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:12:42 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:12:52 4: Connection accepted from WEB_127.0.0.1_34152
2016.12.08 14:12:52 4: WEB_127.0.0.1_34152 GET /fhem?room=Residents; BUFLEN:0
2016.12.08 14:12:52 5: GEOFANCY geofancy: called function GEOFANCY_Set()
2016.12.08 14:12:52 4: name: /fhem?room=Residents / RL:3407 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:12:52 4: Connection closed for WEB_127.0.0.1_34152: EOF
2016.12.08 14:12:52 4: Connection closed for WEB_127.0.0.1_34100: EOF
2016.12.08 14:12:52 4: Connection accepted from WEB_127.0.0.1_34154
2016.12.08 14:12:52 4: WEB_127.0.0.1_34154 GET /fhem/pgm2/jquery-ui.min.js; BUFLEN:0
--
2016.12.08 14:13:40 4: WEB_127.0.0.1_34834 => 304 Not Modified
2016.12.08 14:13:40 4: Connection closed for WEB_127.0.0.1_34834: EOF
2016.12.08 14:13:40 4: Connection accepted from WEB_127.0.0.1_34836
2016.12.08 14:13:40 4: WEB_127.0.0.1_34836 GET /fhem/pgm2/dashboard_ios7.css; BUFLEN:0
2016.12.08 14:13:40 4: WEB_127.0.0.1_34836 => 304 Not Modified
2016.12.08 14:13:40 4: Connection closed for WEB_127.0.0.1_34836: EOF
2016.12.08 14:13:40 4: Connection accepted from WEB_127.0.0.1_34838
2016.12.08 14:13:40 4: WEB_127.0.0.1_34838 GET /fhem/codemirror/fhem_codemirror.js; BUFLEN:0
2016.12.08 14:13:40 4: WEB_127.0.0.1_34838 => 304 Not Modified
2016.12.08 14:13:40 4: Connection closed for WEB_127.0.0.1_34838: EOF
2016.12.08 14:13:40 4: Connection accepted from WEB_127.0.0.1_34840
2016.12.08 14:13:40 4: WEB_127.0.0.1_34840 GET /fhem/images/default/icoEverything.png; BUFLEN:0
2016.12.08 14:13:40 4: WEB_127.0.0.1_34840 => 304 Not Modified
2016.12.08 14:13:40 4: Connection closed for WEB_127.0.0.1_34840: EOF
2016.12.08 14:13:43 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:13:43 1: Perfmon: possible freeze starting at 14:13:41, delay is 2.979
2016.12.08 14:13:43 4: Connection accepted from WEB_127.0.0.1_34844
2016.12.08 14:13:43 4: WEB_127.0.0.1_34844 GET /fhem?cmd={ReadingsVal(%22Kalender_Muellabfuhr%22,%22reload%22,%22%22)}&XHR=1; BUFLEN:0
2016.12.08 14:13:43 5: Cmd: >{ReadingsVal("Kalender_Muellabfuhr","reload","")}<
2016.12.08 14:13:43 4: name: /fhem?cmd={ReadingsVal(%22Kalender_Muellabfuhr%22,%22reload%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:13:43 4: Connection accepted from WEB_127.0.0.1_34846
2016.12.08 14:13:43 4: WEB_127.0.0.1_34846 GET /fhem?cmd={AttrVal(%22Kalender_Muellabfuhr%22,%22room%22,%22%22)}&XHR=1; BUFLEN:0
2016.12.08 14:13:43 5: Cmd: >{AttrVal("Kalender_Muellabfuhr","room","")}<
2016.12.08 14:13:43 4: name: /fhem?cmd={AttrVal(%22Kalender_Muellabfuhr%22,%22room%22,%22%22)}&XHR=1 / RL:32 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:13:43 4: Connection accepted from WEB_127.0.0.1_34848
2016.12.08 14:13:43 4: Connection closed for WEB_127.0.0.1_34844: EOF
2016.12.08 14:13:43 4: WEB_127.0.0.1_34848 GET /fhem?XHR=1&inform=type=status;filter=Kalender_Muellabfuhr;since=1481202819;fmt=JSON&fw_id=1603&timestamp=1481202821072; BUFLEN:0
2016.12.08 14:13:43 4: Connection closed for WEB_127.0.0.1_34846: EOF
2016.12.08 14:13:48 4: Connection accepted from WEB_127.0.0.1_34852
--
2016.12.08 14:14:22 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:14:22 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,0195B796,0009,02

2016.12.08 14:14:22 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:0195B796 IDcnt:0009 L:2 %
2016.12.08 14:14:22 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:14:22 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:14:39 5: HMLAN/RAW: /E33BBC1,0000,0195F9D9,FF,FFC8,F3841033BBC126ED8706012300

2016.12.08 14:14:39 5: HMLAN_Parse: HMLAN1 R:E33BBC1   stat:0000 t:0195F9D9 d:FF r:FFC8     m:F3 8410 33BBC1 26ED87 06012300
2016.12.08 14:14:39 5: HMLAN1: dispatch A0DF3841033BBC126ED8706012300::-56:HMLAN1
2016.12.08 14:14:39 5: Triggering Gang.Bewegungsmelder (3 changes)
2016.12.08 14:14:39 5: Starting notify loop for Gang.Bewegungsmelder, 3 event(s), first is battery: ok
2016.12.08 14:14:39 5: Triggering rg_battery (1 changes)
2016.12.08 14:14:39 5: Starting notify loop for rg_battery, 1 event(s), first is Gang.Bewegungsmelder.battery: <html><svg class="icon measure_battery_100 green" data-txt="100"    xmlns:dc="http://purl.org/dc/elements/1.1/"    xmlns:cc="http://creativecommons.org/ns#"    xmlns:rdf="http://www.w3.org/1999/02/22-rdf-syntax-ns#"    xmlns:svg="http://www.w3.org/2000/svg"    xmlns="http://www.w3.org/2000/svg"    xmlns:sodipodi="http://sodipodi.sourceforge.net/DTD/sodipodi-0.dtd"    xmlns:inkscape="http://www.inkscape.org/namespaces/inkscape"    version="1.1"    x="0px"    y="0px"    width="361px"    height="361px"    viewBox="0 0 361 361"    style="enable-background:new 0 0 361 361;"    xml:space="preserve"    id="svg2"    inkscape:version="0.48.5 r10040"    sodipodi:docname="measure_battery_100.svg"><metadata    id="metadata36"><rdf:RDF><cc:Work        rdf:about=""><dc:format>image/svg+xml</dc:format><dc:type          rdf:resource="http://purl.org/dc/dcmitype/StillImage" /><dc:title></dc:title></cc:Work></rdf:RDF></metadata><defs    id="defs34" /><sodipodi:namedview    pagecolor="#ffffff"    bordercolor="#666666"    borderopacity="1"    objecttolerance="10"    gridtolerance="10"    guidetolerance="10"    inkscape:pageopacity="0"    inkscape:pageshadow="2"    inkscape:window-width="779"    inkscape:window-height="480"    id="namedview32"    showgrid="false"    inkscape:zoom="0.65373961"    inkscape:cx="180.5"    inkscape:cy="180.5"    inkscape:window-x="0"    inkscape:window-y="0"    inkscape:window-maximized="0"    inkscape:current-layer="svg2" /> <g    id="measure_x5F_battery_x5F_100"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> \t<g    id="g5"    style="stroke:#000000;stroke-opacity:1"> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 134.65625,89.15625 c -6.01649,0 -11,4.983509 -11,11 l 0,180 c 0,6.01649 4.98351,11 11,11 l 95.5,0 c 6.01631,0 11,-4.9825 11,-11 l 0,-180 c 0,-6.016491 -4.98351,-11 -11,-11 l -95.5,0 z m 0,10 95.5,0 c 0.60951,0 1,0.390491 1,1 l 0,180 c 0,0.6085 -0.39231,1 -1,1 l -95.5,0 c -0.60951,0 -1,-0.39049 -1,-1 l 0,-180 c 0,-0.609509 0.39049,-1 1,-1 z"    id="path7"    inkscape:connector-curvature="0" /> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 169.625,69.65625 c -6.01649,0 -11,4.983509 -11,11 l 0,14 10,0 0,-14 c 0,-0.609509 0.39049,-1 1,-1 l 25.5,0 c 0.60951,0 1,0.390491 1,1 l 0,14 10,0 0,-14 c 0,-6.016491 -4.98351,-11 -11,-11 l -25.5,0 z"    id="path9"    inkscape:connector-curvature="0" /> \t</g> \t<g    style="stroke:#000000;stroke-opacity:1;display:none"    id="g11"> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path13"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path15"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path17"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path19"    inkscape:connector-curvature="0" /> \t</g> \t<g    id="g21"    style="fill:green;fill-opacity:1;stroke:none"> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path23"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path25"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path27"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path29"    inkscape:connector-curvature="0" /> \t</g> </g> <g    id="Ebene_1"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> </g> </svg></html>
2016.12.08 14:14:46 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:14:46 1: Perfmon: possible freeze starting at 14:14:44, delay is 2.987
2016.12.08 14:14:47 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:14:47 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,01961943,0009,02

2016.12.08 14:14:47 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:01961943 IDcnt:0009 L:2 %
2016.12.08 14:14:47 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:14:47 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:14:52 4: HarmonyMama: send: <iq type='get' id='ping-33'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:14:52 4: Harmony: send: <iq type='get' id='ping-34'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:14:52 5: HarmonyMama: tag: iq, attr:  id='ping-33' type='result'
2016.12.08 14:14:52 5: HarmonyMama: got ping response 33
2016.12.08 14:14:52 5: Harmony: tag: iq, attr:  id='ping-34' type='result'
2016.12.08 14:14:52 5: Harmony: got ping response 34
2016.12.08 14:15:03 4: Connection accepted from WEB_127.0.0.1_35012
2016.12.08 14:15:03 4: WEB_127.0.0.1_35012 GET /fhem?room=K%c3%bcche; BUFLEN:0
2016.12.08 14:15:03 4: name: /fhem?room=K%c3%bcche / RL:2049 / text/html; charset=UTF-8 / Content-Encoding: gzip
--
2016.12.08 14:15:42 5: Harmony: tag: iq, attr:  id='ping-36' type='result'
2016.12.08 14:15:42 5: Harmony: got ping response 36
2016.12.08 14:15:46 5: HMLAN/RAW: /E30961D,0000,0196FE28,FF,FF9D,CB861030961D0000000ABD0A0B0000

2016.12.08 14:15:46 5: HMLAN_Parse: HMLAN1 R:E30961D   stat:0000 t:0196FE28 d:FF r:FF9D     m:CB 8610 30961D 000000 0ABD0A0B0000
2016.12.08 14:15:46 5: HMLAN1: dispatch A0FCB861030961D0000000ABD0A0B0000::-99:HMLAN1
2016.12.08 14:15:46 5: Triggering HM_30961D_Weather (2 changes)
2016.12.08 14:15:46 5: Starting notify loop for HM_30961D_Weather, 2 event(s), first is measured-temp: 26.6
2016.12.08 14:15:46 5: Triggering Wz.Thermo1 (6 changes)
2016.12.08 14:15:46 5: Starting notify loop for Wz.Thermo1, 6 event(s), first is actuator: 0
2016.12.08 14:15:46 5: Triggering rg_battery (1 changes)
2016.12.08 14:15:46 5: Starting notify loop for rg_battery, 1 event(s), first is Wz.Thermo1.battery: <html><svg class="icon measure_battery_100 green" data-txt="100"    xmlns:dc="http://purl.org/dc/elements/1.1/"    xmlns:cc="http://creativecommons.org/ns#"    xmlns:rdf="http://www.w3.org/1999/02/22-rdf-syntax-ns#"    xmlns:svg="http://www.w3.org/2000/svg"    xmlns="http://www.w3.org/2000/svg"    xmlns:sodipodi="http://sodipodi.sourceforge.net/DTD/sodipodi-0.dtd"    xmlns:inkscape="http://www.inkscape.org/namespaces/inkscape"    version="1.1"    x="0px"    y="0px"    width="361px"    height="361px"    viewBox="0 0 361 361"    style="enable-background:new 0 0 361 361;"    xml:space="preserve"    id="svg2"    inkscape:version="0.48.5 r10040"    sodipodi:docname="measure_battery_100.svg"><metadata    id="metadata36"><rdf:RDF><cc:Work        rdf:about=""><dc:format>image/svg+xml</dc:format><dc:type          rdf:resource="http://purl.org/dc/dcmitype/StillImage" /><dc:title></dc:title></cc:Work></rdf:RDF></metadata><defs    id="defs34" /><sodipodi:namedview    pagecolor="#ffffff"    bordercolor="#666666"    borderopacity="1"    objecttolerance="10"    gridtolerance="10"    guidetolerance="10"    inkscape:pageopacity="0"    inkscape:pageshadow="2"    inkscape:window-width="779"    inkscape:window-height="480"    id="namedview32"    showgrid="false"    inkscape:zoom="0.65373961"    inkscape:cx="180.5"    inkscape:cy="180.5"    inkscape:window-x="0"    inkscape:window-y="0"    inkscape:window-maximized="0"    inkscape:current-layer="svg2" /> <g    id="measure_x5F_battery_x5F_100"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> \t<g    id="g5"    style="stroke:#000000;stroke-opacity:1"> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 134.65625,89.15625 c -6.01649,0 -11,4.983509 -11,11 l 0,180 c 0,6.01649 4.98351,11 11,11 l 95.5,0 c 6.01631,0 11,-4.9825 11,-11 l 0,-180 c 0,-6.016491 -4.98351,-11 -11,-11 l -95.5,0 z m 0,10 95.5,0 c 0.60951,0 1,0.390491 1,1 l 0,180 c 0,0.6085 -0.39231,1 -1,1 l -95.5,0 c -0.60951,0 -1,-0.39049 -1,-1 l 0,-180 c 0,-0.609509 0.39049,-1 1,-1 z"    id="path7"    inkscape:connector-curvature="0" /> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 169.625,69.65625 c -6.01649,0 -11,4.983509 -11,11 l 0,14 10,0 0,-14 c 0,-0.609509 0.39049,-1 1,-1 l 25.5,0 c 0.60951,0 1,0.390491 1,1 l 0,14 10,0 0,-14 c 0,-6.016491 -4.98351,-11 -11,-11 l -25.5,0 z"    id="path9"    inkscape:connector-curvature="0" /> \t</g> \t<g    style="stroke:#000000;stroke-opacity:1;display:none"    id="g11"> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path13"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path15"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path17"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path19"    inkscape:connector-curvature="0" /> \t</g> \t<g    id="g21"    style="fill:green;fill-opacity:1;stroke:none"> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path23"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path25"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path27"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path29"    inkscape:connector-curvature="0" /> \t</g> </g> <g    id="Ebene_1"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> </g> </svg></html>
2016.12.08 14:15:46 5: Triggering rg_battery (1 changes)
2016.12.08 14:15:46 5: Starting notify loop for rg_battery, 1 event(s), first is Wz.Thermo1.batteryLevel: <html><svg class="icon measure_battery_100 green" data-txt="100"    xmlns:dc="http://purl.org/dc/elements/1.1/"    xmlns:cc="http://creativecommons.org/ns#"    xmlns:rdf="http://www.w3.org/1999/02/22-rdf-syntax-ns#"    xmlns:svg="http://www.w3.org/2000/svg"    xmlns="http://www.w3.org/2000/svg"    xmlns:sodipodi="http://sodipodi.sourceforge.net/DTD/sodipodi-0.dtd"    xmlns:inkscape="http://www.inkscape.org/namespaces/inkscape"    version="1.1"    x="0px"    y="0px"    width="361px"    height="361px"    viewBox="0 0 361 361"    style="enable-background:new 0 0 361 361;"    xml:space="preserve"    id="svg2"    inkscape:version="0.48.5 r10040"    sodipodi:docname="measure_battery_100.svg"><metadata    id="metadata36"><rdf:RDF><cc:Work        rdf:about=""><dc:format>image/svg+xml</dc:format><dc:type          rdf:resource="http://purl.org/dc/dcmitype/StillImage" /><dc:title></dc:title></cc:Work></rdf:RDF></metadata><defs    id="defs34" /><sodipodi:namedview    pagecolor="#ffffff"    bordercolor="#666666"    borderopacity="1"    objecttolerance="10"    gridtolerance="10"    guidetolerance="10"    inkscape:pageopacity="0"    inkscape:pageshadow="2"    inkscape:window-width="779"    inkscape:window-height="480"    id="namedview32"    showgrid="false"    inkscape:zoom="0.65373961"    inkscape:cx="180.5"    inkscape:cy="180.5"    inkscape:window-x="0"    inkscape:window-y="0"    inkscape:window-maximized="0"    inkscape:current-layer="svg2" /> <g    id="measure_x5F_battery_x5F_100"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> \t<g    id="g5"    style="stroke:#000000;stroke-opacity:1"> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 134.65625,89.15625 c -6.01649,0 -11,4.983509 -11,11 l 0,180 c 0,6.01649 4.98351,11 11,11 l 95.5,0 c 6.01631,0 11,-4.9825 11,-11 l 0,-180 c 0,-6.016491 -4.98351,-11 -11,-11 l -95.5,0 z m 0,10 95.5,0 c 0.60951,0 1,0.390491 1,1 l 0,180 c 0,0.6085 -0.39231,1 -1,1 l -95.5,0 c -0.60951,0 -1,-0.39049 -1,-1 l 0,-180 c 0,-0.609509 0.39049,-1 1,-1 z"    id="path7"    inkscape:connector-curvature="0" /> \t\t<path    style="font-size:medium;font-style:normal;font-variant:normal;font-weight:normal;font-stretch:normal;text-indent:0;text-align:start;text-decoration:none;line-height:normal;letter-spacing:normal;word-spacing:normal;text-transform:none;direction:ltr;block-progression:tb;writing-mode:lr-tb;text-anchor:start;baseline-shift:baseline;color:#000000;fill:green;fill-opacity:1;stroke:none;stroke-width:10;marker:none;visibility:visible;display:inline;overflow:visible;enable-background:accumulate;font-family:Sans;-inkscape-font-specification:Sans"    d="m 169.625,69.65625 c -6.01649,0 -11,4.983509 -11,11 l 0,14 10,0 0,-14 c 0,-0.609509 0.39049,-1 1,-1 l 25.5,0 c 0.60951,0 1,0.390491 1,1 l 0,14 10,0 0,-14 c 0,-6.016491 -4.98351,-11 -11,-11 l -25.5,0 z"    id="path9"    inkscape:connector-curvature="0" /> \t</g> \t<g    style="stroke:#000000;stroke-opacity:1;display:none"    id="g11"> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path13"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path15"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path17"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:none;stroke:#000000;stroke-width:10;stroke-opacity:1;display:inline"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path19"    inkscape:connector-curvature="0" /> \t</g> \t<g    id="g21"    style="fill:green;fill-opacity:1;stroke:none"> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,266.334 c 0,3.313 -2.688,6 -6,6 h -65.5 c -3.313,0 -6,-2.688 -6,-6 v -6 c 0,-3.314 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.686 6,6 v 26 z"    id="path23"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,166.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path25"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,120 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -26 c 0,-3.313 2.687,-6 6,-6 h 65.5 c 3.313,0 6,2.687 6,6 v 6 z"    id="path27"    inkscape:connector-curvature="0" /> \t\t<path    style="fill:green;fill-opacity:1;stroke:none"    d="m 221.141,213.667 c 0,3.313 -2.688,6 -6,6 l -65.5,20 c -3.313,0 -6,-2.687 -6,-6 v -20 c 0,-3.313 2.687,-6 6,-6 l 65.5,-20 c 3.313,0 6,2.687 6,6 v 20 z"    id="path29"    inkscape:connector-curvature="0" /> \t</g> </g> <g    id="Ebene_1"    style="stroke:#000000;stroke-opacity:1"    transform="matrix(1.6146267,0,0,1.6146267,-112.50812,-110.12429)"> </g> </svg></html>
2016.12.08 14:15:49 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:15:49 1: Perfmon: possible freeze starting at 14:15:47, delay is 2.995
2016.12.08 14:16:02 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:16:02 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,01973E4C,0009,02

2016.12.08 14:16:02 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:01973E4C IDcnt:0009 L:2 %
2016.12.08 14:16:02 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:16:02 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:16:09 4: using HUEBridge_HTTP_Request: GET lights
2016.12.08 14:16:09 5: HUEBridge_HTTP_Request http://192.168.11.55/api/ed9c2c9eab2bf78561ca3ca0da9aab18/lights: Got data, length: 1466
2016.12.08 14:16:09 4: parse status message for HUEDevice4
2016.12.08 14:16:09 4: parse status message for HUEDevice2
2016.12.08 14:16:09 4: parse status message for HUEDevice5
2016.12.08 14:16:09 4: parse status message for HUEDevice7
2016.12.08 14:16:09 4: parse status message for HUEDevice6
2016.12.08 14:16:17 4: Connection accepted from WEB_127.0.0.1_35204
2016.12.08 14:16:17 4: WEB_127.0.0.1_35204 GET /fhem?room=System; BUFLEN:0
--
2016.12.08 14:16:30 5: SW: 446f576f726b3a534f4e4f533a53617665426f6f6b6d61726b733a0d0a
2016.12.08 14:16:30 4: name: /fhem?cmd=save&XHR=1&fw_id=1793 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:16:30 4: Connection closed for WEB_127.0.0.1_35336: EOF
2016.12.08 14:16:32 4: HarmonyMama: send: <iq type='get' id='ping-37'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:16:32 4: Harmony: send: <iq type='get' id='ping-38'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:16:32 5: HarmonyMama: tag: iq, attr:  id='ping-37' type='result'
2016.12.08 14:16:32 5: HarmonyMama: got ping response 37
2016.12.08 14:16:32 5: Harmony: tag: iq, attr:  id='ping-38' type='result'
2016.12.08 14:16:32 5: Harmony: got ping response 38
2016.12.08 14:16:46 5: HMLAN/RAW: /E3DDEAD,0000,0197E9E0,FF,FFB9,6784103DDEAD26ED8706012800

2016.12.08 14:16:46 5: HMLAN_Parse: HMLAN1 R:E3DDEAD   stat:0000 t:0197E9E0 d:FF r:FFB9     m:67 8410 3DDEAD 26ED87 06012800
2016.12.08 14:16:46 5: HMLAN1: dispatch A0D6784103DDEAD26ED8706012800::-71:HMLAN1
2016.12.08 14:16:53 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:16:53 1: Perfmon: possible freeze starting at 14:16:50, delay is 3.003
2016.12.08 14:16:53 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:16:53 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,019802EE,0009,02

2016.12.08 14:16:53 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:019802EE IDcnt:0009 L:2 %
2016.12.08 14:16:53 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:16:53 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:17:06 4: rpiPing: dummy rpiPing aktuell
2016.12.08 14:17:06 5: Triggering rpiPing (1 changes)
2016.12.08 14:17:06 5: Starting notify loop for rpiPing, 1 event(s), first is aktuell
2016.12.08 14:17:06 4: rpiPing_at: at rpiPing_at Next: 14:20:06
2016.12.08 14:17:06 5: Triggering rpiPing_at (1 changes)
2016.12.08 14:17:06 5: Starting notify loop for rpiPing_at, 1 event(s), first is Next: 14:20:06
2016.12.08 14:17:09 4: using HUEBridge_HTTP_Request: GET lights
2016.12.08 14:17:09 5: HUEBridge_HTTP_Request http://192.168.11.55/api/ed9c2c9eab2bf78561ca3ca0da9aab18/lights: Got data, length: 1466
2016.12.08 14:17:09 4: parse status message for HUEDevice5
--
2016.12.08 14:17:23 5: Starting notify loop for HM_4B6BF9_SenU, 1 event(s), first is 230.5
2016.12.08 14:17:43 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:17:43 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,0198C644,0009,02

2016.12.08 14:17:43 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:0198C644 IDcnt:0009 L:2 %
2016.12.08 14:17:43 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:17:43 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:17:46 5: HMLAN/RAW: /E30961D,0000,0198D2FB,FF,FFA9,CC861030961D0000000ABD0A0B0000

2016.12.08 14:17:46 5: HMLAN_Parse: HMLAN1 R:E30961D   stat:0000 t:0198D2FB d:FF r:FFA9     m:CC 8610 30961D 000000 0ABD0A0B0000
2016.12.08 14:17:46 5: HMLAN1: dispatch A0FCC861030961D0000000ABD0A0B0000::-87:HMLAN1
2016.12.08 14:17:46 5: Triggering HM_30961D_Weather (2 changes)
2016.12.08 14:17:46 5: Starting notify loop for HM_30961D_Weather, 2 event(s), first is measured-temp: 26.6
2016.12.08 14:17:46 5: Triggering Wz.Thermo1 (6 changes)
2016.12.08 14:17:46 5: Starting notify loop for Wz.Thermo1, 6 event(s), first is actuator: 0
2016.12.08 14:17:56 1: Perfmon: possible freeze starting at 14:17:53, delay is 3.001
2016.12.08 14:17:56 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:18:07 5: [Tageszeit] Original weather readings
2016.12.08 14:18:07 5: Triggering Tageszeit (5 changes)
2016.12.08 14:18:07 5: Starting notify loop for Tageszeit, 5 event(s), first is azimuth: 211.26
2016.12.08 14:18:07 5: [Tageszeit] removing Timer: Tageszeit_sunpos
2016.12.08 14:18:07 5: [Tageszeit] setting  Timer: Tageszeit_sunpos 2016-12-08 14:23:07
2016.12.08 14:18:08 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:18:08 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,019927F0,0009,02

2016.12.08 14:18:08 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:019927F0 IDcnt:0009 L:2 %
2016.12.08 14:18:08 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:18:08 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:18:09 4: using HUEBridge_HTTP_Request: GET lights
2016.12.08 14:18:09 5: HUEBridge_HTTP_Request http://192.168.11.55/api/ed9c2c9eab2bf78561ca3ca0da9aab18/lights: Got data, length: 1466
2016.12.08 14:18:09 4: parse status message for HUEDevice5
--
                fhem ("set Wr.WaschmaschineHoherVerbrauch off")
        }
}
2016.12.08 14:18:26 5: Cmd: >{
        if (ReadingsVal("Wr.Waschmaschine_Power","power","") <= 4 && Value("Wr.WaschmaschineBetrieb") eq "on")
        {
                fhem ("set Wr.WaschmaschineHoherVerbrauch off")
        }
}<
2016.12.08 14:18:33 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:18:33 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,0199899D,0009,02

2016.12.08 14:18:33 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:0199899D IDcnt:0009 L:2 %
2016.12.08 14:18:33 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:18:33 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:18:59 1: Perfmon: possible freeze starting at 14:18:56, delay is 3.001
2016.12.08 14:18:59 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:18:59 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:18:59 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,0199EF33,0009,02

2016.12.08 14:18:59 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:0199EF33 IDcnt:0009 L:2 %
2016.12.08 14:18:59 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:18:59 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:19:02 4: HarmonyMama: send: <iq type='get' id='ping-43'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:19:02 4: Harmony: send: <iq type='get' id='ping-44'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:19:02 5: HarmonyMama: tag: iq, attr:  id='ping-43' type='result'
2016.12.08 14:19:02 5: HarmonyMama: got ping response 43
2016.12.08 14:19:02 5: Harmony: tag: iq, attr:  id='ping-44' type='result'
2016.12.08 14:19:02 5: Harmony: got ping response 44
2016.12.08 14:19:07 5: HMLAN/RAW: /E38E9CF,0000,019A0EB1,FF,FFB9,67861038E9CF0000000AB4FF0C0000

--
2016.12.08 14:19:47.087 4: name: /fhem?cmd=save&XHR=1&fw_id=1891 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.12.08 14:19:47.087 4: Connection closed for WEB_127.0.0.1_35746: EOF
2016.12.08 14:19:49.001 5: HMLAN_Send:  HMLAN1 I:K
2016.12.08 14:19:49.004 5: HMLAN/RAW: /HHM-LAN-IF,03C4,LEQ0102308,26ED87,26ED87,019AB289,0009,02

2016.12.08 14:19:49.005 5: HMLAN_Parse: HMLAN1 V:03C4 sNo:LEQ0102308 d:26ED87 O:26ED87 t:019AB289 IDcnt:0009 L:2 %
2016.12.08 14:19:49.005 5: Triggering HMLAN1 (1 changes)
2016.12.08 14:19:49.005 5: Starting notify loop for HMLAN1, 1 event(s), first is loadLvl: low
2016.12.08 14:19:52.791 4: HarmonyMama: send: <iq type='get' id='ping-45'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:19:52.791 4: Harmony: send: <iq type='get' id='ping-46'><ping xmlns='urn:xmpp:ping'/></iq>
2016.12.08 14:19:52.802 5: HarmonyMama: tag: iq, attr:  id='ping-45' type='result'
2016.12.08 14:19:52.803 5: HarmonyMama: got ping response 45
2016.12.08 14:19:52.805 5: Harmony: tag: iq, attr:  id='ping-46' type='result'
2016.12.08 14:19:52.806 5: Harmony: got ping response 46
2016.12.08 14:20:02.001 1: Perfmon: possible freeze starting at 14:19:59, delay is 3.001
2016.12.08 14:20:02.004 4: SONOS0: Got correct Answer from Subprocess...
2016.12.08 14:20:06.836 4: rpiPing: dummy rpiPing aktuell
2016.12.08 14:20:06.836 5: Triggering rpiPing (1 changes)
2016.12.08 14:20:06.836 5: Starting notify loop for rpiPing, 1 event(s), first is aktuell
2016.12.08 14:20:06.840 4: rpiPing_at: at rpiPing_at Next: 14:23:06
2016.12.08 14:20:06.840 5: Triggering rpiPing_at (1 changes)
2016.12.08 14:20:06.840 5: Starting notify loop for rpiPing_at, 1 event(s), first is Next: 14:23:06
2016.12.08 14:20:09.394 4: using HUEBridge_HTTP_Request: GET lights
2016.12.08 14:20:09.401 5: HUEBridge_HTTP_Request http://192.168.11.55/api/ed9c2c9eab2bf78561ca3ca0da9aab18/lights: Got data, length: 1466
2016.12.08 14:20:09.402 4: parse status message for HUEDevice5
2016.12.08 14:20:09.402 4: parse status message for HUEDevice7
2016.12.08 14:20:09.402 4: parse status message for HUEDevice6
2016.12.08 14:20:09.403 4: parse status message for HUEDevice4
2016.12.08 14:20:09.403 4: parse status message for HUEDevice2
2016.12.08 14:20:14.001 5: HMLAN_Send:  HMLAN1 I:K


Apptime maxDly deutet auch auf Sonos hin?

                             name             function    max  count    total  average maxDly
  tmr-SONOS_IsSubprocessAliveChecker      HASH(0x3a66e00)      2      4        8     2.00   3002 HASH(Sonos)
            tmr-perfmon_ProcessTimer      HASH(0x1bf13f8)      0    110        0     0.00   2023
                 tmr-HMLAN_KeepAlive     keepAlive:HMLAN1      0      5        0     0.00   1009
                    tmr-BlockingKill      HASH(0x621a928)      0      1        0     0.00      1
          tmr-FRITZBOX_Readout_Start FritzBoxRemote.Readout      8      1        8     8.00      1 FritzBoxRemote.Readout
         tmr-FW_closeInactiveClients                           0      2        0     0.00      1
             tmr-HUEBridge_GetUpdate      HASH(0x597ffa0)      8      2       15     7.50      1 HASH(HueBridge)
                 tmr-Twilight_sunpos      HASH(0x5fe9ac8)      4      1        4     4.00      1 HASH(Tageszeit_sunpos)
                         Alarm_Regen          DOIF_Notify      0     21        0     0.00      0
                FHEM.Homebridge.DOIF          DOIF_Notify      0     21        0     0.00      0
                         Fhem_on_rpi       FHEM2FHEM_Read      5      1        5     5.00      0 HASH(Fhem_on_rpi)
              FileLog_Aussen.Thermo1          FileLog_Log      0     21        0     0.00      0
                 FileLog_Bad.Thermo1          FileLog_Log      0     21        0     0.00      0
        FileLog_Gang.Bewegungsmelder          FileLog_Log      0     21        0     0.00      0
              FileLog_Kueche.Thermo1          FileLog_Log      0     21        0     0.00      0
      FileLog_Treppe.Bewegungsmelder          FileLog_Log      0     21        0     0.00      0
                  FileLog_Wz.Thermo1          FileLog_Log      0     21        0     0.00      0
                      FritzBoxRemote         FRITZBOX_Set      0      2        0     0.00      0
                           Fritz_Box FB_CALLMONITOR_Notify      0     21        0     0.00      0
                              HMLAN1         HMLAN_Notify      0     21        0     0.00      0
                              HMLAN1           HMLAN_Read     37      8       88    11.00      0 HASH(HMLAN1)


Kann mir jemand helfen, woran das wirklich liegen könnte?

Ich würd mich sehr über eure Meinungen freuen

Viele Grüße
Benjamin
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: naimo am 09 Dezember 2016, 07:38:03
Update: Nach dem 10. oder 11. "shutdown restart" scheinen sich die "freezes" wieder beruhigt zu haben. Anscheinend kamen sie urplötzlich und verschwinden genauso wieder urplötzlich...

Ich halte euch auf dem laufenden, wenn sich wieder was tut
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: frank am 09 Dezember 2016, 15:38:57
Zitat016.12.08 14:20:02.001 1: Perfmon: possible freeze starting at 14:19:59, delay is 3.001
du musst im log nach dem freeze zeitpunkt schauen.
bei dir ist leider nichts zu sehen.

apptime mit option max aufrufen, um die "langläufer"/täter oben in der tabelle zu sehen. mit maxdly siehst du die opfer der freezes. im bsp wurde sonos gute 3s verzögert ausgeführt.

ZitatUpdate: Nach dem 10. oder 11. "shutdown restart" scheinen sich die "freezes" wieder beruhigt zu haben.
die hoffnung stirbt zuletzt, oder?   :)
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: AndyMu am 27 Dezember 2016, 17:55:52
Also ich hatte die Perfmon Meldungen im 2-Sekundentakt... und habe mit apptime dann durch Zufall rausgefunden, dass es einige Prozesse gibt, die mein System sehr in Anspruch nehmen: Logfiles für die Thermostate!
Die Logfiles hatten Größen >60MB, waren nur als Jahreslogs angelegt.

Ich habe jetzt radikal alle Device-Logs rausgeschmissen, die Thermostat-Logfiles auf Tageslogs umgestellt. Gleiches mit dem zentralen Log, und alle werden mit nrarchive-Attributen nach 3 Tagen automatisch gelöscht.

Was soll ich sagen... seit 5 Minuten absolute Ruhe, sogar meine Disconnects auf den HMLANs haben anscheinend aufgehört.
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: rudolfkoenig am 27 Dezember 2016, 18:09:33
Ich bin der Ansicht, dass grosse Logfiles an sich keine Performance-Probleme verursachen.

Es kommt zu einem Performanceproblem, wenn man ein SVG-Plot aus einer Logdatei erstellen moechte, die neben(!) der gezeigten noch viele weitere Daten enthaelt, deswegen ist die Idee, nur das Notwendige zu loggen sinnvoll. Dabei macht es kein Unterschied, ob es um Tageslogs oder Jahreslogs handelt. Damit das SVG-Berechnen das System nicht blockiert, sollte man das FHEMWEB-Attribut plotfork setzen.

Bitte korrigiere mich, wenn meine Theorie nicht zum Praxis passt
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: duke-f am 27 März 2018, 15:36:46
Das ist schon seeeehr alt, ich probiere trotzdem eine Antwort zu bekommen. Passt nun mal sehr genau zu meiner Situation.
Zeitweise habe ich auch immense Freezes, die gelegentlich scheinbar viel blockieren. Nach Rudolf's  Darstellung können dafür durchaus SVG-Plots die Ursache sein. Nun habe ich konkret dafür mein Bedientablet im Flur im Verdacht. Es kommt schon vor, dass dieses lange Zeit mit einer besonderen Anzeige mit verhältnismäßig vielen Plots da steht. Den Refresh habe ich hier auch auf unter eine Minute gesetzt, weil ansonsten zeitweise die Angaben darauf nicht aktuell genug sind.

Kann das eine wesentliche Bedeutung für die Freezes haben? Ich versuche die Frage mal so zu beantworten, dass ich solche langzeit-Darstellungen von SVG-Plots vermeide.
Titel: Antw:Perfmon "possible freeze" jede Minute
Beitrag von: frank am 27 März 2018, 15:45:30
eigentlich muss man nicht gross spekulieren, sondern nur nach anleitung verbose hochdrehen und zeiten vergleichen.

probiere lieber das neue freezemon.