Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

High CPU on my Docker Daemon from ZvaveJS even without any data #3323

Closed
3 tasks
03397 opened this issue Oct 5, 2023 · 33 comments
Closed
3 tasks

High CPU on my Docker Daemon from ZvaveJS even without any data #3323

03397 opened this issue Oct 5, 2023 · 33 comments
Labels
bug Something isn't working

Comments

@03397
Copy link

03397 commented Oct 5, 2023

Checklist

  • I am not using Home Assistant. Or: a developer has told me to come here.
  • I have checked the troubleshooting section and my problem is not described there.
  • I have read the changelog and my problem is not mentioned there.

Deploy method

Docker

Z-Wave JS UI version

9.0.3.c37f5a4

ZwaveJS version

12.0.2

Describe the bug

I am running a docker instance on my QNAP NAS.
I have several containers utilizing almost 0% CPU utilization.
When I start the zwavejs container I have continuous spikes to my CPU from 10-60% which can be seen on my dockerd process.
The actual container is 0%.
The dockerd starts like this
container-station/dockerd -H tcp://0.0.0.0:2376 -H unix:///var/run/docker.sock --bridge=lxcbr0 --tlsverify --tlscacert=/etc/docker/tls/ca.pem --tlscert=/etc/docker/tls/server.pem --tlskey=/etc/docker/tls/server-key.pem --storage-driver=overlay2 --dns 10.0.3.1 --data-root=/var/lib/docker --exec-root=/var/run/docker --pidfile=/var/run/docker.pid -D --userland-proxy=false --config-file /share/CACHEDEV2_DATA/.qpkg/container-station/etc/docker.json

and the zvavejs docker-compose.yaml file is the following

version: '3.7'
services:
  zwavejs2mqtt:
    container_name: zwavejs2mqtt
    image: zwavejs/zwavejs2mqtt:latest
    restart: always
    tty: true
    stop_signal: SIGINT
    environment:
      - SESSION_SECRET=mysupersecretkey
      - ZWAVEJS_EXTERNAL_CONFIG=/usr/src/app/store/.config-db
      # Uncomment if you want logs time and dates to match your timezone instead of UTC
      # Available at https://en.wikipedia.org/wiki/List_of_tz_database_time_zones
      #- TZ=America/New_York
      - TZ=Asia/Nicosia
    networks:
      - zwave
    devices:
      # Do not use /dev/ttyUSBX serial devices, as those mappings can change over time.
      # Instead, use the /dev/serial/by-id/X serial device for your Z-Wave stick.
      - '/dev/ttyACM0:/dev/zwave'
    volumes:
      - /share/Container/container-station-data/lib/docker/volumes/zwavejs2mqtt/_data:/usr/src/app/store
    ports:
      - '8091:8091' # port for web interface
      - '3000:3000' # port for Z-Wave JS websocket server
networks:
  zwave:
volumes:
  zwave-config:
    name: zwave-config

Also

