100% CPU Last / panStamp / eventTypes / notifies / filelog

[dev0]

Hallo zusammen,

ich schlage mich seit einiger Zeit mit folgendem Problem rum:

100% CPU Last für ca. 8 Sek. bei den folgenden Aktionen im fhemweb:
- Anzeige der Details eines Notify oder FileLog (http://xxx:8083/fhem?detail=yyy)
- Betroffen sind auch Aktionen auf diesen Detailseiten (Attribute ändern und löschen, Speichern der Definition) und der Aufruf der Seite selbst

Auslöser:
Dieses Phänomen tritt genau dann auf, wenn die ersten Daten von PanStamps empfangen wurden, für die eine passende .xml Datei existiert. Ich habe verschiedene Sketches getestet (TempHumPress, Soilmoisture, RGB Driver) sowohl mit AVRs als auch NRGs. Es macht auch keinen Unterschied welche Arduino IDE zum Kompilieren verwendet wurde (1.06, 1.58, 1.6) oder ino in Verbindung mit der IDE 1.06.

Bisher getestet:
- Komplette Server Hardware getauscht
- Ubuntu Server 14.04 durch Lubuntu Distribution ersetzt
- PanStick und Modem-PanStamp (AVR+NRG) getauscht
- PanStick an weiteren Rechner angeschlossen und über fhem2fhem (RAW) verbunden
- diverse Addons disabled (XBMC, iTunes, remotecontrol, Weather, Openweather, Yamaha_AVR)
- alle FileLogs durch dblog erstetzt

Alles ohne Erfolg. Aber im Thread http://forum.fhem.de/index.php/topic,34528.0.html schrieb betateilchen gestern Abend, dass man das Device eventTypes auf produktiven Systemen auch weglassen kann... Und siehe da: Ohne eventTypes Device tritt das Problem nicht mehr auf. Nach dem Löschen der eventTypes.txt und erneutem aktivieren tritt das Problem nach einiger Zeit wieder auf.

Hat jemand eine Idee wie das Problem zu lösen ist?


Hier noch ein paar Details zum meinem System, weitere benötigte Infos reiche ich gerne nach.

Verwendete Hard- u. Software:

Code Auswählen Erweitern


Odroid-U3 (Quad ARM Cortex-A9 1.7GHz 2GB), 8GB eMMC Flash, Ubuntu Server 14.04.x LTS, alle nötigen Perl Module via cpanm installiert


FHEM log:

Code Auswählen Erweitern


2015.02.19 11:16:00.424 5: Triggering global (1 changes)
2015.02.19 11:16:00.424 5: Notify loop for global ATTR global verbose 5
2015.02.19 11:16:00.435 5: Cmd: >attr PS1 verbose 5<
2015.02.19 11:16:00.436 5: Triggering global (1 changes)
2015.02.19 11:16:00.436 5: Notify loop for global ATTR PS1 verbose 5
2015.02.19 11:16:11.238 5: panStamp/RAW: /(
2015.02.19 11:16:11.240 5: panStamp/RAW: (/372F
2015.02.19 11:16:11.241 5: panStamp/RAW: (372F/)00
2015.02.19 11:16:11.242 5: panStamp/RAW: (372F)00/5C001200
2015.02.19 11:16:11.243 5: panStamp/RAW: (372F)005C001200/5C0C
2015.02.19 11:16:11.245 5: panStamp/RAW: (372F)005C0012005C0C/02D7
2015.02.19 11:16:11.246 5: panStamp/RAW: (372F)005C0012005C0C02D7/019D
2015.02.19 11:16:11.247 5: panStamp/RAW: (372F)005C0012005C0C02D7019D/

(372E
2015.02.19 11:16:11.247 5: PS1: 005C0012005C0C02D7019D -46.5 47
2015.02.19 11:16:11.247 5: PS1 dispatch 005C0012005C0C02D7019D
2015.02.19 11:16:11.260 4: BA_SENSOR_TEMP_HUM -> broadcast (0,0-12): status BA_SENSOR_TEMP_HUM 0C:02D7019D
2015.02.19 11:16:11.262 5: Triggering BA_SENSOR_TEMP_HUM (2 changes)
2015.02.19 11:16:11.262 5: Notify loop for BA_SENSOR_TEMP_HUM 0C.1-Humidity: 019D
2015.02.19 11:16:11.273 4: fhem_eventTypes: SWAP BA_SENSOR_TEMP_HUM 0C.1-Humidity: 019D -> 0C.*-Humidity: 019D
2015.02.19 11:16:11.273 4: fhem_eventTypes: SWAP BA_SENSOR_TEMP_HUM humidity: 41.3 -> humidity: .*
2015.02.19 11:16:11.278 5: panStamp/RAW: (372E/)005C0013005C0B0D2C


2015.02.19 11:16:11.278 5: PS1: 005C0013005C0B0D2C -46.5 46
2015.02.19 11:16:11.279 5: PS1 dispatch 005C0013005C0B0D2C
2015.02.19 11:16:11.279 4: BA_SENSOR_TEMP_HUM -> broadcast (0,0-13): status BA_SENSOR_TEMP_HUM 0B:0D2C
2015.02.19 11:16:11.281 5: Triggering BA_SENSOR_TEMP_HUM (2 changes)
2015.02.19 11:16:11.281 5: Notify loop for BA_SENSOR_TEMP_HUM 0B-Voltage: 0D2C
2015.02.19 11:16:11.292 4: fhem_eventTypes: SWAP BA_SENSOR_TEMP_HUM 0B-Voltage: 0D2C -> 0B-Voltage: 0D2C
2015.02.19 11:16:11.292 4: fhem_eventTypes: SWAP BA_SENSOR_TEMP_HUM voltage: 3.372 -> voltage: .*


2015.02.19 11:16:20.852 4: Connection closed for FHEMWEB:172.16.181.36:51876: EOF
2015.02.19 11:16:20.854 4: Connection accepted from FHEMWEB:172.16.181.36:51881
2015.02.19 11:16:20.855 4: HTTP FHEMWEB:172.16.181.36:51881 GET /fhem/desktop?detail=n_BA_HUM
2015.02.19 11:16:20.889 5: Cmd: >get fhem_eventTypes list<
2015.02.19 11:16:29.932 4: 4764:FHEMWEB:172.16.181.36:51881: /fhem/desktop?detail=n_BA_HUM / RL:20669 / text/html; charset=UTF-8 / Content-Encoding: gzip

/
2015.02.19 11:16:29.934 1: Perfmon: possible freeze starting at 11:16:21, delay is 8.933
2015.02.19 11:16:29.939 5: Cmd: >attr PS1 verbose 3<
2015.02.19 11:16:29.940 5: Triggering global (1 changes)
2015.02.19 11:16:29.940 5: Notify loop for global ATTR PS1 verbose 3
2015.02.19 11:16:29.952 5: Cmd: >attr global verbose 3<



fheminfo:

Code Auswählen Erweitern


Fhem info:
  Release  : 5.6
  OS       : linux
  Arch     : arm-linux-gnueabihf-thread-multi-64int
  Perl     : v5.18.2
  uniqueID : 5c0f8ffbb418146dac0e0c4a2a2a68ae
  upTime   : 00:34:45

Defined modules:
  CUL           : 1
  CUL_HM        : 165
  Dashboard     : 1
  DbLog         : 1
  FHEMWEB       : 3
  FileLog       : 1
  GEOFANCY      : 1
  HMLAN         : 1
  HMinfo        : 1
  HUEBridge     : 1
  HUEDevice     : 5
  LightScene    : 3
  OPENWEATHER   : 1
  PRESENCE      : 5
  Pushover      : 3
  RESIDENTS     : 1
  ROOMMATE      : 2
  SVG           : 13
  SWAP          : 3
  Weather       : 1
  XBMC          : 1
  YAMAHA_AVR    : 1
  at            : 9
  autocreate    : 1
  dummy         : 24
  eventTypes    : 1
  holiday       : 1
  notify        : 47
  panStamp      : 1
  readingsGroup : 11
  remotecontrol : 2
  structure     : 10
  telnet        : 1
  weblink       : 10

Defined models per module:
  CUL           : CUL
  CUL_HM        : ActionDetector,CCU-FHEM,HM-CC-RT-DN,HM-LC-1-FM,HM-LC-Bl1PBU-FM,HM-LC-DIM1T-FM,HM-LC-DIM2T-SM,HM-LC-Dim1PWM-CV,HM-LC-Dim1T-Pl-2,HM-LC-Dim1TPBU-FM,HM-LC-SW1-FM,HM-LC-SW1-PL2,HM-LC-SW2-FM,HM-LC-Sw1PBU-FM,HM-PB-2-WM55,HM-PB-6-WM55,HM-PBI-4-FM,HM-RC-4-2,HM-SEC-SC-2,HM-SEC-SCo
  HUEDevice     : LCT001,LST001
  YAMAHA_AVR    : DSP-Z7   


List eines verwendeten panStamp Sensors:

Code Auswählen Erweitern


Internals:
   CFGFN
   DEF        5C
   Developer  panStamp
   IODev      PS1
   LASTInputDev PS1
   MSGCNT     26
   NAME       SWAP_5C
   NR         2082
   PS1_LQI    45
   PS1_MSGCNT 26
   PS1_RAWMSG (092D)005C001B005C0B0126
   PS1_RSSI   -69.5
   PS1_TIME   2015-02-20 08:29:05
   Product    Dual Temperature/Humidity sensor
   STATE      set-statusRequest
   SWAP_00-ProductCode 0000000100000001
   SWAP_00.1-ManufacturerID 00000001
   SWAP_00.2-ProductID 00000001
   SWAP_01-HardwareVersion 00000200
   SWAP_02-FirmwareVersion 00000101
   SWAP_03-SystemState 02
   SWAP_04-FrequencyChannel 00
   SWAP_05-SecurityOption 00
   SWAP_06-SecurityPassword 00
   SWAP_07-SecurityNonce 0B
   SWAP_08-NetworkID B547
   SWAP_09-DeviceAddress 5C
   SWAP_0A-PeriodicTxInterval 003C
   SWAP_MISSED 0
   SWAP_Sent_unconfirmed 0 Sent_unconfirmed
   SWAP_lastRcv 2015-02-20 08:29:05
   SWAP_lastSend 2015-02-20 08:26:59
   SWAP_nonce 1B
   TYPE       SWAP
   addr       5C
   devices
   Readings:
     2015-02-20 08:29:05   0B-Voltage      0126
     2015-02-20 08:29:05   0C.0-Temperature 01F4
     2015-02-20 08:29:05   0C.1-Humidity   0000
     2015-02-20 08:29:05   humidity        0
     2015-02-20 08:26:59   state           set-statusRequest
     2015-02-20 08:29:05   temperature     0
     2015-02-20 08:29:05   voltage         0.294
   Product:
     label      Dual Temperature/Humidity sensor
     name       temphum
     pwrdownmode 1
     Registers:
       11:
         hwmask
         name       Voltage supply
         swversion
         type       regular
         endpoints:
           HASH(0x1f3b788)
       12:
         hwmask
         name       Humidity and Temperature
         swversion
         type       regular
         endpoints:
           HASH(0x1f58438)
           HASH(0x1f374e8)
   sentList:
Attributes:
   IODev      PS1
   ProductCode 0000000100000001
   room       SWAP
   userReadings voltage:0B-Voltage {hex(ReadingsVal($name,"0B-Voltage","0"))*0.001}, temperature:0C.0-Temperature {hex(ReadingsVal($name,"0C.0-Temperature","0"))*0.1-50}, humidity:0C.1-Humidity {hex(ReadingsVal($name,"0C.1-Humidity","0"))*0.1}
   



Gruss Uli

[rudolfkoenig]

Hat jemand eine Idee wie das Problem zu lösen ist?

Vermutlich durch eine Zusammenarbeit zwischen Modulhersteller und mir (eventTypes Maintainer). Die Module produzieren events, was eventTypes nicht ausreichend verdichten kann.  Ich habe z.Bsp. die Vermutung, dass diverse Module Rohdaten (hex oder gar binaer) als event zur Verfuegung stellen, was mAn falsch ist.

Dazu muesste man aber die grossen eventTypes Datei studieren, um zu wissen, wer was aendern muss.
Meine Datei ist nach ueber ein Jahr am sammeln und 150 Geraeten 33k gross, was ich fuer vertretbar halte.

[dev0]

Meine ca. 1 Jahr alte eventTypes.txt war Anfang Januar 550kB groß und wuchst seitdem um ca. 90kB pro Monat. Eine neu erzeugte eventType.txt hatte jetzt gerade, nach 10 Minuten Betrieb und einem Restart, eine Größe von 20kB. Der beschriebene Effekt tritt dabei noch nicht auf.

Aber selbst, wenn die Datei 700kB gross ist tritt das Problem wirklich erst dann auf, sobald Daten eines panStamps von FHEM verarbeitet werden. Vorher nicht. Daher vermute ich, dass es nicht nur mit der Größe (EDIT: oder Inhalt) zusammen hängt.

Gruß Uli

[dev0]

Ich kann auch gerne versuchen den Inhalt meiner eventTypes.txt zu analysieren oder euch bereitstellen, wenn das hilft. Zur Analyse müsste ich nur wissen worauf ich denn achten muss.

[rudolfkoenig]

Gar nichts, wenn es gefuehlt "zu gross" ist, hier (komprimiert) anhaengen.

[dev0]

Anbei die eventType.txt

[rudolfkoenig]

Kannst du bitte noch eine Liste von Name/Typ hier anhaengen (generiert z.Bsp. mit awk '/^define/{print $2,$3}' fhem.cfg)

Manche Module missbrauchen das Konzept, z.Bsp. GA_LS/WZ_LS erzeugt Events mit betraechtlichen HTML-Inhalt.
Vermutlich muss ich gegen sowas zentral vorgehen.

[dev0]

.*_LS sind LightScenes. Anbei die Liste der Namen/Typen.

[rudolfkoenig]

Ich habe den Event-Filter bzw. "Zusammenfasser" in eventTypes.pm erweitert, in deinem Fall spart das ueber 90%.
Falls die Datei wieder stark anwachsen sollte, bitte melden.

[dev0]

Vielen Dank für das schnelle Eingreifen.

[dev0]

Falls die Datei wieder stark anwachsen sollte, bitte melden.

Mittlerweile ist die eventTypes.txt wieder auf gut 200kB angewachsen. Auffällig finde ich die Einträge der folgeden Devices:
- HUEDevice (RGB Werte)
- CUL_HM (Taster, Long press)
- iTunes (Tracks/Alben)

Vielleicht magst Du ja noch einmal schauen?
Anbei: eventTypes.txt und types.txt

[rudolfkoenig]

Du hast ja immerhin 550 Definitionen, das macht 10 Event-Zeilen pro Definition, das finde ich ideal. Bei iTunes habe ich nichts geaendert (immerhin ist die Anzahl der Zeilen auf 201 begrenzt), Hue und HM habe ich angepasst, macht bei dir ca 20% Ersparsnis. Hast du eine Ahnung, was Zahl_Zahl bei HM Long/LongRelease bedeutet?

[dev0]

Wenn ein HM Taster z.B zum Dimmen länger gedrückt wird, dann wird ca. alle 250ms ein Event ausgelöst:

2015-06-10 12:24:35.657 CUL_HM ST_TA1_B1 Long 1_12 (to ST_LI_TVS_L_DEV)
2015-06-10 12:24:35.923 CUL_HM ST_TA1_B1 Long 2_12 (to ST_LI_TVS_L_DEV)
2015-06-10 12:24:36.192 CUL_HM ST_TA1_B1 Long 3_12 (to ST_LI_TVS_L_DEV)

Bei erneuter Auslösung wird die 2. Zahl um 1 erhöht:

2015-06-10 12:28:55.192 CUL_HM ST_TA1_B1 Long 1_13 (to ST_LI_TVS_L_DEV)
2015-06-10 12:28:55.451 CUL_HM ST_TA1_B1 Long 2_13 (to ST_LI_TVS_L_DEV)
2015-06-10 12:28:55.719 CUL_HM ST_TA1_B1 Long 3_13 (to ST_LI_TVS_L_DEV)