Performance Probleme auf BBB

[limats]

Hallo zusammen,

ich hab ein Performance-Problem, das ich nicht analysiert bekomme:
Mein Fhem läuft unter Wheezy auf einem BeagleBoneBlack.
Normalerweise liegt die Load bei ca. 0,1. Perfmon verhält sich ruhig und meckert nur gelegentlich Außreißer zwischen 1 und 2 Sekunden an, von denen ich weiß woher sie kommen.

ABER:
Ca. 1-2 mal pro Tag (vorzugsweise nachts) steigt die Load auf Werte zwischen 2 und 7. Wenn ich es zufällig mit top einfangen kann, ist der "si" Wert sehr hoch. Im fhem.log habe ich dann Perfmon-Zeilen von bis zu 350 Sekunden. Im Log sind trotzdem noch unterschiedliche Ausgaben zu finden. Fhem hat also nicht einen klassischen Hänger, sondern ist einfach überlastet.
Nach einiger Zeit beruhigt sich das System wieder und alles ist wieder gut.

So richtig konnte ich bis jetzt kein Modul für verantwortlich machen. Ich hab das Gefühl, dass sich das Problem durch das Hochdrehen des Loggings verschlimmert. Ist aber eigentlich auch logisch, da dann während der Starklast-Zeit auch noch viele Schreibzugriffe auf die SD dazukommen.

Hat mir irgendwer einen Tipp, wie ich zielgerichtet analysieren kann bzw. an was das Problem hängen könnte?

Viele Grüße
Leo

[betateilchen]

Als erstes würde ich fhem über nacht deaktivieren um festzustellen, ob die Last wirklich von fhem kommt oder ob nicht das Betriebssystem irgendwas im Hintergrund tut.

[Wernieman]

Außerdem nicht nur die load, sondern auch cpu, iound speicherwerte loggen ... load ist eigentlich ein "schlechter Hinweis" ...

[limats]

Habt ihr eine Empfehlung für ein leichtgewichtiges Logging der Parameter? Will den BBB jetzt nicht noch mit einem fetten Monitoring überfordern.
Hab mir bisher mit einem umgeleitetem "top" beholfen. Aber das erzeugt extrem große Files und ist außerdem eine echte Qual bei der Auswertung.

[Wernieman]

Leichtgewichtig wäre ein einfacher Cronjob, oder alternativ direkt iostat, vmstat o.Ä.

Kleiner Hinweis wegen CPU-Belastung:
http://www.linuxhowtos.org/System/procstat.htm

[limats]

Hallo zusammen,

habe noch ein paar Versuche gemacht.
Ohne Fhem konnte ich die Ausreißer nicht reproduzieren.
Mit Fhem hab ich jetzt aber mal einen Mitschrieb:

Ziemlich genau um 21:20:24 beginnt er zu spinnen.
Der Spuk dauert bis 21:41:34 - also gut über eine Stunde!
Wie man am dstat-Mitschrieb gut erkennen kann, war das System so ausgelastet, dass dstat teilweise nur 1x pro Minute zum Zug kam, obwohl das Intervall eigentlich auf 5 Sekunden eingestellt war.

Hier das fhem.log im fraglichen Zeitraum (verbose 4):

Code Auswählen Erweitern


