FHEM Start dauert 3-4 min

[AndreR]

Hallo,

ich habe seit ca 2 Wochen - jedenfalls ist es mir da aufgefallen.. - das Phänomen dass das Starten des FHEM etwas über 3 Minuten dauert. Und mir fehlt so ein wenig die Idee, warum. Das Log ist leider nicht sehr aussagekräftig:

Code Auswählen Erweitern


2015.01.19 15:24:34 0: Server shutdown
2015.01.19 15:24:44 2: Perfmon: ready to watch out for delays greater than one second
2015.01.19 15:24:44 1: Including fhem.cfg
2015.01.19 15:24:45 3: telnetPort: port 7072 opened
2015.01.19 15:24:45 3: WEB: port 8083 opened
2015.01.19 15:24:45 3: WEBphone: port 8084 opened
2015.01.19 15:24:45 3: WEBtablet: port 8085 opened
2015.01.19 15:24:48 2: eventTypes: loaded 6605 events from ./log/eventTypes.txt
2015.01.19 15:24:49 3: Opening CUL device /dev/ttyACM0
2015.01.19 15:24:49 3: Setting CUL baudrate to 9600
2015.01.19 15:24:49 3: CUL device opened
2015.01.19 15:24:49 3: CUL: Possible commands: BbCFiAZEGMKUYRTVWXefmltux
2015.01.19 15:24:52 3: Opening Telefon device 10.0.20.1:1012
2015.01.19 15:24:52 3: Telefon device opened
2015.01.19 15:24:52 2: FB_CALLMONITOR (Telefon) - found FritzBox phonebook /opt/fhem/phonebook
2015.01.19 15:24:52 2: FB_CALLMONITOR (Telefon) - read 3 contacts from /opt/fhem/phonebook
2015.01.19 15:24:55 3: Opening fbaha device 10.0.20.1:2002
2015.01.19 15:24:55 3: fbaha device opened
2015.01.19 15:24:55 1: FBAHA fbaha registered with handle: 0000000b
2015.01.19 15:28:27 1: HMLAN_Parse: hmlan1 new condition disconnected
2015.01.19 15:28:27 3: Opening hmlan1 device 10.0.20.21:1000
2015.01.19 15:28:27 3: hmlan1 device opened
2015.01.19 15:28:27 1: HMLAN_Parse: hmlan1 new condition init
2015.01.19 15:28:32 1: Including ./log/fhem.save
2015.01.19 15:28:35 1: usb create starting
2015.01.19 15:28:37 3: Probing CUL device /dev/ttyAMA0
2015.01.19 15:28:37 3: Can't open /dev/ttyAMA0: Permission denied
2015.01.19 15:28:37 1: usb create end
2015.01.19 15:28:37 2: SecurityCheck:  WEB,WEBphone,WEBtablet has no basicAuth attribute. telnetPort has no password/globalpasswor                                                                                                           d attribute.  Restart FHEM for a new check if the problem is fixed, or set the global attribute motd to none to supress this messa                                                                                                           ge.
2015.01.19 15:28:37 0: Server started with 185 defined entities (version $Id: fhem.pl 7609 2015-01-17 21:37:05Z rudolfkoenig $, os                                                                                                            linux, user fhem, pid 2935)
2015.01.19 15:28:37 1: Perfmon: possible freeze starting at 15:24:45, delay is 232.677


Das ganze passiert sowohl über das

Code Auswählen Erweitern

/etc/init.d/fhem start, als auch über

Code Auswählen Erweitern

perl /opt/fhem/fhem.pl /opt/fhem/fhem.cfg und im FHEM mittels

Code Auswählen Erweitern

shutdown restart

Ich kann mich nicht erinnern, irgendeine großartige Änderung eingespielt zu haben, als das auftrat. Bemerkt habe ich es, als nach einem Update das Shutdown restart so lange dauerte, habe es aber als einmalige Sache abgeschoben. ALs ich heute wegen Änderungen am Callmonitor neu geupdated habe, fiel es mir wieder auf und ich konnte es nachstellen.

Was kann ich tun?

[Wernieman]

Bin jetzt kein Spezialist, aber auffällig ist:

Code Auswählen Erweitern

2015.01.19 15:24:55 1: FBAHA fbaha registered with handle: 0000000b
2015.01.19 15:28:27 1: HMLAN_Parse: hmlan1 new condition disconnected

Genau da vergehen 4 Minuten .... hast Du ein Problem mit HMLAN?

[strauch]

