gelöst: Knapp zwei Minuten Pause bei Start von FHEM

[aeronaut]

Moin moin

seit FHEM vom Raspi mit COC auf einen Beaglebone Black mit CUL umgezogen ist, habe ich bei Start von FHEM ca. 2 Minuten Kaffeepause. Um der Sache auf den Grund zu gehen habe ich Perfmon aktiviert und das Loglevel hochgeschraubt.

Hier ein Restart im Log:

Code Auswählen Erweitern

2014.04.17 17:58:44 5: Cmd: >shutdown restart<
2014.04.17 17:58:44 5: Triggering global (1 changes)
2014.04.17 17:58:44 5: Notify loop for global SHUTDOWN
2014.04.17 17:58:44 0: Server shutdown
2014.04.17 17:58:44 4: CUL_send:  CULX0 0     
2014.04.17 17:58:44 0: Strange call for typeless Systemstatus : ShutdownFn
2014.04.17 17:58:44 4: owo wettermap: shutdown requested
2014.04.17 17:58:46 1: Including fhem.cfg
2014.04.17 17:58:46 5: Cmd: >attr global autoload_undefined_devices 1<
2014.04.17 17:58:46 5: Cmd: >attr global logfile ./log/fhem-%Y-%m.log<
2014.04.17 17:58:46 5: Cmd: >attr global modpath .<
2014.04.17 17:58:46 5: Loading ./FHEM/99_RPiUtils.pm
2014.04.17 17:58:46 5: Loading ./FHEM/99_SUNRISE_EL.pm
2014.04.17 17:58:46 5: Loading ./FHEM/99_Utils.pm
2014.04.17 17:58:46 5: Loading ./FHEM/99_myUtils.pm
2014.04.17 17:58:47 5: Loading ./FHEM/99_perfmon.pm
2014.04.17 17:58:47 2: Perfmon: ready to watch out for delays greater than one second
2014.04.17 17:58:47 5: Cmd: >attr global room Testraum<
2014.04.17 17:58:47 5: Cmd: >attr global sendStatistics onUpdate<
2014.04.17 17:58:47 5: Cmd: >attr global statefile ./log/fhem.save<
2014.04.17 17:58:47 5: Cmd: >attr global uniqueID ./FHEM/FhemUtils/uniqueID<
2014.04.17 17:58:47 5: Cmd: >attr global updateInBackground 1<
2014.04.17 17:58:47 5: Cmd: >attr global userattr devStateIcon devStateStyle fp_Grundriss icon sortby webCmd<
2014.04.17 17:58:47 5: Cmd: >attr global verbose 5<
2014.04.17 17:58:47 5: Cmd: >define telnetPort telnet 7072 global<
2014.04.17 17:58:47 5: Loading ./FHEM/98_telnet.pm
2014.04.17 17:58:47 3: telnetPort: port 7072 opened
2014.04.17 17:58:47 5: Cmd: >attr telnetPort allowfrom 192.168.10.(1|55)|127.0.0.1<
2014.04.17 17:58:47 5: Cmd: >attr telnetPort globalpassword ERSETZT<
2014.04.17 17:58:47 5: Cmd: >attr telnetPort room Serverraum<
2014.04.17 17:58:47 5: Cmd: >define WEB FHEMWEB 8083 global<
2014.04.17 17:58:47 5: Loading ./FHEM/01_FHEMWEB.pm
2014.04.17 17:58:47 3: WEB: port 8083 opened
2014.04.17 17:58:47 5: Cmd: >attr WEB HTTPS 1<
2014.04.17 17:58:47 5: Cmd: >attr WEB basicAuth ERSETZT<
2014.04.17 17:58:47 5: Cmd: >attr WEB basicAuthMsg It's me, Mario!<
2014.04.17 17:58:47 5: Cmd: >attr WEB hiddenroom DashboardRoom<
2014.04.17 17:58:47 5: Cmd: >attr WEB longpoll 1<
2014.04.17 17:58:47 5: Cmd: >attr WEB stylesheetPrefix dark<
2014.04.17 17:58:47 5: Cmd: >define WEBphone FHEMWEB 8084 global<
2014.04.17 17:58:47 3: WEBphone: port 8084 opened
2014.04.17 17:58:47 5: Cmd: >attr WEBphone HTTPS 1<
2014.04.17 17:58:47 5: Cmd: >attr WEBphone basicAuth ERSETZT<
2014.04.17 17:58:47 5: Cmd: >attr WEBphone basicAuthMsg It's me, Mario!<
2014.04.17 17:58:47 5: Cmd: >attr WEBphone hiddenroom DashboardRoom<
2014.04.17 17:58:47 5: Cmd: >attr WEBphone longpoll 1<
2014.04.17 17:58:47 5: Cmd: >attr WEBphone stylesheetPrefix smallscreen<
2014.04.17 17:58:47 5: Cmd: >define Logfile FileLog ./log/fhem-%Y-%m.log fakelog<
2014.04.17 17:58:47 5: Loading ./FHEM/92_FileLog.pm
2014.04.17 17:58:47 5: Cmd: >define autocreate autocreate<
2014.04.17 17:58:47 5: Loading ./FHEM/98_autocreate.pm
2014.04.17 17:58:47 5: Cmd: >attr autocreate autosave 1<
2014.04.17 17:58:47 5: Cmd: >attr autocreate device_room %TYPE<
2014.04.17 17:58:47 5: Cmd: >attr autocreate filelog /var/log/fhem/%NAME-%Y.log<
2014.04.17 17:58:47 5: Cmd: >attr autocreate weblink 1<
2014.04.17 17:58:47 5: Cmd: >attr autocreate weblink_room Plots<
2014.04.17 17:58:47 5: Cmd: >define eventTypes eventTypes ./log/eventTypes.txt<
2014.04.17 17:58:47 5: Loading ./FHEM/91_eventTypes.pm
2014.04.17 17:58:47 2: eventTypes: ./log/eventTypes.txt: bogus line
2014.04.17 17:58:47 2: eventTypes: ./log/eventTypes.txt: bogus line
2014.04.17 17:58:47 2: eventTypes: loaded 1813 events from ./log/eventTypes.txt
2014.04.17 17:58:47 5: Cmd: >define initialUsbCheck notify global:INITIALIZED usb create<
2014.04.17 17:58:47 5: Loading ./FHEM/91_notify.pm
2014.04.17 17:58:47 5: Cmd: >define CUL CUL /dev/ttyACM0 1234<
2014.04.17 17:58:47 5: Loading ./FHEM/00_CUL.pm
2014.04.17 17:58:47 3: Opening CUL device /dev/ttyACM0
2014.04.17 17:58:47 3: CUL device opened
2014.04.17 17:58:48 5: SW: V
2014.04.17 17:58:48 5: CUL/RAW (ReadAnswer): V 1.55 CUL868