{
	"mqtt": {
		"name": "Zwavejs2Mqtt",
		"host": "localhost",
		"port": 1883,
		"qos": 1,
		"prefix": "zwave",
		"reconnectPeriod": 3000,
		"retain": true,
		"clean": true,
		"auth": false,
		"_ca": "",
		"ca": "",
		"_cert": "",
		"cert": "",
		"_key": "",
		"key": "",
		"disabled": true
	},
	"gateway": {
		"type": 0,
		"plugins": [],
		"authEnabled": false,
		"payloadType": 0,
		"nodeNames": true,
		"hassDiscovery": true,
		"discoveryPrefix": "homeassistant",
		"logEnabled": true,
		"logLevel": "info",
		"logToFile": true,
		"values": [
			{
				"device": "134-129-2",
				"value": {
					"id": "128-0-level",
					"commandClass": 128,
					"commandClassName": "Battery",
					"endpoint": 0,
					"property": "level",
					"propertyName": "level",
					"type": "number",
					"readable": true,
					"writeable": false,
					"label": "Battery level",
					"stateless": false,
					"commandClassVersion": 1,
					"min": 0,
					"max": 100,
					"unit": "%",
					"list": false,
					"value": 100,
					"lastUpdate": 1651141622750
				},
				"enablePoll": true,
				"pollInterval": 3600
			},
			{
				"device": "134-130-2",
				"value": {
					"id": "128-0-level",
					"commandClass": 128,
					"commandClassName": "Battery",
					"endpoint": 0,
					"property": "level",
					"propertyName": "level",
					"type": "number",
					"readable": true,
					"writeable": false,
					"label": "Battery level",
					"stateless": false,
					"commandClassVersion": 1,
					"min": 0,
					"max": 100,
					"unit": "%",
					"list": false,
					"value": 47,
					"lastUpdate": 1651141622845
				},
				"enablePoll": true,
				"pollInterval": 3600
			}
		],
		"jobs": [],
		"https": false
	},
	"zwave": {
		"port": "/dev/zwave",
		"allowBootloaderOnly": false,
		"commandsTimeout": 30,
		"logLevel": "info",
		"rf": {
			"txPower": {
				"powerlevel": 0,
				"measured0dBm": 0
			},
			"region": 0
		},
		"logEnabled": true,
		"securityKeys": {
			"S2_Unauthenticated": "x",
			"S2_AccessControl": "x",
			"S2_Authenticated": "x",
			"S0_Legacy": "x"
		},
		"deviceConfigPriorityDir": "/usr/src/app/store/config",
		"logToFile": true,
		"maxFiles": 7,
		"serverEnabled": true,
		"serverServiceDiscoveryDisabled": false,
		"enableSoftReset": true,
		"enableStatistics": true,
		"serverPort": 3000,
		"maxNodeEventsQueueSize": 100,
		"higherReportsTimeout": false,
		"disclaimerVersion": 1
	},
	"backup": {
		"storeBackup": false,
		"storeCron": "0 0 * * *",
		"storeKeep": 7,
		"nvmBackup": false,
		"nvmBackupOnEvent": false,
		"nvmCron": "0 0 * * *",
		"nvmKeep": 7
	}
}

This think is driving me nuts.
Your help will be appreciated.

To Reproduce

Start zwavejs container

Expected behavior

Low CPU

Additional context

No response

@03397 03397 added the bug Something isn't working label Oct 5, 2023
@03397
Copy link
Author

03397 commented Oct 5, 2023

I forgot to tell you during the first start of the container when the docker daemon starts I can see this errors
[ 2165.260966] overlayfs: failed to get index nlink (v/vt200, err=-61)
[ 2165.272293] overlayfs: failed to get index nlink (v/vt220, err=-61)
[ 2165.987081] overlayfs: failed to get index nlink (v/vt200, err=-61)
[ 2165.993446] overlayfs: failed to get index nlink (v/vt220, err=-61)
[ 2166.013862] overlayfs: failed to get index nlink (bin/ar, err=-61)
[ 2166.020192] overlayfs: failed to get index nlink (bin/as, err=-61)
[ 2166.026463] overlayfs: failed to get index nlink (bin/c++, err=-61)
[ 2166.032837] overlayfs: failed to get index nlink (bin/gcc, err=-61)
[ 2166.039247] overlayfs: failed to get index nlink (bin/g++, err=-61)
[ 2166.045584] overlayfs: failed to get index nlink (bin/gcc-ar, err=-61)
[ 2071.502462] overlayfs: failed to get index nlink (Europe/Nicosia, err=-61)
[ 2073.917289] overlayfs: failed to get index nlink (Europe/Nicosia, err=-61)
[ 2074.521750] overlayfs: failed to get index nlink (Europe/Nicosia, err=-61)
[ 2075.831504] overlayfs: failed to get index nlink (Europe/Nicosia, err=-61)
[ 2077.314913] overlayfs: failed to get index nlink (Europe/Berlin, err=-61)
[ 2077.842887] overlayfs: failed to get index nlink (Europe/Nicosia, err=-61)

In order for them to disappear I need to restart the zwavejs container

@robertsLando
Copy link
Member

Please make a driver log, loglevel debug and attach it here as a file (drag & drop into the text field).

@03397
Copy link
Author

03397 commented Oct 5, 2023

Attaching logs after start for first time of the docker daemon and when the errors disappear after restarting
download_2023-10-05_11-44-39.zip

@robertsLando
Copy link
Member

cc @AlCalzone any clue? I don't notice anything strange on logs

@03397 You confirm that the CPU spike is only on startup but then it behaves normally or the cpu usage remains high?

@03397
Copy link
Author

03397 commented Oct 5, 2023