2015.12.15 21:20:13.095 4: Ignoring CUL_TX_31
2015.12.15 21:20:13.103 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:13.104 4: Ignoring IT_1111111111
2015.12.15 21:20:13.115 4: Ignoring Unknown
2015.12.15 21:20:13.133 4: Ignoring CUL_TX_31
2015.12.15 21:20:13.136 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:13.137 4: Ignoring IT_1111111111
2015.12.15 21:20:13.141 4: Ignoring Unknown
2015.12.15 21:20:13.293 4: Ignoring CUL_TX_31
2015.12.15 21:20:13.296 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:13.297 4: Ignoring IT_1111111111
2015.12.15 21:20:13.301 4: Ignoring Unknown
2015.12.15 21:20:13.314 4: Ignoring CUL_TX_31
2015.12.15 21:20:13.317 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:13.318 4: Ignoring IT_1111111111
2015.12.15 21:20:13.322 4: Ignoring Unknown
2015.12.15 21:20:13.406 4: HourCounter CN.Pellets Run.729 tickChanged fired
2015.12.15 21:20:13.406 4: HourCounter CN.Pellets ExecQueue.130 cnt: -1
2015.12.15 21:20:16.350 4: BlockingCall (PRESENCE_DoLocalPingScan) created child (30856), uses telnetForBlockingFn to connect back
2015.12.15 21:20:18.032 4: CUL_Parse: nanocul omAAAAE8
2015.12.15 21:20:19.554 4: Connection accepted from telnet:127.0.0.1:46838
2015.12.15 21:20:19.597 4: PRESENCE (SamsungTV) - rescheduling next check in 10 seconds
2015.12.15 21:20:22.974 4: WW: GetUpdate called (update)
2015.12.15 21:20:22.975 5: WW: internal interval timer set to call GetUpdate again in 600 seconds
2015.12.15 21:20:22.976 5: WW: AddToQueue called, initial send queue length : 0
2015.12.15 21:20:22.976 5: WW: AddToQueue adds type Update to URL http://www.wellinger-wetter.de/index.php?a=wetter, data , header
2015.12.15 21:20:22.977 5: WW: HandleSendQueue called, qlen = 1
2015.12.15 21:20:22.978 4: WW: HandleSendQueue sends request type Update to URL http://www.wellinger-wetter.de/index.php?a=wetter, data , header , timeout 5
2015.12.15 21:20:22.979 4: HttpUtils url=http://www.wellinger-wetter.de/index.php?a=wetter
2015.12.15 21:20:22.999 4: BlockingCall (VBUS_FetchData) created child (30858), uses telnetForBlockingFn to connect back
2015.12.15 21:20:23.002 3: myVBUSDevice: Beende nun Eltern-Prozess
2015.12.15 21:20:23.060 3: myVBUSDevice Ich bin das Kind! Debug: Host:[192.168.1.8] Port:[7053]
2015.12.15 21:20:23.072 3: myVBUSDevice: Try 0 Find beginning
2015.12.15 21:20:23.110 3: myVBUSDevice: Try 0 Find end aa100021741000010f3a16000a
2015.12.15 21:20:23.111 3: myVBUSDevice: Try 0 Find end aa100021741000010f3a16000a01005e4f02640005453822087c0d147158087c0f237158000003330b000000007400000000007f38291b00020100000000007f00000000007f00000000007f00000000007f640a
2015.12.15 21:20:23.111 3: myVBUSDevice: Try 0 Find end aa100021741000010f3a16000a01005e4f02640005453822087c0d147158087c0f237158000003330b000000007400000000007f38291b00020100000000007f00000000007f00000000007f00000000007f640a1400007d4900390501772f7b33010120aa000021742000050000000000000045aa15002174100001073d01080000007600000000007f020a
2015.12.15 21:20:23.112 3: myVBUSDevice: Found end
2015.12.15 21:20:23.113 3: myVBUSDevice: Src: 2174 Dst: 1000 Proto: 10 CMD: 0001 FC: 15 CRC: 58
2015.12.15 21:20:23.115 3: myVBUSDevice Beende das Kind erfolreich...
2015.12.15 21:20:23.126 4: Connection accepted from telnet:127.0.0.1:46841
2015.12.15 21:20:23.142 3: VBUS_DecodeData: Starte Auswertung!
2015.12.15 21:20:23.143 3: VBUS_DecodeData: name=[myVBUSDevice]
2015.12.15 21:20:23.144 3: VBUS_DecodeData: hash=[HASH(0x1d04240)]
2015.12.15 21:20:23.144 3: VBUS_DecodeData: payload=[16000a01cf02e400b82288fcf1d888fcf1d800000b0000000000000038a91b0000000000000000000000000000000000640a1400c9003905af7b3301]
2015.12.15 21:20:23.145 4: myVBUSDevice: Temperature collector                2.2 (Celsius)
2015.12.15 21:20:23.145 4: myVBUSDevice: Temperature tank bottom              26.6 (Celsius)
2015.12.15 21:20:23.146 4: myVBUSDevice: Temperature sensor 3                 71.9 (Celsius)
2015.12.15 21:20:23.146 4: myVBUSDevice: Temperature return energy metering   22.8 (Celsius)
2015.12.15 21:20:23.146 4: myVBUSDevice: Operating hours relay 1               503.553333333333 (h)
2015.12.15 21:20:23.147 4: myVBUSDevice: Heat quantity                         1313.38 (kWh)
2015.12.15 21:20:23.147 4: myVBUSDevice: PWM 1                                 0 (%)
2015.12.15 21:20:23.147 4: myVBUSDevice: Speed relay 1                         0 (%)
2015.12.15 21:20:23.514 3: myVBUSDevice: VBUS TKOL: 2.2 TSPU: 26.6 S3: 71.9 TRLWZ: 22.8 N1: 0 PWM1: 0
2015.12.15 21:20:23.581 4: BlockingCall (SYSMON_blockingCall) created child (30859), uses telnetForBlockingFn to connect back
2015.12.15 21:20:23.657 4: HourCounter CN.Pellets Run.657 rising edge; pauseTimeIncr:11 countPerDay:718
2015.12.15 21:20:23.693 4: statistics statisticsHH: doStatisticDelta.672 Calculating delta statistics for 'CN.Pellets:pelletsOverall = 1467.4539'
2015.12.15 21:20:23.969 4: statistics statisticsHH: doStatisticDelta.672 Calculating delta statistics for 'CN.Pellets:pelletsOverall = 1467.4539'
2015.12.15 21:20:23.975 4: CN.Pellets_notify exec delete CN.Pellets_at; define CN.Pellets_at at +00:02:30 { fhem("trigger CN.Pellets countsOverall") }
2015.12.15 21:20:24.014 4: Ignoring CUL_TX_31
2015.12.15 21:20:24.017 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:24.038 4: Ignoring IT_1111111111
2015.12.15 21:20:24.043 4: Ignoring Unknown
2015.12.15 21:20:24.072 4: Ignoring CUL_TX_31
2015.12.15 21:20:24.075 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:24.075 4: Ignoring IT_1111111111
2015.12.15 21:20:24.088 4: Ignoring Unknown
2015.12.15 21:20:24.391 4: Ignoring CUL_TX_31
2015.12.15 21:20:24.393 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:24.394 4: Ignoring IT_1111111111
2015.12.15 21:20:24.397 4: Ignoring Unknown
2015.12.15 21:20:24.431 4: Ignoring CUL_TX_31
2015.12.15 21:20:24.433 4: Ignoring IT_0010110011110011101100011010000
2015.12.15 21:20:24.434 4: Ignoring IT_1111111111
2015.12.15 21:20:24.437 4: Ignoring Unknown
2015.12.15 21:20:24.518 4: HourCounter CN.Pellets Run.729 tickChanged fired
2015.12.15 21:20:24.519 4: HourCounter CN.Pellets ExecQueue.130 cnt: -1
2015.12.15 21:20:24.543 4: Connection accepted from telnet:127.0.0.1:46842
2015.12.15 21:20:29.016 1: Perfmon: possible freeze starting at 21:20:25, delay is 3.995


