Seit Kurzem permanent perfmon Logs

[vbs]

Hi Leute,

seit ein paar Tagen hab ich permanent perfmon-Einträge im Log, sieht ungefähr so aus:

Code Auswählen Erweitern

2017.02.08 09:40:40.566 1: Perfmon: possible freeze starting at 09:40:39, delay is 1.566
2017.02.08 10:25:48.101 1: Perfmon: possible freeze starting at 10:25:47, delay is 1.101
2017.02.08 10:33:53.329 1: Perfmon: possible freeze starting at 10:33:52, delay is 1.329
2017.02.08 10:59:58.007 3: DbLog benDbLog: Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhem
2017.02.08 10:59:58.009 3: DbLog benDbLog: Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2017.02.08 11:06:36.224 1: Perfmon: possible freeze starting at 11:06:35, delay is 1.224
2017.02.08 11:12:03.063 1: Perfmon: possible freeze starting at 11:12:02, delay is 1.063
2017.02.08 11:52:13.184 1: Perfmon: possible freeze starting at 11:52:12, delay is 1.184
2017.02.08 11:58:39.276 1: Perfmon: possible freeze starting at 11:58:38, delay is 1.276
2017.02.08 12:26:07.236 1: Perfmon: possible freeze starting at 12:26:06, delay is 1.236
2017.02.08 12:36:17.543 3: DbLog benDbLog: Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhem
2017.02.08 12:36:17.566 3: DbLog benDbLog: Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2017.02.08 12:36:21.877 3: DbLog benDbLog: Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhem
2017.02.08 12:36:21.879 3: DbLog benDbLog: Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2017.02.08 12:37:34.513 3: DbLog benDbLog: Creating Push-Handle to database mysql:database=fhem;host=localhost;port=3306 with user fhem
2017.02.08 12:37:34.514 3: DbLog benDbLog: Push-Handle to db mysql:database=fhem;host=localhost;port=3306 created
2017.02.08 12:39:35.336 1: Perfmon: possible freeze starting at 12:39:34, delay is 1.336

Evtl. hängt das mit Änderungen zusammen die ich gemacht habe, evtl. hängts auch mit nem FHEM-Update von vor ein paar Tagen zusammen. Das komische ist, dass apptime überhaupt keine Hänger meldet:

Code Auswählen Erweitern


                                  name             function    max  count    total  average maxDly
                              HMLAN0           HMLAN_Read    304   2412    11013     4.57      0 HASH(HMLAN0)
                      env_nty_motion          notify_Exec    199     49      377     7.69      0 HASH(env_nty_motion); HASH(fl_motion)
                    ku_lightLedFloor        WifiLight_Set    143     28      151     5.39      0 HASH(ku_lightLedFloor); ku_lightLedFloor; HSV; 350,100,20; 0.6
                         smartlights      SMARTLIGHTS_Set    143   1669      358     0.21      0 HASH(smartlights); smartlights; submit
         tmr-PRESENCE_StartLocalScan HASH(0x55ac19119e78)    126    488     3427     7.02   1055 HASH(wz_base)
         tmr-PRESENCE_StartLocalScan HASH(0x55ac1a6ff488)    121    489     3482     7.12     96 HASH(wz_openelec)
                   nty_envLuminosity          notify_Exec    118   2624      470     0.18      0 HASH(nty_envLuminosity); HASH(env_thpl)
         tmr-statistics_PeriodChange HASH(0x55ac191f80d8)    114      5      474    94.80      1 HASH(env_stats)
                    wz_lightLedCouch        WifiLight_Set    102    210      106     0.50      0 HASH(wz_lightLedCouch); wz_lightLedCouch; HSV; 0,0,0; 960
         tmr-PRESENCE_StartLocalScan HASH(0x55ac187126a8)     95    493     3548     7.20    942 HASH(fl_ben)
         tmr-PRESENCE_StartLocalScan HASH(0x55ac199fb4c0)     85    489     3554     7.27    273 HASH(wz_sub)
         tmr-PRESENCE_StartLocalScan HASH(0x55ac1a1bd3a0)     85    488     3409     6.99    905 HASH(sz_z1_pres)
                 tmr-Calendar_Wakeup HASH(0x55ac18389660)     77      4      166    41.50      1 HASH(calGoogle)
         tmr-PRESENCE_StartLocalScan HASH(0x55ac1a66d8e8)     67    487     3339     6.86    564 HASH(sz_tabS_pres)
                         tmr-at_Exec HASH(0x55ac1a678ea8)     53      1       53    53.00      0 HASH(fl_motionTimer)
               tmr-SYSSTAT_GetUpdate HASH(0x55ac199feb70)     48    136     4090    30.07      1 HASH(fl_benStats)
                                TRX0             TRX_Read     41   1381     1304     0.94      0 HASH(TRX0)
                        nty_presence          notify_Exec     36      8      100    12.50      0 HASH(nty_presence); HASH(presence)
             tmr-SB_PLAYER_GetStatus HASH(0x55ac17ab8c98)     32     54     1548    28.67    449 HASH(ku_sb)
                         tmr-at_Exec HASH(0x55ac1bb6dfb8)     32      1       32    32.00      0 HASH(fl_motionTimer)
                            sbserver       SB_SERVER_Read     32    457      770     1.68      0 HASH(sbserver)

