hedera-local-node icon indicating copy to clipboard operation
hedera-local-node copied to clipboard

Published 20 hours ago • verified publisher icon hashgraph

Abnormal CPU resource usage

Open lijyve opened this issue 10 months ago • 5 comments

Description

Hello developer, I encountered some problems when running this project locally and need your help. English is not my first language, so I used translation software to translate the questions I had.

Without changing any code, when I run this project through the command "npm run start", I find that the CPU resources are fully occupied. Is this normal? My environment is: CPU: 8 cores; memory: 32GB; hard disk: 1TB;

I also found that the mirror node will receive frequent and large numbers of requests from the consensus node (most of these request results are 404, and the frequency is one every two milliseconds). This may cause the CPU usage to be too high. There are too many 404 responses to get requests for the api/v1/transactions interface. It makes me wonder if it's normal. The following picture is a screenshot of the mirror node's log. image

When I query these transactions through the interface http://localhost:5551/api/v1/transactions, I find that these transactions are node 0.0.2 transferring money 1 to node 0.0.55。I made sure I didn't modify any code and didn't perform any operations after starting the project. image

Steps to reproduce

  1. npm install && npm install -g
  2. npm run start
  3. do nothing, but cpu is fully occupied.

Additional context

mirror-node-monitor        | 2024-04-04T16:54:13.648Z  INFO main c.h.m.m.MonitorApplication Started MonitorApplication in 6.929 seconds (process running for 7.937)
mirror-node-monitor        | 2024-04-04T16:54:13.675Z  INFO scheduling-2 c.h.m.m.s.SubscribeMetrics No subscribers
mirror-node-monitor        | 2024-04-04T16:54:13.676Z  INFO scheduling-1 c.h.m.m.p.PublishMetrics No publishers
mirror-node-monitor        | 2024-04-04T16:54:13.708Z  INFO validator-2 c.h.m.m.p.NodeSupplier Validated node 0.0.3 successfully
mirror-node-monitor        | 2024-04-04T16:54:13.726Z  INFO validator-2 c.h.m.m.p.NodeSupplier 1 of 1 nodes are functional
mirror-node-importer       | 2024-04-04T16:54:13.806Z  INFO scheduling-2 c.h.m.i.d.r.RecordFileDownloader No new signature files to download after file: 1970-01-01T00_00_00Z.rcd. Retrying in 0.5 s
mirror-node-monitor        | 2024-04-04T16:54:13.942Z  INFO hedera-sdk-5 c.h.m.m.e.ExpressionConverterImpl Created TOPIC entity 0.0.1001
mirror-node-monitor        | 2024-04-04T16:54:13.943Z  INFO single-1 c.h.m.m.e.ExpressionConverterImpl Converted property ${topic.ping} to 0.0.1001
mirror-node-importer       | 2024-04-04T16:54:14.317Z  INFO scheduling-4 c.h.m.i.d.r.RecordFileDownloader No new signature files to download after file: 1970-01-01T00_00_00Z.rcd. Retrying in 0.5 s
network-node               | 2024-04-04 16:54:14.344 INFO  91   SystemTaskManager - Setting pre-existing entity scan status to LAST_PRE_EXISTING_ENTITY_SCANNED
mirror-node-rest           | 2024-04-04T16:54:14.625Z WARN 078515d6 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-159000000 in 37 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:14.641Z WARN 2ee5640b ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-161000000 in 47 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:14.828Z WARN 461f3b19 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-458000000 in 7 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:14.832Z  INFO scheduling-4 c.h.m.i.d.r.RecordFileDownloader No new signature files to download after file: 1970-01-01T00_00_00Z.rcd. Retrying in 0.5 s
record-streams-uploader    | File System Event Notify [ timestamp = '1712249654', event_type = 'modified', src_path = '/records/2024-04-04T16_54_12.997749184Z.rcd_sig', dest_path = 'None' ]
record-streams-uploader    | File System Notify Timing [ notify_timestamp_secs = '1712249654.000000', file_mtime_secs = '1712249654.368786', duration_ms = '368.786', event_type = 'modified', filename = '2024-04-04T16_54_12.997749184Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '24.640', upload_duration_ms = '18.940', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '20.839', upload_duration_ms = '14.738', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_12.997749184Z.rcd.gz' ]
network-node               | 2024-04-04 16:54:14.902 INFO  95   SystemTaskManager - Setting pre-existing entity scan status to ALL_PRE_EXISTING_ENTITIES_SCANNED
mirror-node-rest           | 2024-04-04T16:54:15.039Z WARN b6418a3c ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-756000000 in 3 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:15.222Z WARN 4ba3674b ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-161000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:15.321Z WARN 2215d52b ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-53000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:15.365Z WARN be12ff13 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-159000000 in 3 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:15.474Z  INFO scheduling-6 c.h.m.i.d.r.RecordFileDownloader Downloaded 1 signatures in 139.6 ms (7/s): {2024-04-04T16_54_12.997749184Z.rcd_sig=1}
mirror-node-rest           | 2024-04-04T16:54:15.541Z WARN 3c809061 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-458000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-rest           | 2024-04-04T16:54:15.557Z WARN 8630d1cc ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-756000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:15.616Z  INFO scheduling-6 c.h.m.i.r.r.CompositeRecordFileReader Read 707 items successfully from v6 record file 2024-04-04T16_54_12.997749184Z.rcd.gz in 103.2 ms
mirror-node-importer       | 2024-04-04T16:54:15.616Z  WARN scheduling-6 c.h.m.i.d.r.RecordFileDownloader Previous hash not available
mirror-node-importer       | 2024-04-04T16:54:15.634Z  INFO scheduling-1 c.h.m.i.c.DateRangeCalculator RECORD: parser will parse items in DateRangeFilter([1970-01-01T00:00:00Z, 2262-04-11T23:47:16.854775807Z])
mirror-node-rest           | 2024-04-04T16:54:15.643Z WARN a4e2cb45 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-348000000 in 3 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:15.659Z  INFO scheduling-1 c.h.m.i.a.AddressBookServiceImpl Clearing node cache
record-streams-uploader    | File System Event Notify [ timestamp = '1712249655', event_type = 'modified', src_path = '/records/2024-04-04T16_54_14.220266166Z.rcd_sig', dest_path = 'None' ]
record-streams-uploader    | File System Notify Timing [ notify_timestamp_secs = '1712249655.000000', file_mtime_secs = '1712249655.216812', duration_ms = '216.812', event_type = 'modified', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
record-streams-uploader    | File System Event Notify [ timestamp = '1712249655', event_type = 'modified', src_path = '/records/2024-04-04T16_54_14.220266166Z.rcd_sig', dest_path = 'None' ]
record-streams-uploader    | File System Notify Timing [ notify_timestamp_secs = '1712249655.000000', file_mtime_secs = '1712249655.216812', duration_ms = '216.812', event_type = 'modified', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Initiated [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '45.850', upload_duration_ms = '34.197', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '94.347', upload_duration_ms = '84.524', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd.gz' ]
json-rpc-relay             | [2024-04-04 16:54:15.775 +0000] INFO (rpc-server/86 on de3b6b2fe26e): [GET]: /health/liveness 200 0 ms
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '70.350', upload_duration_ms = '60.647', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Complete [ service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
record-streams-uploader    | Cloud Copy Timing [ duration_ms = '105.882', upload_duration_ms = '101.591', service = 'S3', bucket = 'hedera-streams', remote_path = 'recordstreams/record0.0.3', filename = '2024-04-04T16_54_14.220266166Z.rcd_sig' ]
mirror-node-rest           | 2024-04-04T16:54:15.880Z WARN dc6360b8 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-53000000 in 1 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:15.882Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 3 rows to crypto_transfer table in 49.04 ms
mirror-node-rest           | 2024-04-04T16:54:16.032Z WARN e27e010c ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-645000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:16.129Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 705 rows to entity_temp table in 99.81 ms
mirror-node-rest           | 2024-04-04T16:54:16.133Z WARN 678b2ba9 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-458000000 in 3 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:16.141Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 1 rows to network_stake table in 9.058 ms
mirror-node-importer       | 2024-04-04T16:54:16.147Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 1 rows to node_stake table in 4.311 ms
mirror-node-importer       | 2024-04-04T16:54:16.161Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 1 rows to record_file table in 4.614 ms
mirror-node-importer       | 2024-04-04T16:54:16.161Z  INFO scheduling-6 c.h.m.i.d.r.RecordFileDownloader Downloaded 1 signatures in 37.75 ms (26/s): {2024-04-04T16_54_14.220266166Z.rcd_sig=1}
mirror-node-importer       | 2024-04-04T16:54:16.173Z  INFO scheduling-6 c.h.m.i.r.r.CompositeRecordFileReader Read 4 items successfully from v6 record file 2024-04-04T16_54_14.220266166Z.rcd.gz in 776.8 μs
mirror-node-importer       | 2024-04-04T16:54:16.189Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 707 rows to transaction table in 25.14 ms
mirror-node-importer       | 2024-04-04T16:54:16.189Z  INFO scheduling-1 c.h.m.i.p.r.e.s.SqlEntityListener Completed batch inserts in 358.8 ms
mirror-node-importer       | 2024-04-04T16:54:16.199Z  INFO scheduling-1 c.h.m.i.p.r.RecordFileParser Successfully processed 707 items from 2024-04-04T16_54_12.997749184Z.rcd.gz in 572.4 ms
mirror-node-importer       | 2024-04-04T16:54:16.211Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 8 rows to crypto_transfer table in 1.358 ms
mirror-node-rest           | 2024-04-04T16:54:16.228Z WARN a1a9255c ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-161000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:16.233Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 2 rows to entity_temp table in 21.35 ms
mirror-node-importer       | 2024-04-04T16:54:16.235Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 1 rows to record_file table in 2.172 ms
mirror-node-importer       | 2024-04-04T16:54:16.239Z  INFO scheduling-1 c.h.m.i.p.b.BatchInserter Copied 4 rows to transaction table in 3.401 ms
mirror-node-rest           | 2024-04-04T16:54:16.242Z WARN e9ff6df7 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-935000000 in 3 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:16.239Z  INFO scheduling-1 c.h.m.i.p.r.e.s.SqlEntityListener Completed batch inserts in 29.26 ms
mirror-node-importer       | 2024-04-04T16:54:16.239Z  INFO scheduling-1 c.h.m.i.p.r.RecordFileParser Successfully processed 4 items from 2024-04-04T16_54_14.220266166Z.rcd.gz in 32.40 ms
mirror-node-rest           | 2024-04-04T16:54:16.268Z INFO 6bb2fa00 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249654-159000000 in 12 ms: 200
mirror-node-rest           | 2024-04-04T16:54:16.292Z WARN 1dabb177 ::ffff:172.26.0.9 GET /api/v1/transactions/0.0.2-1712249655-348000000 in 2 ms: 404 Not found NotFoundError Not found
mirror-node-importer       | 2024-04-04T16:54:16.352Z  INFO task-2 c.h.m.i.p.r.e.s.EntityStakeCalculatorImpl Created entity_state_start in 143.9 ms
mirror-node-importer       | 2024-04-04T16:54:16.377Z  WARN task-2 c.h.m.i.p.r.e.s.EntityStakeCalculatorImpl Failed to calculate pending reward in 168.8 ms, last end stake period is 0, and the end stake period afterwards is null

Hedera network

other

Version

v.2.21.0

Operating system

Linux

lijyve avatar Apr 04 '24 17:04 lijyve

Hey @lijyve thank you, we'll take a look and let you know 👍

georgi-l95 avatar Apr 08 '24 08:04 georgi-l95

Hi @lijyve could you please provide the output of top and htop while all containers are running. htop will show the breakdown of the load on all CPU cores and top shows the percentage as a sum. We tested with a machine with similar to your specs and the load looks like this:

image image

If you are observing something similar then this is the expected load.

I don't think that the multiple 404 requests to the mirror node are related to the high CPU load, but this is a known issue and we are looking into it.

Ivo-Yankov avatar Apr 08 '24 12:04 Ivo-Yankov

Hi @lijyve could you please provide the output of top and htop while all containers are running. htop will show the breakdown of the load on all CPU cores and top shows the percentage as a sum. We tested with a machine with similar to your specs and the load looks like this:

image image

If you are observing something similar then this is the expected load.

I don't think that the multiple 404 requests to the mirror node are related to the high CPU load, but this is a known issue and we are looking into it.

This is the output of top and htop. My cpu is i7-8700. I am running this project in a vmware virtual machine. I assigned 8 cpu cores to the ubuntu virtual machine. image image

lijyve avatar Apr 10 '24 07:04 lijyve

Hi @lijyve could you please provide the output of top and htop while all containers are running. htop will show the breakdown of the load on all CPU cores and top shows the percentage as a sum. We tested with a machine with similar to your specs and the load looks like this: image image If you are observing something similar then this is the expected load. I don't think that the multiple 404 requests to the mirror node are related to the high CPU load, but this is a known issue and we are looking into it.

This is the output of top and htop. My cpu is i7-8700. I am running this project in a vmware virtual machine. I assigned 8 cpu cores to the ubuntu virtual machine. image image

Hi @lijyve, thanks for sharing the output and your system specs. The results indicate that there is a high system/kernel CPU usage. This might be caused by issues with your storage, or with the virtualization itself. Can you also please share the specs of your storage and the output of sudo iotop. It is usually not installed by default and can be added by running sudo apt install -y iotop.

isavov avatar Apr 10 '24 12:04 isavov

Hi @lijyve could you please provide the output of top and htop while all containers are running. htop will show the breakdown of the load on all CPU cores and top shows the percentage as a sum. We tested with a machine with similar to your specs and the load looks like this: image image If you are observing something similar then this is the expected load. I don't think that the multiple 404 requests to the mirror node are related to the high CPU load, but this is a known issue and we are looking into it.

This is the output of top and htop. My cpu is i7-8700. I am running this project in a vmware virtual machine. I assigned 8 cpu cores to the ubuntu virtual machine. image image

Hi @lijyve, thanks for sharing the output and your system specs. The results indicate that there is a high system/kernel CPU usage. This might be caused by issues with your storage, or with the virtualization itself. Can you also please share the specs of your storage and the output of sudo iotop. It is usually not installed by default and can be added by running sudo apt install -y iotop.

This is the output of iotop on my virtual machine. I also think the cause of this issue might be virtualization. However, I don't have a physical machine with a Linux system and docker installed, so I cannot provide more attempts. image

lijyve avatar Apr 11 '24 03:04 lijyve

Hello @lijyve, It seems we've exhausted all diagnostic steps regarding this issue. Has anything changed in the situation? If we can support you further let me know, otherwise I'll close this issue.

isavov avatar May 13 '24 07:05 isavov

Hey @lijyve have any of those previous replies helped you? Closing the issue now, if you still have this issue, feel free to reopen.

georgi-l95 avatar Jun 10 '24 19:06 georgi-l95