/proc/interrupts um 21:36

Code Auswählen Erweitern


           CPU0       
23:          2      INTC   7  tps65217
28:      64384      INTC  12  edma
30:        506      INTC  14  edma_error
33:  286795940      INTC  17  47400000.dma-controller
34:          0      INTC  18  musb-hdrc.0.auto
35:    1011209      INTC  19  musb-hdrc.1.auto
36:          0      INTC  20  4a300000.pruss
37:          0      INTC  21  4a300000.pruss
38:          0      INTC  22  4a300000.pruss
39:          0      INTC  23  4a300000.pruss
40:          0      INTC  24  4a300000.pruss
41:          0      INTC  25  4a300000.pruss
42:          0      INTC  26  4a300000.pruss
43:          0      INTC  27  4a300000.pruss
44:     150322      INTC  28  mmc1
46:          0      INTC  30  4819c000.i2c
52:          0      INTC  36  tilcdc
56:          0      INTC  40  4a100000.ethernet
57:    1670546      INTC  41  4a100000.ethernet
58:     875193      INTC  42  4a100000.ethernet
59:          0      INTC  43  4a100000.ethernet
80:     150107      INTC  64  mmc0
84:   12891797      INTC  68  gp_timer
86:    3722013      INTC  70  44e0b000.i2c
88:        265      INTC  72  OMAP UART0
91:          0      INTC  75  rtc0
92:          0      INTC  76  rtc0
93:          0      INTC  77  wkup_m3
94:          1      INTC  78  wkup_m3_txev
125:          0      INTC 109  53100000.sham
127:          0      INTC 111  48310000.rng
150:          0  44e07000.gpio   6  mmc0
IPI0:          0  CPU wakeup interrupts
IPI1:          0  Timer broadcast interrupts
IPI2:          0  Rescheduling interrupts
IPI3:          0  Function call interrupts
IPI4:          0  Single function call interrupts
IPI5:          0  CPU stop interrupts
IPI6:          0  IRQ work interrupts
IPI7:          0  completion interrupts
Err:          0


und 2 Minuten später um 21:38:

Code Auswählen Erweitern


           CPU0       
