Too much wake per seconde

[roumano]

What happened

After the service start and in a idle state , zigbee2mqtt wake up too much time per second

It's visible via 2 kind of command :

• powertop
  arround 250 to 300 events/sec
  for comparaison, mosquitto : 5 events/sec and home assistant less than 10 events/sec
• strace

strace -p $(pidof node index.js) > /tmp/1 2>&1
# stop it after 10 second

on the log file, it's content like 3000 clock_gettime per second( like clock_gettime(CLOCK_MONOTONIC, {tv_sec=125521, tv_nsec=997610561}) = 0
exact number can be found via : grep -c clock_gettime /tmp/1 then divise by 10 (for 10 second)

What did you expect to happen

it's should not wake-up so often or need to change how it's working ?

How to reproduce it (minimal and precise)

systemctl start zigbee2mqtt.service
powertop

Debug info

Zigbee2MQTT version: 1.18.2
Adapter hardware: Conbee II
Adapter firmware version: lasted available : deCONZ_ConBeeII_0x26680700.bin.GCF : release the 30-Nov-2020

[nurikk]

Interesting finding, this might come from nodeserial package.

Can you describe your setup? OS / Serial device (uart/usb)?

[roumano]

Hi, Debian 10 on raspberry 4 8Gio All installation was done on the OS (no VM, no docker). Combee2 mounted on a usb port. Pi connected via wire cable. A harddisk is mounted on a other usb port Le ven. 9 avr. 2021 à 05:07, John Doe ***@***.***> a écrit :

…

Interesting finding, this might come from nodeserial package. Can you describe your setup? OS / Serial device (uart/usb)? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#7004 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABQ3GTSA2HZLMOC4AOE3APTTHZVOHANCNFSM42TZVLEA> .

[Koenkk]

Same as #6747 (some bug in the Conbee 2 code). @ChrisHae can you look at this?

[ChrisHae]

Can you please provide zigbee-herdsman debug logs from the startup of z2mqtt. https://www.zigbee2mqtt.io/information/debug.html

[roumano]

Hi @ChrisHae , sorry for the delay ...
please found the log output

~$ DEBUG=zigbee-herdsman* npm start

> zigbee2mqtt@1.18.2 start /data/zigbee2mqtt
> node index.js

Zigbee2MQTT:debug 2021-04-13 10:20:10: Loaded state from file /data/zigbee2mqtt/data/state.json
Zigbee2MQTT:info  2021-04-13 10:20:10: Logging to console and directory: '/tmp/' filename: log.txt
Zigbee2MQTT:info  2021-04-13 10:20:10: Starting Zigbee2MQTT version 1.18.2 (commit #abd8a09)
Zigbee2MQTT:info  2021-04-13 10:20:10: Starting zigbee-herdsman (0.13.88)
Zigbee2MQTT:debug 2021-04-13 10:20:10: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null},"backupPath":"/data/zigbee2mqtt/data/coordinator_backup.json","databaseBackupPath":"/data/zigbee2mqtt/data/database.db.backup","databasePath":"/data/zigbee2mqtt/data/database.db","network":{"channelList":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"path":"/dev/ttyACM0"}}'
  zigbee-herdsman:adapter Path '/dev/ttyACM0' is valid for 'DeconzAdapter' +0ms
  zigbee-herdsman:deconz:driver Set delay to 0 +0ms
CREATED DECONZ ADAPTER
  zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"path":"/dev/ttyACM0"},"databasePath":"/data/zigbee2mqtt/data/database.db","databaseBackupPath":"/data/zigbee2mqtt/data/database.db.backup","backupPath":"/data/zigbee2mqtt/data/coordinator_backup.json","adapter":{"concurrent":null,"delay":null}}' +0ms
  zigbee-herdsman:deconz:driver Opening with /dev/ttyACM0 +8ms
  zigbee-herdsman:deconz:driver Serialport opened +9ms
  zigbee-herdsman:controller:log Started with result 'resumed' +15ms
  zigbee-herdsman:controller:log Injected database: true, adapter: true +0ms
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 1 paramId: 1 +3ms
  zigbee-herdsman:deconz:frameParser MAC: 0x00212effff06d42f +0ms
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 2 paramId: 7 +7ms
  zigbee-herdsman:deconz:frameParser NWKADDR: 0 +4ms