Hat jemand eine Idee, was man da machen kann und wieso apptime davon nichts mitbekommt?

Danke euch!

[P.A.Trick]

Hm maxdly ist hier z.B zu hoch:

         tmr-PRESENCE_StartLocalScan HASH(0x55ac19119e78)    126    488     3427     7.02   1055 HASH(wz_base)


Was ist denn wz_base?

[vbs]

Ich glaube ich weiß was passiert ist. Theorie: Es liegt nicht an FHEM, also da blockiert nix. Aber die Systemzeit meines Systems scheint nicht geradeaus zu laufen, manipuliert durch den ntpd. Der ntpd benutzt bei mir im Normalfall die Pool-Server von pool.ntp.org. Jedoch läuft parallel der DHCP-Client dhclient. Wenn nun ein DHCP-Event auftritt (zum Beispiel die regelmäßige Lease-Erneuerung), dann trägt dhclient den DHCP-Server als NTP-Server in die ntp.conf ein und startet den ntpd neu, der dann fortan meinen DHCP-Server nutzt anstatt die Pool-Server.
Mein DHCP-Server ist eine FritzBox und offenbar läuft mein System mit der Box als NTP-Server nicht so rund. Ich hab jetzt den NTP-Server in der FritzBox deaktiviert, so dass bei DHCP-Events der dhclient nicht mehr am NTP-Server manipuliert.

Werde das beobachten ob es hilft.

Quelle:

Code Auswählen Erweitern

When the DHCP client program, dhclient, receives a list of NTP servers from the DHCP server, it adds them to ntp.conf and restarts the service. To disable that feature, add PEERNTP=no to /etc/sysconfig/network.
https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/6/html/Deployment_Guide/s1-Understanding_the_ntpd_Configuration_File.html

PS.: wz_base ist mein PC im Wohnzimmer

[P.A.Trick]

Hört sich unwahrscheinlich an! Hast du so etwas wie presence o.ä. Laufen?

[marvin78]

Nutzt du readingsProxy? Mach mal ein

Code Auswählen Erweitern

apptime maxDly

und schaue, ob sich readingsProxy_setNotfiyDev unter den Übeltätern befindet. Das ist bei mir aktuell die Ursache für viele Freezes und ich habe noch nicht analysieren können warum.

[vbs]

Ja presence hab ich, aber IIRC forking, also sollte nicht blockieren.

Ja stimmt, klingt unwahrscheinlich, aber folgende Indizien:
- System lief problemlos und auf einmal fing das an -> Systemzeit war ok bis ein DHCP-Event die NTP-Config verdreht hat
- perfmon bemerkt ein Problem, apptime meldet aber keine Blockierung -> offenbar ist perfmon sensibel ggü. Zeitsprüngen, apptime jedoch nicht
- systemd meldet andauernd, dass sich die Systemzeit geändert hat:

Code Auswählen Erweitern

