[Erweiterung] Raspberry: 58_GPIO4 neben 1Wire jetzt auch für DHT11/DHT22

[KölnSolar]

Hi Jörg,
scheinbar liest Du doppelt

Code: [Auswählen]

2021.10.24 17:06:00 2: RPi_OW_TCar1: Poll for temperature took 0.101958 s
2021.10.24 17:06:02 2: RPi_OW_TCar1: Poll for temperature took 0.094962 s
2021.10.24 17:07:02 2: RPi_OW_TCar1: Poll for temperature took 0.093208 s
2021.10.24 17:07:04 2: RPi_OW_TCar1: Poll for temperature took 0.09867 s
2021.10.24 17:08:04 2: RPi_OW_TCar1: Poll for temperature took 0.094438 s
2021.10.24 17:08:05 2: RPi_OW_TCar1: Poll for temperature took 0.098338 s
2021.10.24 17:09:05 2: RPi_OW_TCar1: Poll for temperature took 0.09395 s
2021.10.24 17:09:07 2: RPi_OW_TCar1: Poll for temperature took 0.09655 s
2021.10.24 17:10:07 2: RPi_OW_TCar1: Poll for temperature took 0.099392 s
2021.10.24 17:10:09 2: RPi_OW_TCar1: Poll for temperature took 0.097218 s
2021.10.24 17:11:09 2: RPi_OW_TCar1: Poll for temperature took 0.09739 s
2021.10.24 17:11:10 2: RPi_OW_TCar1: Poll for temperature took 0.094363 s
2021.10.24 17:12:11 2: RPi_OW_TCar1: Poll for temperature took 0.202024 s
2021.10.24 17:12:12 2: RPi_OW_TCar1: Poll for temperature took 0.098524 s
2021.10.24 17:13:12 2: RPi_OW_TCar1: Poll for temperature took 0.095339 s
2021.10.24 17:13:14 2: RPi_OW_TCar1: Poll for temperature took 0.097046 s
2021.10.24 17:14:14 2: RPi_OW_TCar1: Poll for temperature took 0.093119 s
2021.10.24 17:14:16 2: RPi_OW_TCar1: Poll for temperature took 0.097148 s
2021.10.24 17:15:16 2: RPi_OW_TCar1: Poll for temperature took 0.101318 s
2021.10.24 17:15:17 2: RPi_OW_TCar1: Poll for temperature took 0.09525 s
2021.10.24 17:16:17 2: RPi_OW_TCar1: Poll for temperature took 0.096868 s
2021.10.24 17:16:19 2: RPi_OW_TCar1: Poll for temperature took 0.098114 s
2021.10.24 17:17:19 2: RPi_OW_TCar1: Poll for temperature took 0.096775 s
2021.10.24 17:17:21 2: RPi_OW_TCar1: Poll for temperature took 0.098046 s
2021.10.24 17:18:21 2: RPi_OW_TCar1: Poll for temperature took 0.092432 s
2021.10.24 17:18:22 2: RPi_OW_TCar1: Poll for temperature took 0.099036 s
2021.10.24 17:19:23 2: RPi_OW_TCar1: Poll for temperature took 0.097574 s
2021.10.24 17:19:24 2: RPi_OW_TCar1: Poll for temperature took 0.098594 s
2021.10.24 17:20:24 2: RPi_OW_TCar1: Poll for temperature took 0.103044 s
2021.10.24 17:20:26 2: RPi_OW_TCar1: Poll for temperature took 0.096827 s
2021.10.24 17:21:26 2: RPi_OW_TCar1: Poll for temperature took 0.221009 s
2021.10.24 17:21:28 2: RPi_OW_TCar1: Poll for temperature took 0.127375 s
2021.10.24 17:22:28 2: RPi_OW_TCar1: Poll for temperature took 0.094627 s
2021.10.24 17:22:30 2: RPi_OW_TCar1: Poll for temperature took 0.097465 s
2021.10.24 17:23:30 2: RPi_OW_TCar1: Poll for temperature took 0.101513 s
2021.10.24 17:23:31 2: RPi_OW_TCar1: Poll for temperature took 0.098766 s
2021.10.24 17:24:31 2: RPi_OW_TCar1: Poll for temperature took 0.099656 s
2021.10.24 17:24:33 2: RPi_OW_TCar1: Poll for temperature took 0.095701 s
2021.10.24 17:25:33 2: RPi_OW_TCar1: Poll for temperature took 0.096936 s
2021.10.24 17:25:35 2: RPi_OW_TCar1: Poll for temperature took 0.096899 s
2021.10.24 17:26:35 2: RPi_OW_TCar1: Poll for temperature took 0.095325 s
2021.10.24 17:26:36 2: RPi_OW_TCar1: Poll for temperature took 0.096865 s
2021.10.24 17:27:36 2: RPi_OW_TCar1: Poll for temperature took 0.101343 s
2021.10.24 17:27:38 2: RPi_OW_TCar1: Poll for temperature took 0.199141 s
2021.10.24 17:28:38 2: RPi_OW_TCar1: Poll for temperature took 0.09846 s
2021.10.24 17:28:40 2: RPi_OW_TCar1: Poll for temperature took 0.095127 s
2021.10.24 17:29:40 2: RPi_OW_TCar1: Poll for temperature took 0.09286 s
2021.10.24 17:29:42 2: RPi_OW_TCar1: Poll for temperature took 0.095109 s
2021.10.24 17:30:42 2: RPi_OW_TCar1: Poll for temperature took 0.096441 s
2021.10.24 17:30:43 2: RPi_OW_TCar1: Poll for temperature took 0.098809 s
2021.10.24 17:31:43 2: RPi_OW_TCar1: Poll for temperature took 0.096544 s
2021.10.24 17:31:45 2: RPi_OW_TCar1: Poll for temperature took 0.09845 s
2021.10.24 17:32:45 2: RPi_OW_TCar1: Poll for temperature took 0.095375 s
2021.10.24 17:32:47 2: RPi_OW_TCar1: Poll for temperature took 0.094913 s
2021.10.24 17:33:47 2: RPi_OW_TCar1: Poll for temperature took 0.096925 s
2021.10.24 17:33:49 2: RPi_OW_TCar1: Poll for temperature took 0.177198 s
2021.10.24 17:34:49 2: RPi_OW_TCar1: Poll for temperature took 0.09767 s
2021.10.24 17:34:50 2: RPi_OW_TCar1: Poll for temperature took 0.111738 s
2021.10.24 17:35:50 2: RPi_OW_TCar1: Poll for temperature took 0.099235 sDadurch wird das Intervall nicht eingehalten.
Weil ich immer noch GPIO4 im Einsatz hab, führt das vermutlich beim konkurrierenden Zugriff zu freezes