The CPU is spiking all the time when the docker daemon starts for the first time with all the containers.
This also gives, the errors that I have copied in my initial post.
When I restart the container of zwavejs the errors go away and the CPU spiking is minimal.

@robertsLando
Copy link
Member

@03397 This seems to me something strange related to docker/docker-compose, tried to upgrade it?

@03397
Copy link
Author

03397 commented Oct 5, 2023

On second thought, after restarting the container of zwavejs only the errors go away. The spiking is there but not at the same rate. In order for the spiking to go away completely I need to stop zwavejs container completely.

No, I have not upgraded since this comes as a package on my NAS

@03397
Copy link
Author

03397 commented Oct 5, 2023

Look below
[~] # docker info
Client:
Context: default
Debug Mode: false
Plugins:
compose: Docker Compose (Docker Inc., v2.14.1-qnap1)

Server:
Containers: 13
Running: 12
Paused: 0
Stopped: 1
Images: 13
Server Version: 20.10.22-qnap7
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Native Overlay Diff: false
userxattr: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Cgroup Version: 1
Plugins:
Volume: local
Network: bridge host ipvlan macvlan null overlay qnet
Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
Swarm: inactive
Runtimes: io.containerd.runtime.v1.linux kata-runtime runc io.containerd.runc.v2
Default Runtime: runc
Init Binary: docker-init
containerd version: 78f51771157abb6c9ed224c22013cdf09962315d
runc version: v1.1.4-0-g5fd4c4d1
init version: de40ad0
Security Options:
apparmor
seccomp
Profile: default
Kernel Version: 5.10.60-qnap
Operating System: QTS 5.1.2 (20230926)
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 6.746GiB
Name: NASC7BD01
ID: BRWP:STEQ:NFPY:7S3Q:WKEO:D4O2:DTQ3:RMYG:V22Y:M3NA:DLKS:5FZQ
Docker Root Dir: /share/CACHEDEV2_DATA/Container/container-station-data/lib/docker
Debug Mode: true
File Descriptors: 133
Goroutines: 100
System Time: 2023-10-05T12:21:26.269105829+03:00
EventsListeners: 1
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
Product License: Community Engine
Default Address Pools:
Base: 172.29.0.0/16, Size: 22

@AlCalzone
Copy link
Member

AlCalzone commented Oct 5, 2023

Do we have any way of calling the node process in Docker with the --prof flag, to get an idea where the CPU time is spent?

Note that this might also require running another command in Docker and getting the generated file out of it.

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

https://nodejs.org/en/docs/guides/simple-profiling

@kpine
Copy link
Contributor

kpine commented Oct 6, 2023

Do we have any way of calling the node process in Docker with the --prof flag, to get an idea where the CPU time is spent?

Update the docker-compose.yml file and add command:

version: '3.7'
services:
  zwavejs2mqtt:
    container_name: zwavejs2mqtt
    image: zwavejs/zwavejs2mqtt:latest
    command:
      - node
      - --prof
      - server/bin/www

Note that this might also require running another command in Docker and getting the generated file out of it.

docker compose exec zwavejs2mqtt /bin/sh -c 'node --prof-process $(ls -1t isolate* | head -n1)' > processed.txt

(use docker-compose for the V1 Compose)

Example of saved output:

processed.txt
Statistical profiling result from isolate-0x7f9436c722e0-1-v8.log, (12068 ticks, 2979 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
   8775   72.7%          /lib/ld-musl-x86_64.so.1
     81    0.7%          /usr/lib/libstdc++.so.6.0.29
      6    0.0%          [vdso]
      2    0.0%          /usr/local/bin/node

 [JavaScript]:
   ticks  total  nonlib   name
     40    0.3%    1.2%  LazyCompile: *persistenceThread /usr/src/app/node_modules/@alcalzone/jsonl-db/build/lib/db.js:582:28
     21    0.2%    0.7%  LazyCompile: *listOnTimeout node:internal/timers:517:25
     18    0.1%    0.6%  LazyCompile: *string /usr/src/app/node_modules/json5/lib/parse.js:570:12
     17    0.1%    0.5%  LazyCompile: *parse /usr/src/app/node_modules/json5/lib/parse.js:13:33
     16    0.1%    0.5%  LazyCompile: *doQuickSort /usr/src/app/node_modules/source-map/lib/quick-sort.js:58:21
     13    0.1%    0.4%  LazyCompile: *resolve node:path:1091:10
      8    0.1%    0.2%  LazyCompile: *processTimers node:internal/timers:497:25
      7    0.1%    0.2%  LazyCompile: *default /usr/src/app/node_modules/json5/lib/parse.js:133:13
      5    0.0%    0.2%  LazyCompile: *compareByOriginalPositions /usr/src/app/node_modules/source-map/lib/util.js:304:36
      5    0.0%    0.2%  Function: ^processTimers node:internal/timers:497:25
      5    0.0%    0.2%  Function: ^listOnTimeout node:internal/timers:517:25
      3    0.0%    0.1%  LazyCompile: *normalizeString node:path:66:25
      3    0.0%    0.1%  LazyCompile: *initAsyncResource node:internal/timers:159:27
      3    0.0%    0.1%  LazyCompile: *compareByGeneratedPositionsDeflated /usr/src/app/node_modules/source-map/lib/util.js:343:45
      3    0.0%    0.1%  LazyCompile: *SourceMapConsumer_parseMappings /usr/src/app/node_modules/source-map/lib/source-map-consumer.js:468:43
      2    0.0%    0.1%  LazyCompile: *read /usr/src/app/node_modules/json5/lib/parse.js:113:15
      2    0.0%    0.1%  LazyCompile: *popAsyncContext node:internal/async_hooks:553:25
      2    0.0%    0.1%  LazyCompile: *beforePropertyName /usr/src/app/node_modules/json5/lib/parse.js:625:24
      2    0.0%    0.1%  Function: ^packageExportsResolve node:internal/modules/esm/resolve:625:31
      2    0.0%    0.1%  Function: ^incRefCount node:internal/timers:309:21
      1    0.0%    0.0%  RegExp: ^((?:<|>)?=?)\s{0,1}(v?(0|[1-9]\d{0,256})\.(0|[1-9]\d{0,256})\.(0|[1-9]\d{0,256})(?:-((?:0|[1-9]\d{0,256}|\d{0,256}[a-zA-Z-][a-zA-Z0-9-]{0,250})(?:\.(?:0|[1-9]\d{0,256}|\d{0,256}[a-zA-Z-][a-zA-Z0-9-]{0,250}))*))?(?:\+([a-zA-Z0-9-]{1,250}(?:\.[a-zA-Z0-9-]{1,250})*))?)$|^$
      1    0.0%    0.0%  LazyCompile: *syncExports node:internal/bootstrap/loaders:307:14
      1    0.0%    0.0%  LazyCompile: *remove node:internal/linkedlist:16:16
      1    0.0%    0.0%  LazyCompile: *onParseComplete node:internal/url:545:25
      1    0.0%    0.0%  LazyCompile: *newToken /usr/src/app/node_modules/json5/lib/parse.js:708:19
      1    0.0%    0.0%  LazyCompile: *lex /usr/src/app/node_modules/json5/lib/parse.js:86:14
      1    0.0%    0.0%  LazyCompile: *formatId /usr/src/app/node_modules/@zwave-js/shared/build/strings.js:35:18
      1    0.0%    0.0%  LazyCompile: *dirname node:path:1275:10
      1    0.0%    0.0%  LazyCompile: *beforePropertyValue /usr/src/app/node_modules/json5/lib/parse.js:887:25
      1    0.0%    0.0%  LazyCompile: *beforePropertyValue /usr/src/app/node_modules/json5/lib/parse.js:665:25
      1    0.0%    0.0%  LazyCompile: *__read /usr/src/app/node_modules/xstate/lib/_virtual/_tslib.js:55:16
      1    0.0%    0.0%  LazyCompile: *Module._load node:internal/modules/cjs/loader:886:24
      1    0.0%    0.0%  Function: ^writeOrBuffer node:internal/streams/writable:368:23
      1    0.0%    0.0%  Function: ^setTimeout node:timers:140:20
      1    0.0%    0.0%  Function: ^resolveJsonImports /usr/src/app/node_modules/@zwave-js/config/build/JsonTemplate.js:152:34
      1    0.0%    0.0%  Function: ^removeAt node:internal/priority_queue:85:11
      1    0.0%    0.0%  Function: ^persistenceThread /usr/src/app/node_modules/@alcalzone/jsonl-db/build/lib/db.js:582:28
      1    0.0%    0.0%  Function: ^moduleProvider node:internal/modules/esm/loader:452:28
      1    0.0%    0.0%  Function: ^makeStatsCallback node:fs:203:27
      1    0.0%    0.0%  Function: ^isEmpty node:internal/fixed_queue:95:10
      1    0.0%    0.0%  Function: ^internalCompileFunction node:internal/vm:31:33
      1    0.0%    0.0%  Function: ^getStatsFromBinding node:internal/fs/utils:535:29
      1    0.0%    0.0%  Function: ^getOptions node:internal/fs/utils:318:20
      1    0.0%    0.0%  Function: ^get isOpen /usr/src/app/node_modules/@serialport/bindings-cpp/dist/linux.js:46:15
      1    0.0%    0.0%  Function: ^finalizeEsmResolution node:internal/modules/cjs/loader:1081:31
      1    0.0%    0.0%  Function: ^emitBeforeScript node:internal/async_hooks:509:26
      1    0.0%    0.0%  Function: ^emit node:events:460:44
      1    0.0%    0.0%  Function: ^doneInvoke /usr/src/app/node_modules/xstate/lib/actions.js:355:20
      1    0.0%    0.0%  Function: ^dfs /usr/src/app/node_modules/xstate/lib/StateNode.js:116:17
      1    0.0%    0.0%  Function: ^createDeferredPromise /usr/src/app/node_modules/alcalzone-shared/deferred-promise/index.js:4:31
      1    0.0%    0.0%  Function: ^compareByGeneratedPositionsDeflated /usr/src/app/node_modules/source-map/lib/util.js:343:45
      1    0.0%    0.0%  Function: ^callback /usr/src/app/node_modules/graceful-fs/polyfills.js:301:25
      1    0.0%    0.0%  Function: ^calculateFirstLineLength /usr/src/app/node_modules/@zwave-js/core/build/log/shared.js:372:34
      1    0.0%    0.0%  Function: ^beforePropertyName /usr/src/app/node_modules/json5/lib/parse.js:625:24
      1    0.0%    0.0%  Function: ^allocate node:buffer:409:18
      1    0.0%    0.0%  Function: ^_write /usr/src/app/node_modules/winston-transport/index.js:69:51
      1    0.0%    0.0%  Function: ^__values /usr/src/app/node_modules/xstate/lib/_virtual/_tslib.js:43:18
      1    0.0%    0.0%  Function: ^WritableState node:internal/streams/writable:77:23
      1    0.0%    0.0%  Function: ^Socket node:net:338:16
      1    0.0%    0.0%  Function: ^Readable.read node:internal/streams/readable:402:35
      1    0.0%    0.0%  Function: ^OrdinaryGetMetadata /usr/src/app/node_modules/reflect-metadata/Reflect.js:600:37
      1    0.0%    0.0%  Function: ^NodeError node:internal/errors:367:28
      1    0.0%    0.0%  Function: ^Module.require node:internal/modules/cjs/loader:1133:36
      1    0.0%    0.0%  Function: ^Module._resolveFilename node:internal/modules/cjs/loader:984:35
      1    0.0%    0.0%  Function: ^Module._load node:internal/modules/cjs/loader:886:24
      1    0.0%    0.0%  Function: ^Module._findPath node:internal/modules/cjs/loader:582:28
      1    0.0%    0.0%  Function: ^GetOrCreateMetadataMap /usr/src/app/node_modules/reflect-metadata/Reflect.js:562:40
      1    0.0%    0.0%  Function: ^<anonymous> node:internal/fs/utils:691:40

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
    225    1.9%    7.0%  JavaScript
      0    0.0%    0.0%  C++
    167    1.4%    5.2%  GC
   8864   73.5%          Shared libraries
   2979   24.7%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
   8775   72.7%  /lib/ld-musl-x86_64.so.1

   2979   24.7%  UNKNOWN
   1068   35.9%    Function: ^internalCompileFunction node:internal/vm:31:33
   1056   98.9%      Function: ^wrapSafe node:internal/modules/cjs/loader:1152:18
   1056  100.0%        Function: ^Module._compile node:internal/modules/cjs/loader:1208:37
   1040   98.5%          Function: ^Module._extensions..js node:internal/modules/cjs/loader:1263:37
    827   79.5%            Function: ^Module.load node:internal/modules/cjs/loader:1105:33
    213   20.5%            LazyCompile: *Module._load node:internal/modules/cjs/loader:886:24
     16    1.5%          LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1263:37
     16  100.0%            Function: ^Module.load node:internal/modules/cjs/loader:1105:33
     12    1.1%      LazyCompile: ~wrapSafe node:internal/modules/cjs/loader:1152:18
     12  100.0%        LazyCompile: ~Module._compile node:internal/modules/cjs/loader:1208:37
     12  100.0%          LazyCompile: ~Module._extensions..js node:internal/modules/cjs/loader:1263:37
      9   75.0%            Function: ^Module.load node:internal/modules/cjs/loader:1105:33
      3   25.0%            LazyCompile: ~Module.load node:internal/modules/cjs/loader:1105:33
     74    2.5%    Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
     61   82.4%      Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
     10   16.4%        Function: ~<anonymous> node:http2:1:1
     10  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
     10  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      9   14.8%        Function: ~<anonymous> node:http:1:1
      9  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      9  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      5    8.2%        Function: ~<anonymous> node:tls:1:1
      5  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      5  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      4    6.6%        Function: ~<anonymous> node:_http_client:1:1
      4  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      4  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      3    4.9%        Function: ~<anonymous> node:internal/child_process:1:1
      3  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      3  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      3    4.9%        Function: ~<anonymous> node:child_process:1:1
      3  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      3  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      2    3.3%        LazyCompile: ~lazyWebCrypto node:crypto:125:23
      2  100.0%          LazyCompile: ~get node:crypto:369:8
      2  100.0%            Function: ^getOwn node:internal/bootstrap/loaders:188:16
      2    3.3%        LazyCompile: ~lazyLoadStreams node:fs:2907:25
      2  100.0%          LazyCompile: ~get ReadStream node:fs:3050:17
      2  100.0%            LazyCompile: ~getOwn node:internal/bootstrap/loaders:188:16
      2    3.3%        LazyCompile: ~initCJSParse node:internal/modules/esm/translators:58:28
      2  100.0%          LazyCompile: ~commonjsStrategy node:internal/modules/esm/translators:147:60
      2  100.0%            Function: ^moduleProvider node:internal/modules/esm/loader:452:28
      2    3.3%        Function: ~<anonymous> node:worker_threads:1:1
      2  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      2  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      2    3.3%        Function: ~<anonymous> node:internal/http2/core:1:1
      2  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      2  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      2    3.3%        Function: ~<anonymous> node:internal/http2/compat:1:1
      2  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      2  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      2    3.3%        Function: ~<anonymous> node:_http_common:1:1
      2  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      2  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        LazyCompile: ~lookupAndListen node:net:1930:25
      1  100.0%          LazyCompile: ~Server.listen node:net:1821:35
      1  100.0%            LazyCompile: ~startServer /usr/src/app/server/app.js:154:27
      1    1.6%        LazyCompile: ~get node:dns:350:8
      1  100.0%          LazyCompile: *syncExports node:internal/bootstrap/loaders:307:14
      1  100.0%            Function: ^<anonymous> node:internal/bootstrap/loaders:293:15
      1    1.6%        Function: ~<anonymous> node:readline/promises:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:module:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25
      1    1.6%        Function: ~<anonymous> node:internal/worker:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:internal/cluster/primary:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:internal/assert/assertion_error:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:https:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      1    1.6%        Function: ~<anonymous> node:dgram:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:cluster:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:assert:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
      1    1.6%        Function: ~<anonymous> node:_tls_wrap:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
      1    1.6%        Function: ~<anonymous> node:_tls_common:1:1
      1  100.0%          Function: ^compileForInternalLoader node:internal/bootstrap/loaders:319:27
      1  100.0%            Function: ^requireBuiltin node:internal/bootstrap/loaders:356:24
     12   16.2%      Function: ^compileForPublicLoader node:internal/bootstrap/loaders:264:25
     12  100.0%        Function: ^loadBuiltinModule node:internal/modules/cjs/helpers:51:27
     12  100.0%          Function: ^Module._load node:internal/modules/cjs/loader:886:24
     12  100.0%            Function: ^Module.require node:internal/modules/cjs/loader:1133:36
      1    1.4%      LazyCompile: ~compileForPublicLoader node:internal/bootstrap/loaders:264:25
      1  100.0%        Function: ^loadBuiltinModule node:internal/modules/cjs/helpers:51:27
      1  100.0%          LazyCompile: ~Module._load node:internal/modules/cjs/loader:886:24
      1  100.0%            Function: ^Module.require node:internal/modules/cjs/loader:1133:36
     50    1.7%    LazyCompile: *parse /usr/src/app/node_modules/json5/lib/parse.js:13:33
     45   90.0%      LazyCompile: ~loadDeviceIndexShared /usr/src/app/node_modules/@zwave-js/config/build/devices/DeviceConfig.js:131:37
      5   10.0%      LazyCompile: ~loadNotificationsInternal /usr/src/app/node_modules/@zwave-js/config/build/ConfigManager.js:651:41
     41    1.4%    LazyCompile: ~configSecureContext node:internal/tls/secure-context:124:29
     41  100.0%      LazyCompile: ~createSecureContext node:_tls_common:99:29
     41  100.0%        LazyCompile: ~TLSSocket._wrapHandle node:_tls_wrap:602:43
     41  100.0%          LazyCompile: ~TLSSocket node:_tls_wrap:470:19
     41  100.0%            Function: ~<anonymous> /usr/src/app/node_modules/http2-wrapper/source/utils/js-stream-socket.js:1:1
     38    1.3%    LazyCompile: *string /usr/src/app/node_modules/json5/lib/parse.js:570:12
     36   94.7%      LazyCompile: *parse /usr/src/app/node_modules/json5/lib/parse.js:13:33
     36  100.0%        LazyCompile: ~loadDeviceIndexShared /usr/src/app/node_modules/@zwave-js/config/build/devices/DeviceConfig.js:131:37
      2    5.3%      LazyCompile: *lex /usr/src/app/node_modules/json5/lib/parse.js:86:14
      2  100.0%        Function: ^parse /usr/src/app/node_modules/json5/lib/parse.js:13:33
      1   50.0%          LazyCompile: ~loadDeviceIndexShared /usr/src/app/node_modules/@zwave-js/config/build/devices/DeviceConfig.js:131:37
      1   50.0%          LazyCompile: ~loadDeviceClassesInternal /usr/src/app/node_modules/@zwave-js/config/build/ConfigManager.js:521:41
     33    1.1%    LazyCompile: *persistenceThread /usr/src/app/node_modules/@alcalzone/jsonl-db/build/lib/db.js:582:28
      9   27.3%      Function: ^runNextTicks node:internal/process/task_queues:58:22
      5   55.6%        Function: ^listOnTimeout node:internal/timers:517:25
      5  100.0%          Function: ^processTimers node:internal/timers:497:25
      4   44.4%        LazyCompile: *listOnTimeout node:internal/timers:517:25
      4  100.0%          LazyCompile: *processTimers node:internal/timers:497:25
      3    9.1%      LazyCompile: *listOnTimeout node:internal/timers:517:25
      3  100.0%        Function: ^processTimers node:internal/timers:497:25
      2    6.1%      LazyCompile: *runNextTicks node:internal/process/task_queues:58:22
      2  100.0%        LazyCompile: *listOnTimeout node:internal/timers:517:25
      2  100.0%          LazyCompile: *processTimers node:internal/timers:497:25
     33    1.1%    LazyCompile: *listOnTimeout node:internal/timers:517:25
     24   72.7%      LazyCompile: *processTimers node:internal/timers:497:25
      9   27.3%      Function: ^processTimers node:internal/timers:497:25

@03397
Copy link
Author

03397 commented Oct 7, 2023

Managed to do what you guys have described
processed.txt

@AlCalzone
Copy link
Member

@03397 can you do the last step again but with this changed command?

docker compose exec zwavejs2mqtt /bin/sh -c 'node --prof-process --preprocess $(ls -1t isolate* | head -n1)' > processed.txt

@03397
Copy link
Author

03397 commented Oct 7, 2023

Adding new exported as per the conmand below
docker exec zwavejs2mqtt /bin/sh -c 'node --prof-process --preprocess $(ls -1t isolate* | head -n1)' > processed.txt
processed.zip

@AlCalzone
Copy link
Member

Hmm... That last one has a lot of (unknown) stack frames, where I have no idea what it is.
The previous one indicates that not a lot is happening aside from module loading:

(19451 ticks total)

 [Summary]:
   ticks  total  nonlib   name
    742    3.8%    8.1%  JavaScript
      0    0.0%    0.0%  C++
    497    2.6%    5.4%  GC
  10235   52.6%          Shared libraries
   8474   43.6%          Unaccounted

There's a bottom up profile for 10080 of those ticks, and the "heaviest" part of zwave-js takes up 122 ticks, so roughly 1%.

Not sure what this "Unaccounted" chunk is and how to figure it out though.

Could it be that the peaks are due to slow I/O?

@03397
Copy link
Author

03397 commented Oct 7, 2023

@AlCalzone
There is no chance that this is because of slow I/O

This runs on a raid 5 array with over 250MB/s thoughput with minimal I/O. There is not much going on the disks anyway.

However, why do I get these overlays errors after the start of the zwavejs container?

@AlCalzone
Copy link
Member

Ok I'm out of ideas. If anyone knows how we could get to the bottom of what causes the spikes, I'm all ears.

@robertsLando
Copy link
Member

Just wondering... Could it be that high cpu usage is due to log to file enabled with debug level? I know that at startup logs could be a lot expecially if the loglevel is very low

@03397
Copy link
Author

03397 commented Oct 12, 2023

@robertsLando
Debug enable always have an overhead om the CPU and sometimes in production systems can cause huge problems.

I am not sure if this is causing the issue since this specific configuration is coming out of the box and I did not mess with it. This was not creating any issue in the past.

I can try it if some can pinpoint me to the direction full path of changing this to info.

@robertsLando
Copy link
Member

Just go to settings UI and disable both application and driver log

@03397
Copy link
Author

03397 commented Oct 12, 2023

I was referring to the debug level of the docker.
The debug level inside zwavejs is disabled.

See my post about the docker info

@robertsLando
Copy link
Member

Oh I forgot you attached the settings on the issue, if so I have no clue... I was mentioning those logs, I have no clue about docker logs sincerly also not sure they could cause those errors

@AlCalzone
Copy link
Member

So, one thing I noticed while debugging is that my CPU is constantly at 3-5% load without Z-Wave JS UI doing. It looks like this is due to nodemon's file watching. This should be off in production though.

@robertsLando
Copy link
Member

I don't use nodemon inside docker, I just run node command

@zeev-mindali
Copy link

which model of qnap do you have?
take in mind that the cpu of those products can be slow.
i have rp4 with no problems, and also have imx6ul from variscite and i getting the cpu spikes that you talking about.
some of products have a cpu with multi core, some are don't, this is releated to the embbded cpu envirement you have

@03397
Copy link
Author

03397 commented Oct 25, 2023

@zeev-mindali
My QNAP is TVS-673 with AMD Embedded R-Series RX-421BD Radeon R7 and 8GM RAM.
It is quit powerful. In general the CPU utilization is close to 0%

@robertsLando
Copy link
Member

Seems we found the reason of this in zwave-js/node-zwave-js#6612. Please follow updates there 🙏🏼

@robertsLando
Copy link
Member

Hi guys, could you give a try to master tag?

@03397
Copy link
Author

03397 commented Jan 26, 2024

Is this included in this. I am on the latest tag
zwave-js-ui: 9.8.1.2462761
zwave-js: 12.4.2
home id: 4224210025
home hex: 0xfbc85469

@robertsLando
Copy link
Member

robertsLando commented Jan 26, 2024

Nope latest should be: 9.8.1.0207327

@03397
Copy link
Author

03397 commented Jan 26, 2024

Nope latest should be: 9.8.1.10207327

This is in a docker from docker hub.

@robertsLando
Copy link
Member

robertsLando commented Jan 27, 2024

@03397
Copy link
Author

03397 commented Jan 27, 2024

The latest imnage downloaded is sha256:f5bcbe833942af9f7dc9516ef261e7c58ff3c08f5e6ee76ca10b4859b4194766

@robertsLando
Copy link
Member

robertsLando commented Jan 27, 2024

@03397 did you tried the tag of the link? I don't understand if you refer to the docker image sha or to the commit sha of zui, just try to do another docker pull if you are on master tag or use the tag you find in the link above

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

5 participants