2014.04.17 17:58:48 5: SW: ?
2014.04.17 17:58:48 5: CUL/RAW (ReadAnswer): ? (? is unknown) Use one of B C F i A Z E G M R T V W X e f m l t u x

2014.04.17 17:58:48 3: CUL: Possible commands: BCFiAZEGMRTVWXefmltux
2014.04.17 17:58:48 5: SW: X21
2014.04.17 17:58:48 5: SW: T01
2014.04.17 17:58:48 5: CUL/RAW (ReadAnswer): 1234

2014.04.17 17:58:48 5: GOT CUL fhtid: 1234
2014.04.17 17:58:48 5: Cmd: >attr CUL hmId 123ABC<
2014.04.17 17:58:48 5: Cmd: >attr CUL rfmode HomeMatic<
2014.04.17 17:58:48 5: SW: Zx
2014.04.17 17:58:48 5: SW: X21
2014.04.17 17:58:48 5: SW: Ar
2014.04.17 17:58:48 2: Switched CUL rfmode to HomeMatic
2014.04.17 17:58:48 5: Cmd: >define myJeeLink JeeLink /dev/ttyUSB0@57600<
2014.04.17 17:58:48 5: Loading ./FHEM/36_JeeLink.pm
2014.04.17 17:58:48 3: Opening myJeeLink device /dev/ttyUSB0
2014.04.17 17:58:48 3: Setting myJeeLink baudrate to 57600
2014.04.17 17:58:48 3: myJeeLink device opened
2014.04.17 17:58:48 5: Cmd: >attr myJeeLink room Serverraum<
2014.04.17 17:58:48 5: Cmd: >define wz.thermostat CUL_HM 1D9573<
2014.04.17 17:58:48 5: Loading ./FHEM/10_CUL_HM.pm

(...)  --> es folgt die Definition der Entities, die mit 4 Sekunden im realen Bereich liegt