Code: [Auswählen]

2021.10.24 17:35:54 2: RPi_OW_TCar1: Poll for temperature took 2.259114 s
2021.10.24 17:35:54 2: [Freezemon] freezedetect: possible freeze starting at 17:35:53, delay is 1.646 possibly caused by: tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1)
2021.10.24 18:10:55 2: RPi_OW_TCar1: Poll for temperature took 2.415079 s
2021.10.24 18:10:55 2: [Freezemon] freezedetect: possible freeze starting at 18:10:54, delay is 1.77 possibly caused by: tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1) tmr-at_Exec(check_jammer)
2021.10.24 18:45:56 2: RPi_OW_TCar1: Poll for temperature took 2.273054 s
2021.10.24 18:45:56 2: [Freezemon] freezedetect: possible freeze starting at 18:45:55, delay is 1.819 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_WWL) tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1)
2021.10.24 19:19:57 2: RPi_OW_TCar1: Poll for temperature took 3.51826 s
2021.10.24 19:19:57 2: [Freezemon] freezedetect: possible freeze starting at 19:19:55, delay is 2.786 possibly caused by: tmr-GPIO4_DeviceUpdateLoop(RPi_OW_WZ) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_TA) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_TC1) tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1) tmr-GPIO4_DeviceUpdateLoop(RPi_OW_VT)
2021.10.24 19:54:58 2: RPi_OW_TCar1: Poll for temperature took 2.296177 s
Ich denke Du kannst die Zeitmessung auf verbose level 5 setzen.

Grüße Markus

[Adimarantis]

Hi Markus,

Wenn die Funktion "fromTimer" aufgerufen wird, dann ist es normal, dass es zwei Aufrufe gibt (im Abstand von 1.5s). Hast du "mode" auf "timer"? Das ist für den Trick mit conv_time=2 gedacht - und dann kann er nicht blockieren, weil die Abfrage ja sofort zurückkommt.
Wenn du das nicht eingestellt hast, bräuchte ich ein "list" vom Device, da ich mir dann nicht erklären kann, warum er das macht.

Jörg

[KölnSolar]

Hast du "mode" auf "timer"?

Yes.

und dann kann er nicht blockieren

Doch, tat es.

Code: [Auswählen]