23:          2      INTC   7  tps65217
28:      64415      INTC  12  edma
30:        506      INTC  14  edma_error
33:  286866066      INTC  17  47400000.dma-controller
34:          0      INTC  18  musb-hdrc.0.auto
35:    1011443      INTC  19  musb-hdrc.1.auto
36:          0      INTC  20  4a300000.pruss
37:          0      INTC  21  4a300000.pruss
38:          0      INTC  22  4a300000.pruss
39:          0      INTC  23  4a300000.pruss
40:          0      INTC  24  4a300000.pruss
41:          0      INTC  25  4a300000.pruss
42:          0      INTC  26  4a300000.pruss
43:          0      INTC  27  4a300000.pruss
44:     150417      INTC  28  mmc1
46:          0      INTC  30  4819c000.i2c
52:          0      INTC  36  tilcdc
56:          0      INTC  40  4a100000.ethernet
57:    1670790      INTC  41  4a100000.ethernet
58:     875267      INTC  42  4a100000.ethernet
59:          0      INTC  43  4a100000.ethernet
80:     150167      INTC  64  mmc0
84:   12899201      INTC  68  gp_timer
86:    3722034      INTC  70  44e0b000.i2c
88:        265      INTC  72  OMAP UART0
91:          0      INTC  75  rtc0
92:          0      INTC  76  rtc0
93:          0      INTC  77  wkup_m3
94:          1      INTC  78  wkup_m3_txev
125:          0      INTC 109  53100000.sham
127:          0      INTC 111  48310000.rng
150:          0  44e07000.gpio   6  mmc0
IPI0:          0  CPU wakeup interrupts
IPI1:          0  Timer broadcast interrupts
IPI2:          0  Rescheduling interrupts
IPI3:          0  Function call interrupts
IPI4:          0  Single function call interrupts
IPI5:          0  CPU stop interrupts
IPI6:          0  IRQ work interrupts
IPI7:          0  completion interrupts
Err:          0


Ich kann es mir echt nicht erklären. Wär klasse, wenn mir jemand einen Tipp hätte...

Gruß
Leo

[Wernieman]

1. Das sind 20 Minuten und keine Stunde (21:20 bis 21:4X)
2. Das Netz geht hoch ... hat jemand z.B. angefangen zu spielen? Würde mal suchen, ob in der der Zeit etwas in Deinem Homenetz los war
3. Die IRQs gehen um den Faktor 10 hoch .... wenn 2. Nichts ergibt, könnte im Funk Bereich was los sein?

[betateilchen]

Zu 2 fällt mir spontan ein beliebtes und oft vergessenes Gimmick ein: Mac TimeMachine Backup im Netzwerk

Was passiert eigentlich hier? Wer oder was baut hier die telnet Verbindung auf, denn danach beginnen offenbar die Probleme.

Code Auswählen Erweitern

2015.12.15 21:20:24.543 4: Connection accepted from telnet:127.0.0.1:46842

[limats]

Zu 2 fällt mir spontan ein beliebtes und oft vergessenes Gimmick ein: Mac TimeMachine Backup im Netzwerk

Was passiert eigentlich hier? Wer oder was baut hier die telnet Verbindung auf, denn danach beginnen offenbar die Probleme.

Code Auswählen Erweitern

2015.12.15 21:20:24.543 4: Connection accepted from telnet:127.0.0.1:46842

Gute Frage. Muss irgendein NonBlocking-Job sein. Sonst verbindet sich bei mir nichts per Telnet mit Fhem (sollte zumindest).
Kriege ich aus der Port-Nummer irgendwie die Zuordnung zum öffnenden Logging-Eintrag hin? (z.B.)

Code Auswählen Erweitern


2015.12.15 21:20:16.350 4: BlockingCall (PRESENCE_DoLocalPingScan) created child (30856), uses telnetForBlockingFn to connect back


Das mit dem Netzwerk verstehe ich nicht ganz. Kann sein, dass ich in diesem Fall ziemlich zeitgleich begonnen hab, mit dem FireTV-Stick fernzusehen. Das geht natürlich auf das Netzwerk, sollte aber ja komplett am BBB vorbeigehen.

[Wernieman]

sollte aber ja komplett am BBB vorbeigehen

"sollte" ist aber nicht "geht" vorbei

Und eben laut Log, hast Du Netzwerktrafik am BBB. Hast Du ein Geswitschtes oder ein Hub-Netz? WLAN oder Kabel??

[limats]

Konnte das Problem auf meinen nanoCUL einschränken.
Hab deshalb im dortigen Unterforum einen neuen Thread aufgemacht: http://forum.fhem.de/index.php/topic,47299.0.html