Feb  8 09:01:43 minion systemd[1]: Time has been changed
Feb  8 09:08:53 minion systemd[1]: Time has been changed
Feb  8 09:24:06 minion systemd[1]: Time has been changed
Feb  8 09:40:40 minion systemd[1]: Time has been changed
Feb  8 09:52:46 minion systemd[1]: Time has been changed
Feb  8 09:59:36 minion systemd[1]: Time has been changed
Feb  8 10:14:43 minion systemd[1]: Time has been changed
Feb  8 10:25:47 minion systemd[1]: Time has been changed
Feb  8 10:33:53 minion systemd[1]: Time has been changed
Feb  8 10:41:00 minion systemd[1]: Time has been changed
Feb  8 10:50:30 minion systemd[1]: Time has been changed
Feb  8 11:06:36 minion systemd[1]: Time has been changed
Feb  8 11:12:02 minion systemd[1]: Time has been changed
Feb  8 11:20:28 minion systemd[1]: Time has been changed
Feb  8 11:35:25 minion systemd[1]: Time has been changed
Feb  8 11:52:12 minion systemd[1]: Time has been changed
Feb  8 11:58:39 minion systemd[1]: Time has been changed


Die perfmon-Meldungen decken sich zeitlich 1:1 mit den systemd-Meldungen:

Code Auswählen Erweitern

2017.02.08 09:40:40.566 1: Perfmon: possible freeze starting at 09:40:39, delay is 1.566
2017.02.08 10:25:48.101 1: Perfmon: possible freeze starting at 10:25:47, delay is 1.101
2017.02.08 10:33:53.329 1: Perfmon: possible freeze starting at 10:33:52, delay is 1.329
2017.02.08 11:06:36.224 1: Perfmon: possible freeze starting at 11:06:35, delay is 1.224
2017.02.08 11:12:03.063 1: Perfmon: possible freeze starting at 11:12:02, delay is 1.063
2017.02.08 11:52:13.184 1: Perfmon: possible freeze starting at 11:52:12, delay is 1.184
2017.02.08 11:58:39.276 1: Perfmon: possible freeze starting at 11:58:38, delay is 1.276

Also gerade aufgrund der Logeinträge würde ich Geld drauf wetten, dass das der Grund ist.

@marvin78:
Nee, hab kein readingsProxy

[herrmannj]

offenbar ist perfmon sensibel ggü. Zeitsprüngen

yepp. Perfmon misst die relative Verzögerung. Wenn die Uhr sich ändert könnte dieser Effekt auftreten, der Zeitsprung muss jedoch eine Sekunde betragen. Das wäre viel weil bei Dir ja auch häufig.

vg
joerg

[vbs]

Hm, ich hatte ja eigentlich gedacht, dass der NTP-Server der FritzBox evtl. zu ungenau ist und daher auch die Probleme kommen. Es stellt sich heraus, dass mein System (Ubuntu-VM) plötzlich generell ein Problem hat, die Zeit synchron zu halten. Nach 90 Minuten Laufzeit hab ich schon knapp 10 Sekunde Offset zur Referenzzeit.
Seltsam... Ich hab ntpd installiert vor ca. 2 Wochen nachdem ich VMWare's Timekeeping Best Practice gelesen habe und daraufhin hat das System die Zeit zumindest stabil mit einem Offset von ca. 80 ms gehalten. Und nun fängt es auf einmal so stark an zu driften

[Wernieman]

Also eigentlich macht npd keine Zeitsprünge. npd läsr die Softwareuhr schneller/langsamer laufen, aber keine Zeitsprünge.

Es sei denn ... Du hast einen Cron mit ntpdate eingerichtet.

was sagt denn ein "ntpq -p" auf Deinem System?

[vbs]

Doch doch, ntpd macht schon Zeitsprünge, nennt sich "steps". Das passiert wenn der aktuelle Offset größer ist als der konfigurierte step threshold (default 128 ms).
Du kannst auch ntpd mit "-x" starten. Das ist dann der Slew Mode in dem wirklich nie steps gemacht werden.

Ich hab momentan ntpd in diesem slew mode laufen und mal zu sehen wie sich der Offset entwickelt. Sieht momentan so aus (Offset wird immer größer):

Code Auswählen Erweitern

    remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