[Freezemon] freezedetect: possible freeze starting at 19:54:57, delay is 1.754 possibly caused by: tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1)
2021.10.24 19:54:56.397 5: RPi_OW_TCar1: Open /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
--- log skips     2.295 secs.
2021.10.24 19:54:58.692 5: RPi_OW_TCar1: Read ae 00 4b 46 7f ff 02 10 97 : crc=97 YES
2021.10.24 19:54:58.692 5: RPi_OW_TCar1: Read ae 00 4b 46 7f ff 02 10 97 t=10875
2021.10.24 19:54:58.692 2: RPi_OW_TCar1: Poll for temperature took 2.296177 s
2021.10.24 19:54:58.693 5: RPi_OW_TCar1: Finish: RPi_OW_TCar1 temperature=10.875
2021.10.24 19:54:58.703 5: End notify loop for RPi_OW_TCar1
Wie gesagt, ich denke

Weil ich immer noch GPIO4 im Einsatz hab, führt das vermutlich beim konkurrierenden Zugriff zu freezes

[Adimarantis]

machst du mal ein "list"?

[KölnSolar]

ungern.  Wird nicht großartig erhellen und ich muss erst wieder umändern. 
Aber bitte

Code: [Auswählen]

Internals:
   CFGFN     
   DEF        28-000005fa612d
   FUUID      617454c4-f33f-49d8-9852-6a7589159f29b2fe
   NAME       RPi_OW_TCar1
   NOTIFYDEV  global
   NR         886365
   NTFY_ORDER 50-RPi_OW_TCar1
   STATE      T: 9.000
   TYPE       RPI_1Wire
   family     28
   id         000005fa612d
   model      DS18B20
   .attraggr:
   .attrminint:
   READINGS:
     2021-10-25 10:17:06   conv_time       2
     2021-10-21 15:06:59   failreason      empty_data
     2021-10-21 15:06:59   failures        2
     2021-10-25 10:17:06   precision       12
     2021-10-25 10:17:35   state           T: 9.000
     2021-10-25 10:17:35   temperature     9.000
   getList:
     udev       noArg
   helper:
     write      resolution
     RUNNING_PID:
       abortArg   
       abortFn   
       bc_pid     934740
       finishFn   RPI_1Wire_FinishFn
       fn         RPI_1Wire_Poll
       pid        DEAD:13843
       terminated 1
       timeout   
       arg:
   setList:
     conv_time  textField
     update     noArg
Attributes:
   mode       timer
   room       Aussen
   verbose    1Ich lass es dann mal ne Stunde so laufen und werde dann sicherlich wieder den freeze haben und hier als Edit posten.

Edit: Und schon ist er wieder da

Code: [Auswählen]

[Freezemon] freezedetect: possible freeze starting at 10:46:24, delay is 1.908 possibly caused by: tmr-at_Exec(check_jammer) tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1)
2021.10.25 10:46:23.424 5: exec at command check_jammer
2021.10.25 10:46:23.425 5: Cmd: >{if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}<
2021.10.25 10:46:23.427 5: redefine at command check_jammer as +*00:00:05 {if (ReadingsAge('TRXUSB','state',0) > 40 || ReadingsVal('CULFB','state','opened') ne 'Initialized') {Voicecmd('jammer')}}
2021.10.25 10:46:23.453 5: End notify loop for check_jammer
2021.10.25 10:46:23.596 5: RPi_OW_TCar1: Open /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
--- log skips     2.296 secs.
2021.10.25 10:46:25.892 5: RPi_OW_TCar1: Read b0 00 4b 46 7f ff 10 10 07 : crc=07 YES
2021.10.25 10:46:25.892 5: RPi_OW_TCar1: Read b0 00 4b 46 7f ff 10 10 07 t=11000
2021.10.25 10:46:25.892 2: RPi_OW_TCar1: Poll for temperature took 2.296319 s
2021.10.25 10:46:25.892 5: RPi_OW_TCar1: Finish: RPi_OW_TCar1 temperature=11
2021.10.25 10:46:25.902 5: End notify loop for RPi_OW_TCar1
2021.10.25 10:46:25.906 4: Connection accepted from telnetForBlockingFn_1633424004_127.0.0.1_41584
2021.10.25 10:46:25.909 5: [Freezemon] freezedetect: ----------- Starting Freeze handling at 2021.10.25 10:46:25.908 ---------------------
[Freezemon] freezedetect: possible freeze starting at 10:46:24, delay is 1.908 possibly caused by: tmr-at_Exec(check_jammer) tmr-RPI_1Wire_FromTimer(RPi_OW_TCar1)


[Adimarantis]

Mal sehen ob das am Modul oder am System liegt. Kannst du mal auf der Kommandozeile (in /sys/device/w1_bus_master1/28-xxx/)

Code: [Auswählen]

time cat w1_slavemachen.
Ruhig paar mal wiederholen.
Erwartung bei conv_time=2 wäre das dies in der Gegend von 0,1xx Sekunden liegt.

Code: [Auswählen]

64 01 55 05 7f a5 81 66 7c : crc=7c YES
64 01 55 05 7f a5 81 66 7c t=22250