Zigbee2MQTT:info  2021-04-13 10:20:11: zigbee-herdsman started
  zigbee-herdsman:deconz:driver send read firmware version request from queue. seqNr: 3 +10ms
  zigbee-herdsman:deconz:frameParser read firmware version response - version: 0,7,104,38 +9ms
Zigbee2MQTT:info  2021-04-13 10:20:11: Coordinator firmware version: '{"meta":{"maintrel":0,"majorrel":38,"minorrel":104,"product":0,"revision":"0x26680700","transportrev":0},"type":"ConBee2/RaspBee2"}'
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 4 paramId: 5 +5ms
  zigbee-herdsman:deconz:frameParser PANID: 1a62 +6ms
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 5 paramId: 11 +5ms
  zigbee-herdsman:deconz:frameParser APS_EXT_PANID: 0xdddddddddddddddd +5ms
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 6 paramId: 28 +5ms
  zigbee-herdsman:deconz:frameParser CHANNEL: 11 +5ms
  zigbee-herdsman:deconz:driver send read parameter request from queue. seqNr: 7 paramId: 24 +6ms
  zigbee-herdsman:deconz:frameParser NETWORK_KEY: hidden +5ms
Zigbee2MQTT:debug 2021-04-13 10:20:11: Zigbee network parameters: {"channel":11,"extendedPanID":"0xdddddddddddddddd","panID":6754}
Zigbee2MQTT:info  2021-04-13 10:20:11: Currently 43 devices are joined:
Zigbee2MQTT:warn  2021-04-13 10:20:11: `permit_join` set to  `true` in configuration.yaml.
Zigbee2MQTT:warn  2021-04-13 10:20:11: Allowing new devices to join.
Zigbee2MQTT:warn  2021-04-13 10:20:11: Set `permit_join` to `false` once you joined all devices.
Zigbee2MQTT:info  2021-04-13 10:20:11: Zigbee: allowing new devices to join.
Zigbee2MQTT:info  2021-04-13 10:20:11: Started frontend on port 0.0.0.0:8081
  zigbee-herdsman:deconz:driver DATA_REQUEST - destAddr: 0xfffc EP:0 SeqNr. 8 request id: 1 +79ms
  zigbee-herdsman:deconz:frameParser DATA_REQUEST RESPONSE - request id: 1 status: 0 +79ms
  zigbee-herdsman:deconz:driver networkstate: 2 apsDataConfirm: 0 apsDataIndication: 1 configChanged: 0 apsRequestFreeSlots: 1 +3ms
  zigbee-herdsman:deconz:driver query aps data indication +3ms
  zigbee-herdsman:deconz:driver DATA_INDICATION - sending read data request - SeqNr. 9 +5ms
  zigbee-herdsman:deconz:frameParser DATA_INDICATION RESPONSE - seqNr. 9 srcAddr: 0x3d4c destAddr: 0x0 profile id: 0x104 cluster id: 0xb04 +11ms
  zigbee-herdsman:deconz:frameParser response payload: 24,158,10,5,5,33,235,0 +0ms
  zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":158,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":1285,"dataType":33,"attrData":235}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":15692,"endpoint":1,"linkquality":167,"groupID":null,"wasBroadcast":false}' +140ms

[ChrisHae]

I think the cause is too fast time intervals for checking internal queues. This came with the new "adapter_delay" option in the configuration.yaml in z2mqtt v1.18.0.

setting a delay value between 10 and 60 will reduce the cpu load.

configuration.yaml:

advanced:
adapter_delay: 50

But I just noticed the value is not passed correctly. So I uploaded a fix to zigbee-herdsman. i think it will be soon in the latest z2mqtt dev-branch version. https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html

[roumano]

Great, i will happy to test the Dev branch, please notify me when this change will be in the branch. so i will test.

Regards

[Koenkk]

Will be in the dev branch in 1 hours from now.

[roumano]

Build and use the dev branch is working as expected.
I have put adapter_delay: 50 and now,i got around 65 events/s (before it was 300) for the zigbee2qttt service (node index.js) and the cpu usage decrease to 1.7%.
65, it's a normal value (compared to other zigbee stick ? )

[Gr4ffy]

Same here
Docker "dev" is working fine now.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days