2014.04.17 17:58:51 5: Cmd: >setstate wz.thermostat 2014-04-17 14:21:20 party-temp 20 C<
2014.04.17 17:58:51 5: Cmd: >setstate wz.thermostat 2014-04-17 17:56:40 state T: 22.2 H: 51<
2014.04.17 17:58:51 5: Cmd: >setstate wz.thermostat 2014-04-17 00:00:53 time-request -<
2014.04.17 17:58:51 5: Cmd: >setstate wz.thermostat.plot initialized<
2014.04.17 17:58:51 5: Interface "interface": readings "", getters "", setters ""
2014.04.17 17:58:51 5: Interface "switch": readings "onoff", getters "onoff", setters ""
2014.04.17 17:58:51 5: Interface "switch_active": readings "onoff", getters "onoff", setters ""
2014.04.17 17:58:51 5: Interface "switch_passive": readings "onoff", getters "onoff", setters "on:off"
2014.04.17 17:58:51 5: Interface "dimmer": readings "onoff:level", getters "onoff:level", setters "on:off:dimto:dimup:dimdown"
2014.04.17 17:58:51 5: Interface "temperature": readings "temperature", getters "temperature", setters ""
2014.04.17 17:58:51 5: Interface "humidity": readings "humidity", getters "humidity", setters ""
2014.04.17 17:58:51 5: Interface "wind": readings "wind", getters "wind", setters ""
2014.04.17 17:58:51 5: Interface "power": readings "power:maxPower:energy", getters "power:maxPower:energy", setters ""
2014.04.17 17:58:51 5: Triggering global (1 changes)
2014.04.17 17:58:51 5: Notify loop for global INITIALIZED
2014.04.17 17:58:51 5: Triggering initialUsbCheck
2014.04.17 17:58:51 4: initialUsbCheck exec usb create
2014.04.17 17:58:51 5: Cmd: >usb create<
2014.04.17 17:58:51 1: usb create starting
2014.04.17 17:58:52 4: ### ttyACM0: checking if it is a CUL
2014.04.17 17:58:52 4: already used by the fhem device CUL
2014.04.17 17:58:52 4: ### ttyACM1: checking if it is a CUL
2014.04.17 17:58:52 3: Probing CUL device /dev/ttyACM1
2014.04.17 17:58:52 5: SW: 0a
2014.04.17 17:58:54 5: SW: 560a
2014.04.17 17:59:27 4: got wrong answer for a CUL
2014.04.17 17:59:27 4: ### ttyACM1: checking if it is a TCM310
2014.04.17 17:59:27 3: Probing TCM310 device /dev/ttyACM1
2014.04.17 17:59:27 5: SW: 5500010005700838
2014.04.17 18:00:00 4: got wrong answer for a TCM310
2014.04.17 18:00:00 4: ### ttyACM1: checking if it is a FRM
2014.04.17 18:00:00 3: Probing FRM device /dev/ttyACM1
2014.04.17 18:00:00 5: SW: f9
2014.04.17 18:00:06 5: SW: f079f7
2014.04.17 18:00:40 4: got wrong answer for a FRM
2014.04.17 18:00:40 4: ### ttyUSB0: checking if it is a TCM310
2014.04.17 18:00:40 4: already used by the fhem device myJeeLink
2014.04.17 18:00:40 1: usb create end
2014.04.17 18:00:40 0: Server started with 95 defined entities (version $Id: fhem.pl 5532 2014-04-15 16:32:25Z rudolfkoenig $, os linux, user fhem, pid 27088)
2014.04.17 18:00:40 1: Perfmon: possible freeze starting at 17:58:48, delay is 112.227

Bei Sekunde 52 passieren einige verdächtig langlaufende Dinge. Das Delay könnte sich damit erklären.
2014.04.17 17:58:52 4: ### ttyACM0: checking if it is a CUL
(...)
2014.04.17 18:00:40 1: Perfmon: possible freeze starting at 17:58:48, delay is 112.227

Was passiert da? Es sieht für mich so aus als könne der CUL nicht eindeutig identifiziert werden ...

[betateilchen]

Kommentiere das USB autocreate in Deiner fhem.cfg aus.

[aeronaut]

Jau, schon gehts ohne Pause. Danke, betateilchen.

Aus dem USB autocreate resultiert also ein >initialUsbCheck<, der die USB-Devices versucht zu identifizieren und dabei an einem bereits früher definierten Device, dem CUL, etwas zu lange rumprobiert, bevor er aufgibt? Beim jeelink wird erkannt, dass er bereits definiert ist?

Nur mal zum Verständnis ...

[betateilchen]

ja, für mich ist das völliger Unfug. Aber manche Leute glauben fest daran, das sei die eierlegende Wollmilchsau 

Wurde hier im Forum auch schon mehrfach drüber diskutiert.

[aeronaut]

In gewissen Situationen mag das Sinn machen, nur es müsste bemerkt werden, wenn ein Device schon definiert ist.

Beim Jeelink klappt das und zwar so fix, dass es gar nicht auffällt.

[betateilchen]

naja, ich hatte damit bisher in Summe mehr Probleme als Nutzen