real    0m0,131s
user    0m0,001s
sys     0m0,026s


[KölnSolar]

Vielleicht habe ich mit dem letzten Zugriff tatsächlich einen konkurrierenden Zugriff erwischt

Code: [Auswählen]

pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
28 01 4b 46 7f ff 08 10 4c : crc=4c YES
28 01 4b 46 7f ff 08 10 4c t=18500

real    0m0.137s
user    0m0.013s
sys     0m0.025s
pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
27 01 4b 46 7f ff 09 10 72 : crc=72 YES
27 01 4b 46 7f ff 09 10 72 t=18437

real    0m0.107s
user    0m0.001s
sys     0m0.025s
pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
27 01 4b 46 7f ff 09 10 72 : crc=72 YES
27 01 4b 46 7f ff 09 10 72 t=18437

real    0m0.105s
user    0m0.001s
sys     0m0.022s
pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
27 01 4b 46 7f ff 09 10 72 : crc=72 YES
27 01 4b 46 7f ff 09 10 72 t=18437

real    0m0.105s
user    0m0.001s
sys     0m0.023s
pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
27 01 4b 46 7f ff 09 10 72 : crc=72 YES
27 01 4b 46 7f ff 09 10 72 t=18437

real    0m0.107s
user    0m0.001s
sys     0m0.023s
pi@raspberrypi:~ $ time cat /sys/devices/w1_bus_master1/28-000005fa612d/w1_slave
27 01 4b 46 7f ff 09 10 72 : crc=72 YES
27 01 4b 46 7f ff 09 10 72 t=18437

real    0m1.658s
user    0m0.001s
sys     0m0.026s
pi@raspberrypi:~ $


[Adimarantis]

Ich habe eine Vermutung:
Du hast nicht alle deine Sensoren auf conv_time=2 umgestellt.
Da die Abfragen alle über den selben 1Wire Bus laufen, blockieren die "langsamen" Sensoren, die schnellen trotzdem (müssen warten bis der Bus frei wird). Zumindest kann ich dein Bild nur auf diese Weise bei mir nachstellen. Wenn alle umgestellt sind, sehe ich bei zwei Sensoren die beide parallel von GPIO4 und RPI_1Wire bedient werden, selbst bei 5s update keine Ausreisser.

Ich könnte mir so als Feature noch vorstellen, dass ich mir die letzten 3 Zeiten merke und wenn der Durchschnitt >1s ist einen Hinweis in der Modulübersicht gebe (falls timer oder blocking) dass die Einstellung nonblocking die bessere Idee wäre.

[KölnSolar]

Du hast nicht alle deine Sensoren auf conv_time=2 umgestellt.

Natürlich nicht. Laufen alle mit GPIO4.
Ich teile Deine Vermutung aber nicht. Der freeze tritt ja offensichtlich nur bei KONKURRIERENDEM Zugriff auf DENSELBEN Sensor(siehe 7 Posts zurück).

Ich könnte mir so als Feature noch vorstellen, dass ich mir die letzten 3 Zeiten merke und wenn der Durchschnitt >1s ist einen Hinweis in der Modulübersicht gebe (falls timer oder blocking) dass die Einstellung nonblocking die bessere Idee wäre.

Bloß nicht. Das wird ja immer komplizierter. Und 99,9% werden sowieso die default-Einstellung nutzen, die ja problemlos funktioniert.

[Adimarantis]

Ich teile Deine Vermutung aber nicht. Der freeze tritt ja offensichtlich nur bei KONKURRIERENDEM Zugriff auf DENSELBEN Sensor(siehe 7 Posts zurück).

Je nachdem wieviele Sensoren du hast, ist das schwer zu bestimmen. Mit zwei Sensoren (einer konkurriert mit GPIO4) schaffe ich zumindest keine Freezemon Hits. Und auf meinen Produktivsystemen hab ich aktuell nur nonblocking im Einsatz (und natürlich komplett umgestellt).

Bloß nicht. Das wird ja immer komplizierter. Und 99,9% werden sowieso die default-Einstellung nutzen, die ja problemlos funktioniert.

Ein Hinweis, dass man möglicherweise etwas falsch eingestellt hat, sollte es doch nicht komplizierter machen, sondern eher unnötige Supportanfragen vermeiden. Aber wie du schon sagst, ist das Feature nur für wenige überhaupt relevant.

Ich habe jetzt trotzdem mal das therm_bulk_read feature eingebaut (wie üblich in dem anderen thread im ersten Post: https://forum.fhem.de/index.php/topic,123499.0.html). Einen Bug mit der conv_time hatte ich noch gefunden, aber der würde dich erst nach einem "shutdown restart" erwischen - da wurde die conv_time nicht wieder gesetzt.