PRESENCE-StartLocalScan und appTime

vbs · 31 Mai 2015, 20:08:19

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:

Code Auswählen

                                 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?

smurfix · 31 Mai 2015, 21:48:18

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.?

vbs · 31 Mai 2015, 22:18:41

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

Markus Bloch · 01 Juni 2015, 16:19:21

Bist du dir sicher, dass es sich hier um Sekunden handelt? Ich meine das wären Millisekunden unter total und average.

vbs · 01 Juni 2015, 16:52:55

Ja ja , ich denke auch, dass es Millisekunden sind (aber 6000 ms sind ja 6 Sekunden):

Code Auswählen

                                 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.

smurfix · 01 Juni 2015, 18:05:21

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.

vbs · 01 Juni 2015, 18:11:59

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:

Code Auswählen

                                 name             function    max  count    total  average maxDly 
          tmr-PRESENCE_StartLocalScan      HASH(0xb214928)   6540   3605    20898     5.80   4492 HASH(wz_notebook)

vbs · 14 März 2018, 19:46:04

Epic Necroposting!

Code Auswählen


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:

Code Auswählen


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

Markus Bloch · 15 März 2018, 14:03:51

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

vbs · 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!

vbs · 15 März 2018, 16:18:33

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"):

Code Auswählen

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...

KernSani · 15 März 2018, 18:59:02

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...

vbs · 16 März 2018, 09:40:39

Klasse, danke dir, werd ich ausprobieren!

vbs · 19 März 2018, 13:46:32

Ich hab da jetzt etwas "gefangen" mit dem freezemon. Aber irgendwie bin ich noch nicht viel schlauer

Code Auswählen

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!

frank · 19 März 2018, 15:57:06

das anlegen des childs durch blockingcall scheint zu dauern.
hast du eventuell manchmal speicherprobleme?

vbs · 19 März 2018, 16:09:53

Meinst du Probleme im Sinne von Speichermangel? Hm, eigentlich nicht, ist ein komfortables Gigabytchen frei:

Code Auswählen

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

KernSani · 19 März 2018, 16:36:59

Hast du das blockingCallMax Attribut in global gesetzt?

Kurz, weil mobil...

vbs · 19 März 2018, 16:46:18

Nein, hab ich nicht. Ich schwöre!

frank · 19 März 2018, 19:40:25

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:
Code Auswählen Erweitern
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.