zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard

Zigbee2mqtt causes high CPU usage

Open geoffreydemaagd opened this issue 3 years ago • 1 comments

What happened?

When starting zigbee (systemctl start zigbee2mqtt) the CPU usage increases to 100% and more Stopping Zigbee and all is ok, So i has something to do when Herdsmann or Zigbee2mqtt.

I updates zigbee2mqtt to the latest version.

Started zigbee in example below with -test to show zigbee was the creator( 147% cpu)

image

In the zigbee logging nothing specials appears but the herdsmann logging is showing following output extensively zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvRead - {"status":0,"len":20,"value":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0]}} +10ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvLength - {"sysid":1,"itemid":4,"subid":178} +11ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,33,50,1,4,0,178,0,161] +10ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,4,97,50,20,0,0,0,67] +6ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,4,97,50,20,0,0,0,67] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 4 - 3 - 1 - 50 - [20,0,0,0] - 67 +1ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvLength - {"len":20} +8ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvRead - {"sysid":1,"itemid":4,"subid":178,"offset":0,"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,8,33,51,1,4,0,178,0,0,0,20,185] +8ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +9ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 22 - 3 - 1 - 51 - [0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0] - 175 +1ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvRead - {"status":0,"len":20,"value":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0]}} +10ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvLength - {"sysid":1,"itemid":4,"subid":179} +10ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,33,50,1,4,0,179,0,160] +10ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,4,97,50,20,0,0,0,67] +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,4,97,50,20,0,0,0,67] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 4 - 3 - 1 - 50 - [20,0,0,0] - 67 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvLength - {"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvRead - {"sysid":1,"itemid":4,"subid":179,"offset":0,"len":20} +8ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,8,33,51,1,4,0,179,0,0,0,20,184] +7ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +8ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 22 - 3 - 1 - 51 - [0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0] - 175 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvRead - {"status":0,"len":20,"value":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0]}} +9ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvLength - {"sysid":1,"itemid":4,"subid":180} +9ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,33,50,1,4,0,180,0,167] +9ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,4,97,50,20,0,0,0,67] +6ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,4,97,50,20,0,0,0,67] +1ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 4 - 3 - 1 - 50 - [20,0,0,0] - 67 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvLength - {"len":20} +8ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvRead - {"sysid":1,"itemid":4,"subid":180,"offset":0,"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,8,33,51,1,4,0,180,0,0,0,20,191] +8ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +8ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 22 - 3 - 1 - 51 - [0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0] - 175 +1ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvRead - {"status":0,"len":20,"value":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0]}} +9ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvLength - {"sysid":1,"itemid":4,"subid":181} +10ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,33,50,1,4,0,181,0,166] +9ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,4,97,50,20,0,0,0,67] +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,4,97,50,20,0,0,0,67] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 4 - 3 - 1 - 50 - [20,0,0,0] - 67 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvLength - {"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvRead - {"sysid":1,"itemid":4,"subid":181,"offset":0,"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,8,33,51,1,4,0,181,0,0,0,20,190] +7ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +9ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,22,97,51,0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0,175] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 22 - 3 - 1 - 51 - [0,20,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0] - 175 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvRead - {"status":0,"len":20,"value":{"type":"Buffer","data":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,0,0,0]}} +11ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - nvLength - {"sysid":1,"itemid":4,"subid":182} +10ms zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,5,33,50,1,4,0,182,0,165] +11ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,4,97,50,20,0,0,0,67] +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,4,97,50,20,0,0,0,67] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 4 - 3 - 1 - 50 - [20,0,0,0] - 67 +0ms zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - nvLength - {"len":20} +7ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms ....

node -v v16.15.1

npm -v 8.11.0

If you could pinpoint me how to solve the problem. Was this already mentionned in the past?

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.28.2 commit: e66fe853

Adapter firmware version

20211217

Adapter

zStack3x0

Debug log

No response

geoffreydemaagd avatar Nov 17 '22 18:11 geoffreydemaagd

After digging for a while I see in the V8 CPU profiler that after starting Z2M the garbage collector is constanly running. This is causing the high CPU load. Tried to install different version but the problem stays. Unfortunatly I still have a RPI 3b+ so the available memory isn't so great. Does anybody have an idea why this problem suddenly pops up? Memory usage is quite the same as when the problem wasn't there.

geoffreydemaagd avatar Nov 29 '22 06:11 geoffreydemaagd

What devices do you have in your network?

Koenkk avatar Nov 29 '22 18:11 Koenkk

Koen,

I have only 3 devices WSDCGQ11LM KEYZB-110 TS011F_plug_3

SONOFF ZigBee 3.0 USB Dongle Plus, TI CC2652P

Even without the USB sonofff connected, the garbage collector initiated after starting Z2M is running constantly with high CPU as a result.

geoffreydemaagd avatar Nov 29 '22 18:11 geoffreydemaagd

Can you provide the herdsman debug log when starting z2m + 5 minutes after this? (after 5 minutes the cpu usage is still 100%, right?)

See https://www.zigbee2mqtt.io/guide/usage/debug.html on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

Koenkk avatar Nov 29 '22 18:11 Koenkk

Koen, putty.log

Tried to capture the output but there are so many messages I can't copy them all. In attached to log I could capture

ps outputed the full ouput=> see new attachment

Many thanks for your help

geoffreydemaagd avatar Nov 29 '22 18:11 geoffreydemaagd

In the logs I only see the starting phase of Zigbee2MQTT. In this phase a lot of commands are fired at the adapter so 100% CPU usage would not be strange at this phase.

Can you provide me the logs when Zigbee2MQTT has started (wait 60 seconds after start) and the CPU usage is 100%?

Koenkk avatar Nov 30 '22 15:11 Koenkk

Installed different version op NPM and node (14.x,16.x 18.x) just to be sure the problem is not related with those version.

The log what I send was already the logging when the cpu was going crazy.

Normally my CPU is around

image

From the moment the parser of Herdsman starts the CPU is increasing

image

And after a few sec it's like

image

Stopping zigbee and the cpu goes back to normal

Do you have an email to send the file?

The moment when the cpu starts was about 20:14:48

[31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m<-- [254,41,68,129,0,0,4,11,146,232,1,1,0,167,0,230,139,167,0,0,21,24,3,1,5,5,0,33,232,0,8,5,0,33,116,0,11,5,0,41,14,0,146,232,29,36] [31m+49ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [254,41,68,129,0,0,4,11,146,232,1,1,0,167,0,230,139,167,0,0,21,24,3,1,5,5,0,33,232,0,8,5,0,33,116,0,11,5,0,41,14,0,146,232,29,36] [31m+1ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--> parsed 41 - 2 - 4 - 129 - [0,0,4,11,146,232,1,1,0,167,0,230,139,167,0,0,21,24,3,1,5,5,0,33,232,0,8,5,0,33,116,0,11,5,0,41,14,0,146,232,29] - 36 [31m+1ms[0m [34;1mzigbee-herdsman:adapter:zStack:znp:AREQ [0m<-- AF - incomingMsg - {"groupid":0,"clusterid":2820,"srcaddr":59538,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":167,"securityuse":0,"timestamp":10980326,"transseqnumber":0,"len":21,"data":{"type":"Buffer","data":[24,3,1,5,5,0,33,232,0,8,5,0,33,116,0,11,5,0,41,14,0]}} [34m+53ms[0m [31;1mzigbee-herdsman:controller:log [0mReceived 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":3,"manufacturerCode":null,"commandIdentifier":1},"Payload":[{"attrId":1285,"status":0,"dataType":33,"attrData":232},{"attrId":1288,"status":0,"dataType":33,"attrData":116},{"attrId":1291,"status":0,"dataType":41,"attrData":14}],"Command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}},"address":59538,"endpoint":1,"linkquality":167,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' [31m+1m[0m [34mZigbee2MQTT:debug[39m 2022-11-30 20:14:48: Received Zigbee message from '0x540f57fffe8970a2', type 'readResponse', cluster 'haElectricalMeasurement', data '{"activePower":14,"rmsCurrent":116,"rmsVoltage":232}' from endpoint 1 with groupID 0 [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [] [31m+51ms[0m [32mZigbee2MQTT:info [39m 2022-11-30 20:14:48: MQTT publish: topic 'zigbee2mqtt/xxxx', payload '{"child_lock":"UNLOCK","current":0.12,"energy":165.31,"indicator_mode":"off/on","last_seen":"2022-11-30T20:14:48+01:00","linkquality":167,"power":14,"state":"ON","update":{"state":"idle"},"voltage":232}' [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m<-- [254,5,69,196,68,61,1,146,232,134] [31m+17s[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [254,5,69,196,68,61,1,146,232,134] [31m+2ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--> parsed 5 - 2 - 5 - 196 - [68,61,1,146,232] - 134 [31m+0ms[0m [34;1mzigbee-herdsman:adapter:zStack:znp:AREQ [0m<-- ZDO - srcRtgInd - {"dstaddr":15684,"relaycount":1,"relaylist":[59538]} [34m+17s[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [] [31m+3ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m<-- [254,5,69,196,68,61,1,146,232,134,254,25,68,129,0,0,10,0,68,61,44,11,0,167,0,31,247,183,0,0,5,0,2,0,0,0,146,232,28,17,254,29,68,129,0,0,0,5,68,61,44,11,0,163,0,27,251,183,0,0,9,9,3,0,20,0,0,23,255,255,146,232,28,17] [31m+2ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [254,5,69,196,68,61,1,146,232,134,254,25,68,129,0,0,10,0,68,61,44,11,0,167,0,31,247,183,0,0,5,0,2,0,0,0,146,232,28,17,254,29,68,129,0,0,0,5,68,61,44,11,0,163,0,27,251,183,0,0,9,9,3,0,20,0,0,23,255,255,146,232,28,17] [31m+1ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--> parsed 5 - 2 - 5 - 196 - [68,61,1,146,232] - 134 [31m+1ms[0m [34;1mzigbee-herdsman:adapter:zStack:znp:AREQ [0m<-- ZDO - srcRtgInd - {"dstaddr":15684,"relaycount":1,"relaylist":[59538]} [34m+6ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [254,25,68,129,0,0,10,0,68,61,44,11,0,167,0,31,247,183,0,0,5,0,2,0,0,0,146,232,28,17,254,29,68,129,0,0,0,5,68,61,44,11,0,163,0,27,251,183,0,0,9,9,3,0,20,0,0,23,255,255,146,232,28,17] [31m+2ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--> parsed 25 - 2 - 4 - 129 - [0,0,10,0,68,61,44,11,0,167,0,31,247,183,0,0,5,0,2,0,0,0,146,232,28] - 17 [31m+1ms[0m [34;1mzigbee-herdsman:adapter:zStack:znp:AREQ [0m<-- AF - incomingMsg - {"groupid":0,"clusterid":10,"srcaddr":15684,"srcendpoint":44,"dstendpoint":11,"wasbroadcast":0,"linkquality":167,"securityuse":0,"timestamp":12056351,"transseqnumber":0,"len":5,"data":{"type":"Buffer","data":[0,2,0,0,0]}} [34m+4ms[0m [31;1mzigbee-herdsman:controller:log [0mReceived 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":2,"manufacturerCode":null,"commandIdentifier":0},"Payload":[{"attrId":0}],"Command":{"ID":0,"name":"read","parameters":[{"name":"attrId","type":33}],"response":1}},"address":15684,"endpoint":44,"linkquality":167,"groupID":0,"wasBroadcast":false,"destinationEndpoint":11}' [31m+17s[0m [34mZigbee2MQTT:debug[39m 2022-11-30 20:15:05: Received Zigbee message from 'xxxxxx', type 'read', cluster 'genTime', data '["time"]' from endpoint 44 with groupID 0 [32mZigbee2MQTT:info [39m 2022-11-30 20:15:05: MQTT publish: topic 'zigbee2mqtt/xxxxxx', payload '{"battery":100,"battery_low":false,"last_seen":"2022-11-30T20:15:05+01:00","linkquality":167,"tamper":false,"update":{"state":"idle"},"voltage":5700}' [33;1mzigbee-herdsman:controller:endpoint [0mReadResponse xxxx/44 genTime({"time":723150905}, {"sendWhen":"active","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":11,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) [33m+17s[0m [32;1mzigbee-herdsman:adapter:zStack:adapter [0msendZclFrameToEndpointInternal xxxxx:15684/44 (0,0,1) [32m+17s[0m [34;1mzigbee-herdsman:adapter:zStack:znp:SREQ [0m--> AF - dataRequest - {"dstaddr":15684,"destendpoint":44,"srcendpoint":11,"clusterid":10,"transid":3,"options":0,"radius":30,"len":11,"data":{"type":"Buffer","data":[24,2,1,0,0,0,226,57,104,26,43]}} [34m+17s[0m [32;1mzigbee-herdsman:adapter:zStack:unpi:writer [0m--> frame [254,21,36,1,68,61,44,11,10,0,3,0,30,11,24,2,1,0,0,0,226,57,104,26,43,235] [32m+17s[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--- parseNext [254,29,68,129,0,0,0,5,68,61,44,11,0,163,0,27,251,183,0,0,9,9,3,0,20,0,0,23,255,255,146,232,28,17] [31m+37ms[0m [31;1mzigbee-herdsman:adapter:zStack:unpi:parser [0m--> parsed 29 - 2 - 4 - 129 - [0,0,0,5,68,61,44,11,0,163,0,27,251,183,0,0,9,9,3,0,20,0,0,23,255,255,146,232,28] - 17 [31m+1ms[0m

and this goes on an on without any warning or error

geoffreydemaagd avatar Nov 30 '22 18:11 geoffreydemaagd

You can paste the log file here.

Koenkk avatar Nov 30 '22 20:11 Koenkk

putty.log Thank you for your help

geoffreydemaagd avatar Nov 30 '22 20:11 geoffreydemaagd

Can you try removing the TS011F_plug_3 from your network and see if this issue disappears?

Koenkk avatar Nov 30 '22 20:11 Koenkk

I removed all devices (tried first the TS011F but was not the cause) but the problem stays the same.

geoffreydemaagd avatar Nov 30 '22 20:11 geoffreydemaagd

Can you provide the logging when having no devices paired (and also all removed from power) from starting z2m + 5 minutes after this when the cpu usage is 100%?

Koenkk avatar Dec 01 '22 17:12 Koenkk

Removed all devices=> staring zigbee2mqtt => cpu stays stable

I tried to join only 1 device (remove the rest to test each device) But from the moment I try to join the problem occures immedialtly

logging021222.txt

I was trying to join and approx from this line the cpu went crazy zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1026,"srcaddr":51165,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":21,"securityuse":0,"timestamp":7793532,"transseqnumber":0,"len":8,"data":{"type":"Buffer","data":[24,0,10,0,0,41,92,8]}} +56s zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":0,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"dataType":41,"attrData":2140}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":51165,"endpoint":1,"linkquality":21,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +56s zigbee-herdsman:controller:log 'zcl' data is from unknown device with address '51165', skipping... +1ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,5,4,221,199,1,1,0,21,0,134,236,118,0,0,8,24,1,10,0,0,33,224,27,221,199] +15ms zigbee-herdsman:adapter:zStack:unpi:parser <-- [29,13,254,37,68,129,0,0,3,4,221,199,1,1,0,18,0,145,237,118,0,0,17,24,2,10,0,0,41,248,3,20,0,40,255,16,0,41,177,39,221,199,29,93] +1ms zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,28,68,129,0,0,5,4,221,199,1,1,0,21,0,134,236,118,0,0,8,24,1,10,0,0,33,224,27,221,199,29,13,254,37,68,129,0,0,3,4,221,199,1,1,0,18,0,145,237,118,0,0,17,24,2,10,0,0,41,248,3,20,0,40,255,16,0,41,177,39,221,199,29,93] +0ms zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 28 - 2 - 4 - 129 - [0,0,5,4,221,199,1,1,0,21,0,134,236,118,0,0,8,24,1,10,0,0,33,224,27,221,199,29] -

Maybe I should try an older version of the coordinator software?

geoffreydemaagd avatar Dec 02 '22 09:12 geoffreydemaagd

  • What device is this?
  • Can you provide the logging again but then running with DEBUG=* instead of DEBUG=zigbee-herdsman*

Koenkk avatar Dec 02 '22 16:12 Koenkk

I have 3 devices but with each device I have the same problem KEYZB-110 WSDCGQ11LM TS011F_plug_3 Logging041222.txt

From the moment those lines appears the cpu starting to reach high and never stops getting high

32;1mserialport/bindings/unixRead [0mStarting read [32m+3ms[0m

=> at line 4929 the cpu begins to throttle

geoffreydemaagd avatar Dec 04 '22 08:12 geoffreydemaagd

Seems it is caused by the serialport library. I just updated it to 10.5.0, (from 9.2.8) can you check if this fixes the issue?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

Koenkk avatar Dec 04 '22 19:12 Koenkk

Tried with 1.28.4-dev but the same behavior is happening. Still lots of serialport/bindings/unixRead �[0mStarting read �[32m+3ms�[0m and of course high cpu usage

geoffreydemaagd avatar Dec 05 '22 15:12 geoffreydemaagd

Do you have any other USB devices attached? Somehow the serialport library is not working correctly on your system.

Koenkk avatar Dec 06 '22 16:12 Koenkk

Koen, I have 2 RPI3b+ and have already tested it on both RPI's. Both have the problem, even with only 1 USB (the dongle) attached to it.

geoffreydemaagd avatar Dec 06 '22 19:12 geoffreydemaagd

More things you could try (but I'm not sure if this fixes the problem)

  • Run npm rebuild --build-from-source in the Zigbee2MQTT directory
  • Upgrade your adapter firmware: https://github.com/Koenkk/Z-Stack-firmware/tree/develop/coordinator/Z-Stack_3.x.0/bin

Koenkk avatar Dec 07 '22 17:12 Koenkk

Wasn't working - I'm currenlty installing a fresh new image on a RPI4 8GB. Will keep you informed as soon as its finished

geoffreydemaagd avatar Dec 17 '22 14:12 geoffreydemaagd

Koen,

I've found the reason of the high cpu usage and zigbee was not the cause. I have also OLAD installed on my RPI to control my DMX lighting. In one of those config files there was only a prefix mentionned of which usb device it could use for example ttyUSB

Both programs worked and without seeing it in the debug and logs it (not of ola neither in zigbee) was hard to pinpoint the actual problem.

I was settting up a brand new RPI 4 with 8 GB (new os etc) and the problem arised also on that device.

Changed the OLA to the actual serial/by-id and the problem was gone.

In the past I had a symlink configured for zigbee2mqtt, in that setup I had no problem at all but started since using the serial/by-id in the config yaml of zigbee2mqtt (now that I know the problem, it all became clear)

Many thanks for all your cooperation and good advice. That's what I like here.

geoffreydemaagd avatar Dec 18 '22 11:12 geoffreydemaagd

Good to hear!

Koenkk avatar Dec 18 '22 12:12 Koenkk