+ivanova.ganneff 192.53.103.108   2 u   42   64  377   20.710  12073.5 424.774
-ntp4.v-bits.nl  78.46.93.106     3 u    2   64  377   20.190  11445.2 520.284
*ntp0.rrze.uni-e .GPS.            1 u   58   64  377   18.378  11577.7 339.617
+s1.vlns.de      176.221.46.134   3 u    2   64  377   20.569  11568.2 418.842

Also seit ca. 8 Uhr nun ~ 12 s Offset. Wenn ich ihn ohne slew mode laufen lassen, dann setzt ntpd regelmäßig die Zeit hart, so dass der Offset auf 0 springt. Aber dann meckert auch FHEM's perfmon.
Die Uhr des Systems läuft einfach viel zu schnell/langsam. Offenbar auch so stark, dass ntpd das nicht ausgleichen kann. Ich glaube ntpd korrigiert maximal mit 0,5ms/s.

Im Moment (mit slew) hab ich keine Zeitsprünge aber dafür geht die Uhr einfach falsch 

[herrmannj]

Nach 90 Minuten Laufzeit hab ich schon knapp 10 Sekunde Offset zur Referenzzeit.

na denn erklären sich die perfmon Meldungen. Perfmon merkt das es (vermeintlich) später aufgerufen wird als geplant. Das genau meldet es dann: "Achtung, hier stimmt was nicht"

vg
joerg

[Wernieman]

Mir fällt spontan ein:
- Auf was für ein System/Distri arbeitest Du?

[vbs]

Der Rechner ist nativ ein Windows 10 mit Intel i5 CPU. Da läuft dann ein aktuelles VMWare Workstation mit einem Ubuntu 16.10 x64 Gast.

Laut diesem Best-Practice-Guide (https://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1006427) sind da keine weiteren Kernel-Tweaks notwendig und es ist der Einsatz von ntpd anstatt der eigenen VMWare-Zeittools empfohlen.

Das Ganze lief halt jetzt ca. 2 Wochen ohne Probleme mit einem recht konstanten Offset von ca. 50 ms. Seit zwei Tagen dreht dir Uhr einfach total durch

[Wernieman]

Mhhhh ......

Habe gerade versucht mich auf die schnelle einzulesen und habe gerade anderweitiges gelesen.

Hast Du die VMTools installiert?

Allerdings gebe ich Dir Recht, das sehr unterschiedliche Angaben im Netz zu finden sind. Hast Du folgendes gelesen?
https://kb.vmware.com/selfservice/microsites/search.do?cmd=displayKC&docType=kc&externalId=1011771&sliceId=1&docTypeID=DT_KB_1_1&dialogID=780562710&stateId=1%200%20780582396

Bzw:
Geht die Uhr von Deinem Windows-Rechner richtig?

[vbs]

Hast Du die VMTools installiert?

Ja die hab ich, aber die timeSync-Option gemäß BestPractices momentan deaktiviert.

Allerdings gebe ich Dir Recht, das sehr unterschiedliche Angaben im Netz zu finden sind. Hast Du folgendes gelesen?
https://kb.vmware.com/selfservice/microsites/search.do?cmd=displayKC&docType=kc&externalId=1011771&sliceId=1&docTypeID=DT_KB_1_1&dialogID=780562710&stateId=1%200%20780582396

Vielen Dank! Ich bin da auch schonmal drüber gestolpert und werde das nachher mal in Ruhe durcharbeiten.

Das hier fand ich auch interessant (ist aber schon sehr alt. Ich weiß nicht, ob das noch zutrifft):
http://vmblog.com/archive/2007/08/24/help-vmware-fixing-time-keeping-problems-with-the-guest-os.aspx#.WJx1-N8k7mF
Da gehts drum, dass VMWare die CPU-Frequenz des Hosts kennen muß. Wird normalerweise wohl automatisch erkannt. Vielleicht liegt da was im Argen bei mir. Mir ist nicht ganz klar, wie sich das verhalten soll, wenn die CPU dynamisch die Frequenz ändert.

Geht die Uhr von Deinem Windows-Rechner richtig?

Gehe ich eigentlich von aus. Ist ein normaler (hoffentlich) korrekt eingerichteter Windows-10-PC. Werde ich aber auch nochmal überprüfen nachher.