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
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.
Außerdem nicht nur die load, sondern auch cpu, iound speicherwerte loggen ... load ist eigentlich ein "schlechter Hinweis" ...
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.
Leichtgewichtig wäre ein einfacher Cronjob, oder alternativ direkt iostat, vmstat o.Ä.
Kleiner Hinweis wegen CPU-Belastung:
http://www.linuxhowtos.org/System/procstat.htm
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):
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
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:
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
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?
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.
2015.12.15 21:20:24.543 4: Connection accepted from telnet:127.0.0.1:46842
Zitat von: betateilchen am 17 Dezember 2015, 09:40:44
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.
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.)
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.
Zitatsollte 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??
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