Ich glaube eher das die Fritzbox abfrage (FBAHA) solange dauert. Bis dahin ist der HMLAN disconected, weil FHEM blockiert ist, deswegen kommt anschließend die Meldung.

[Dietmar63]

Mit attr global verbose 5 kannst du das Problem vielleicht besser einkreisen

[AndreR]

Interessant,
auch in verbose 5 hängt er die 4 Minuten, und zwar an genau dieser Stelle:
2015.01.20 08:05:27 5: Loading ./FHEM/57_Calendar.pm
2015.01.20 08:05:28 4: Calendar Kalender_Lia: Wakeup
2015.01.20 08:05:28 4: Calendar Kalender_Lia: Updating...
2015.01.20 08:05:28 4: HttpUtils url=<hidden>
2015.01.20 08:05:33 4: <hidden>: HTTP response code 200
2015.01.20 08:05:33 4: HttpUtils <hidden>: Got data, length: 531995
2015.01.20 08:08:45 5: Next time of XXXX is: start 09.01.2016 00:00:00, end 10.01.2016 00:00:00
2015.01.20 08:08:45 5: Next time of XXXX Geburtstag is: start 26.12.2012 00:00:00, end 27.12.2012 00:00:00

Da ich den Kalender erstmal nur zu Testzwecken hatte (richtige Integration folgt noch) deaktivierte ich das mal und siehe da: er startet wieder korrekt

Code Auswählen Erweitern

2015.01.20 08:14:02 1: Including fhem.cfg
2015.01.20 08:14:02 3: telnetPort: port 7072 opened
2015.01.20 08:14:03 3: WEB: port 8083 opened
2015.01.20 08:14:03 3: WEBphone: port 8084 opened
2015.01.20 08:14:04 3: WEBtablet: port 8085 opened
2015.01.20 08:14:06 2: eventTypes: loaded 6702 events from ./log/eventTypes.txt
2015.01.20 08:14:07 3: Opening CUL device /dev/ttyACM0
2015.01.20 08:14:07 3: Setting CUL baudrate to 9600
2015.01.20 08:14:07 3: CUL device opened
2015.01.20 08:14:07 3: CUL: Possible commands: BbCFiAZEGMKUYRTVWXefmltux
2015.01.20 08:14:10 3: Opening Telefon device 10.0.20.1:1012
2015.01.20 08:14:10 3: Telefon device opened
2015.01.20 08:14:10 2: FB_CALLMONITOR (Telefon) - found FritzBox phonebook /opt/fhem/phonebook
2015.01.20 08:14:10 2: FB_CALLMONITOR (Telefon) - read 3 contacts from /opt/fhem/phonebook
2015.01.20 08:14:13 3: Opening fbaha device 10.0.20.1:2002
2015.01.20 08:14:13 3: fbaha device opened
2015.01.20 08:14:13 1: FBAHA fbaha registered with handle: 0000000e
2015.01.20 08:14:14 1: HMLAN_Parse: hmlan1 new condition disconnected
2015.01.20 08:14:14 3: Opening hmlan1 device 10.0.20.21:1000
2015.01.20 08:14:14 3: hmlan1 device opened
2015.01.20 08:14:14 1: HMLAN_Parse: hmlan1 new condition init
2015.01.20 08:14:19 1: Including ./log/fhem.save
2015.01.20 08:14:20 1: usb create starting
2015.01.20 08:14:22 3: Probing CUL device /dev/ttyAMA0
2015.01.20 08:14:22 3: Can't open /dev/ttyAMA0: Permission denied
2015.01.20 08:14:22 1: usb create end
2015.01.20 08:14:22 2: SecurityCheck:  WEB,WEBphone,WEBtablet has no basicAuth attribute. telnetPort has no password/globalpassword attribute.  Restart FHEM for a new check if the problem is fixed, or set the global attribute motd to none to supress this message.
2015.01.20 08:14:22 0: Server started with 184 defined entities (version $Id: fhem.pl 7609 2015-01-17 21:37:05Z rudolfkoenig $, os linux, user fhem, pid 24888)
2015.01.20 08:14:22 1: Perfmon: possible freeze starting at 08:14:03, delay is 19.613
2015.01.20 08:14:24 1: HMLAN_Parse: hmlan1 new condition ok
2015.01.20 08:14:24 1: Perfmon: possible freeze starting at 08:14:23, delay is 1.141


Ist der Kalender "zu voll"?

[der-Lolo]

der Perforcemancemonitor und apptime hilft dir sicherlich bei der Analyse...