apptime zeigt mir ein paar Funktionen an, die FHEM für mehrere Sekunden blockieren. Da ist zum Beispiel die Funktion "StartLocalScan" aus dem PRESENCE-Modul:
name function max count total average maxDly
tmr-statistics_PeriodChange HASH(0xbedf0a8) 6663 31 18931 610.68 16 HASH(env_stats)
tmr-PRESENCE_StartLocalScan HASH(0xb214928) 6540 3605 20898 5.80 4492 HASH(wz_notebook)
tmr-YAMAHA_AVR_GetStatus HASH(0xa59eb30) 5250 3635 9563 2.63 6403 HASH(wz_avr)
tmr-ENIGMA2_GetStatus HASH(0xa5e6278) 5081 2405 11878 4.94 229 HASH(wz_dm7020hd)
HMLAN0 HMLAN_Read 1172 12789 103354 8.08 0 HASH(HMLAN0)
Ich versteh das nicht ganz, da ich den Modus "lan-ping" nutze, der doch eigenlich nicht-blockierend ausgeführt wird, oder? Ich habe auch mal in den Code geschaut, aber außer einem Aufruf von BlockingCall, sehe ich eigentlich keine weiteren Aufrufe, die in Frage kämen. Hat da jemand eine Idee, wieso die Funktion FHEM so lange blockiert?
Hmm. Wenn das Ding 20'000mal aufgerufen wird und davon genau einmal für 6 Sekunden blockiert, dann kann das durchaus daran liegen, dass der Rechner an sich viel zu tun hat und FHEM schlicht nicht ausgeführt wurde.
Mit welcher CPU-Priorität läuft dein FHEM? Wie ist deine Rechnerauslastung etc.?
Hm, die Idee ist nicht schlecht. Aber FHEM läuft in einer TinyCore-Linux-VM auf einem i5 mit 8 GB RAM. Der Rechner idlet eigentlich immer vor sich hin, so dass ich denke, dass solche Hänger von 6 Sekunden eigentlich nicht vorkommen sollten.
Wenn FHEM einfach nicht dran kommen würde, dann würde ich auch erwarten, dass bei apptime immer mal wieder auch andere Funktionen ganz oben stehen müssten. Es sind jedoch immer die gleichen 2-3 "Verdächtigen", die ich oben auf der Liste erwische :)
Bist du dir sicher, dass es sich hier um Sekunden handelt? Ich meine das wären Millisekunden unter total und average.
Ja ja , ich denke auch, dass es Millisekunden sind (aber 6000 ms sind ja 6 Sekunden):
name function max count total average maxDly
tmr-PRESENCE_StartLocalScan HASH(0xb214928) 6540 3605 20898 5.80 4492 HASH(wz_notebook)
Sorgen macht mir da eben die Angabe "max 6663", welche ich als 6663 ms, also 6,7 s interpretiere.
Ich muss zugeben, auch 0.6 Sekunden (das 'average') wären mir viel zu viel Latenz zwischen "Schalter drücken" und "Licht geht an".
Ich würde da mal mit "strace -ttT -p $(cat /run/fhem/fhem.pid)" drangehen und ihm auf Kernel-Ebene auf die Finger schauen. (Dein pidfile ist bestimmt woanders.)
Evtl. mit "-e !gettimeofday" (oder was auch immer) die Systemaufrufe rausfiltern, die garantiert nicht lang im Kernel herumhängen.
Argh, sorry, jetzt hab ich Verwirrung gestiftet:
In meinem vorherigen Beitrag hatte ich fälschlicherweise die Ausgabe von "tmr-statistics_PeriodChange" reingeschrieben. Da kann ich mir sogar vorstellen, dass das im Schnitt 0,6 s dauert.
Hier nochmal die Ausgabe von PRESENCE, um die es mir eigentlich ging. Die dauert normalerweise nur 6 ms (wäre ok), aber hat Ausreißer bis 6 s:
name function max count total average maxDly
tmr-PRESENCE_StartLocalScan HASH(0xb214928) 6540 3605 20898 5.80 4492 HASH(wz_notebook)
Epic Necroposting!
name function max count total average maxDly avgDly TS Max call param Max call
tmr-PRESENCE_StartLocalScan HASH(0x6591368) 41687 5505 87192.85 15.84 203344.18 57.17 14.03. 19:26:32 HASH(fl_ben)
Aber ich hab das Problem immernoch :( Gerade eben einen saftigen Delay von 41 Sek. in PRESENCE_StartLocalScan. Hat evtl. jemand eine Idee, was da die Ursache sein könnte? Die Funktion sollte doch nie blockieren, oder?
Das hier ist das Device:
Internals:
ADDRESS 192.168.2.232
CHANGED
DEF lan-ping 192.168.2.232
INTERVAL_NORMAL 30
INTERVAL_PRESENT 30
MODE lan-ping
NAME fl_ben
NOTIFYDEV global
NR 358
NTFY_ORDER 50-fl_ben
STATE present
TYPE PRESENCE
READINGS:
2018-03-12 16:40:54 model lan-ping
2018-03-14 19:44:46 presence present
2018-03-14 19:44:46 state present
helper:
CURRENT_STATE present
PRESENT_COUNT 0
bm:
PRESENCE_Notify:
cnt 57
dmx -1000
dtot 0
dtotcnt 0
mTS 14.03. 19:33:39
max 0.000644207000732422
tot 0.00621914863586426
mAr:
HASH(fl_ben)
HASH(global)
PRESENCE_Set:
cnt 4
dmx -1000
dtot 0
dtotcnt 0
mTS 14.03. 19:44:57
max 4.91142272949219e-05
tot 0.00015711784362793
mAr:
HASH(0x6591368)
fl_ben
?
Attributes:
alias Ben - Online
devStateIcon present:control_on_off@00FF00 absent:control_on_off@FF0000
event-on-change-reading state
group Geräte
icon it_nas
room Flur
PRESENCE_StartLocalScan() werden nur 2 Funktionen aufgerufen (RemoveInternalTimer und BlockingCall). Ansonsten werden nur Daten geprüft und Variablen neue Werte zugewiesen.
Ich kann mir daher nur vorstellen, dass entweder beim Aufruf von RemoveInternalTimer() oder BlockingCall() der Zeitverzug herrührt. Hast du evtl. ein Log mit gesetztem verbose 5 von PRESENCE wo so ein Verzug von mehreren Sekunden auftritt?
Danke
Gruß
Markus
Ich werde mal versuchen, das mit verbose 5 einzufangen. Tritt aber nur alle paar Tage auf, also kann etwas dauern.
Evtl. hat auch die Maschine an sich ab und zu Hänger. Normalerweise ist sowas aber in dmesg/syslog sichtbar... schon komisch... Aber je mehr ich darüber nachdenke, desto plausibler finde ich das...
Naja, ich werds beobachten, danke dir!
Das Ubuntut hat ja ein paar RealTime-Prozesse laufen, die potenziell in der Lage wären, alle nicht-realtime-Prozesse auf unbestimmte Zeit verhungern zu lassen (FF - "FiFo"):
vbs@minion:~$ ps -eLfc
UID PID PPID LWP NLWP CLS PRI STIME TTY TIME CMD
root 1 0 1 1 TS 19 Feb13 ? 00:00:25 /sbin/init noprompt
root 2 0 2 1 TS 19 Feb13 ? 00:00:00 [kthreadd]
root 3 2 3 1 TS 19 Feb13 ? 00:00:55 [ksoftirqd/0]
root 5 2 5 1 TS 39 Feb13 ? 00:00:00 [kworker/0:0H]
root 7 2 7 1 TS 19 Feb13 ? 00:08:38 [rcu_sched]
root 8 2 8 1 TS 19 Feb13 ? 00:00:00 [rcu_bh]
root 9 2 9 1 FF 139 Feb13 ? 00:00:08 [migration/0]
root 10 2 10 1 FF 139 Feb13 ? 00:00:10 [watchdog/0]
root 11 2 11 1 FF 139 Feb13 ? 00:00:11 [watchdog/1]
root 12 2 12 1 FF 139 Feb13 ? 00:00:09 [migration/1]
root 13 2 13 1 TS 19 Feb13 ? 00:13:49 [ksoftirqd/1]
root 15 2 15 1 TS 39 Feb13 ? 00:00:00 [kworker/1:0H]
root 16 2 16 1 FF 139 Feb13 ? 00:00:10 [watchdog/2]
root 17 2 17 1 FF 139 Feb13 ? 00:00:07 [migration/2]
root 18 2 18 1 TS 19 Feb13 ? 00:17:49 [ksoftirqd/2]
root 20 2 20 1 TS 39 Feb13 ? 00:00:00 [kworker/2:0H]
root 21 2 21 1 FF 139 Feb13 ? 00:00:10 [watchdog/3]
root 22 2 22 1 FF 139 Feb13 ? 00:00:07 [migration/3]
...
Wäre dann einfach Zufall, dass es das PRESENCE trifft. Einfach weil PRESENCE regelmäßig läuft ... grübel grübel...
Zitat von: vbs am 15 März 2018, 15:43:53
Ich werde mal versuchen, das mit verbose 5 einzufangen. Tritt aber nur alle paar Tage auf, also kann etwas dauern.
Evtl. hat auch die Maschine an sich ab und zu Hänger. Normalerweise ist sowas aber in dmesg/syslog sichtbar... schon komisch... Aber je mehr ich darüber nachdenke, desto plausibler finde ich das...
Naja, ich werds beobachten, danke dir!
Du kannst mal Freezemon mit eingeschaltetem fm_logFile mitlaufen lassen. Dann bekommst du ein separates verbose 5 log vom Zeitpunkt des ,,freeze"
Kurz, weil mobil...
Klasse, danke dir, werd ich ausprobieren!
Ich hab da jetzt etwas "gefangen" mit dem freezemon. Aber irgendwie bin ich noch nicht viel schlauer :(
jump to the end
=========================================================
[Freezemon] sys_freezemon: possible freeze starting at 08:37:53, delay is 1.393 possibly caused by: CUL_HM_valvePosUpdt(N/A) PRESENCE_StartLocalScan(wz_htpc) BlockingKill(N/A)
2018.03.19 08:37:52.400 5: CUL_HM bd_hmVirtualWeather m:205 ->206 t:1521445072.39788->1521445217.94788 M:1521445072.40093 :145.55
2018.03.19 08:37:52.401 5: CUL_HM bd_hmVirtual protEvent:CMDs_pending pending:1
2018.03.19 08:37:52.401 5: HMLAN_Send: HMLAN0 S:+000000,00,00,00
2018.03.19 08:37:52.451 5: HMLAN_Send: HMLAN0 S:S3D316F73 stat: 00 t:00000000 d:01 r:3D316F73 m:CE 8470 F16789 000000 00CF
2018.03.19 08:37:52.451 5: CUL_HM bd_hmVirtual protEvent:CMDs_done
2018.03.19 08:37:52.843 5: HMLAN/RAW: /R3D316F73,0002,00000000,FF,7FFF,CE8470F1678900000000CF
2018.03.19 08:37:52.844 5: HMLAN_Parse: HMLAN0 R:R3D316F73 stat:0002 t:00000000 d:FF r:7FFF m:CE 8470 F16789 000000 00CF
2018.03.19 08:37:53.124 5: co2mini data received 87 39 6 132 13
2018.03.19 08:37:53.125 5: PRESENCE (wz_htpc) - stopping timer
2018.03.19 08:37:53.125 5: PRESENCE (wz_htpc) - starting blocking call for mode lan-ping
--- log skips 1.241 secs.
2018.03.19 08:37:54.366 4: BlockingCall (PRESENCE_DoLocalPingScan): created child (120229), uses telnetPort to connect back
[Freezemon] sys_freezemon: possible freeze starting at 08:37:53, delay is 1.393 possibly caused by: CUL_HM_valvePosUpdt(N/A) PRESENCE_StartLocalScan(wz_htpc) BlockingKill(N/A)
jump to the top
Hat da jemand eine Idee evtl.? Danke!
das anlegen des childs durch blockingcall scheint zu dauern.
hast du eventuell manchmal speicherprobleme?
Meinst du Probleme im Sinne von Speichermangel? Hm, eigentlich nicht, ist ein komfortables Gigabytchen frei:
vbs@minion:~$ free -h
total used free shared buff/cache available
Mem: 17G 14G 1.0G 26M 3.0G 3.6G
Swap: 1.0G 210M 811M
Hast du das blockingCallMax Attribut in global gesetzt?
Kurz, weil mobil...
Nein, hab ich nicht. Ich schwöre!
Zitat von: vbs am 19 März 2018, 16:09:53
Meinst du Probleme im Sinne von Speichermangel? Hm, eigentlich nicht, ist ein komfortables Gigabytchen frei:
vbs@minion:~$ free -h
total used free shared buff/cache available
Mem: 17G 14G 1.0G 26M 3.0G 3.6G
Swap: 1.0G 210M 811M
im grunde hast du recht, ... aber ...
in der guten alten fritzbox zeit galt bei mir: sobald swap speicher genutzt wurde, war das desaster nicht mehr weit. dann habe ich immer einen reboot gemacht und hatte wieder eine weile ruhe.
wenn von gigantischen 17GB bereits 14GB genutzt werden, finde ich das schon enorm voll.
ich würde auf alle fälle den speicher beobachten.