Zigbee2mqtt causes high CPU usage

geoffreydemaagd commented 2 years ago

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)

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 commented 2 years ago

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.

Koenkk commented 2 years ago

What devices do you have in your network?

geoffreydemaagd commented 2 years ago

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.

Koenkk commented 2 years ago

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.

geoffreydemaagd commented 2 years ago

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

Koenkk commented 2 years ago

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%?

geoffreydemaagd commented 1 year ago

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

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

And after a few sec it's like

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

Koenkk commented 1 year ago

You can paste the log file here.

geoffreydemaagd commented 1 year ago

putty.log Thank you for your help

Koenkk commented 1 year ago

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

geoffreydemaagd commented 1 year ago

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

Koenkk commented 1 year ago

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%?

geoffreydemaagd commented 1 year ago

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?

Koenkk commented 1 year ago

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

geoffreydemaagd commented 1 year ago

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

Koenkk commented 1 year ago

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)

geoffreydemaagd commented 1 year ago

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

Koenkk commented 1 year ago

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

geoffreydemaagd commented 1 year ago

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.

Koenkk commented 1 year ago

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

geoffreydemaagd commented 1 year ago

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 commented 1 year ago

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.

Koenkk commented 1 year ago

Good to hear!

Koenkk / zigbee2mqtt