Problems with add_spendbundle log entries

[Jacek-ghub]

My node has problems with add_spendbundle log entries. Today, those are added about one millisecond apart causing one log file to reach 20MB (current max size) in about 5 minutes making those logs rather worthless.

Are those entries reflecting the state of the node, or rather the network, i.e., do I need to check something on my server and fix it? I don't see anything that would look like broken (drives are more or less idle, there is plenty of free RAM, although one CPU core is hosed by start_full_node.exe process, my node is synced, and most of the peers are on the sync level).

I am not sure if that is the problem, but looking at my CPU, one of the cores is basically hosed. I have never seen this behavior before, so it may be indicative that the process that generates those add_spendbundle entries is really struggling (not sure about it).

Is there any value in those log entries? Could those be pushed to DEBUG level, so will be invisible on INFO level (what basically everyone is using)?

Here is an example of those log entries, please note the time differences (single millisecond apart, if even that):

2021-12-20T08:47:57.501 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.502 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.503 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.504 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.505 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.506 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.508 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.509 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.510 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.510 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.511 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)
2021-12-20T08:47:57.512 full_node chia.full_node.mempool_manager: INFO     add_spendbundle took 0.0 seconds, cost 8480552 (0.077%)

[mk01]

the same here. out of ~150k lines in one log file (rotated every 2minutes), ~110k is add_spendbundle.

[Jacek-ghub]

My node was also struggling today with being synced (another dust storm?). However, when I dropped the log level to ERROR, it is happy again.

This is just a nonsense to push engineering logs that have no place in production code on the same level as logs that are needed to check health of the service. It is an entry level mistake.

[mk01]

to me it didn't help in keeping node synced (still going back and forth between no-sync and fully synced) always when the shit storm hits, node goes out of sync.

[Jacek-ghub]

Sorry, I didn't notice your reply. Did you reduce the log level, and reduce your peer count down to about 10? If that didn't help, what CPU you have on your node. What type of drive is your db on (mechanical, SSD, NVMe)?

At least for me, that is already sevral hours, and I don't have virtually any stales (yes, there are some, but rather blips comparing to what was before),

For me, the next step will be to kick off the farmer from the full node to my harvester. Maybe that will eliminate those stales.

[Jacek-ghub]

If more people have the same problem, I will move this thread to Issues page, as this needs to be fixed.

[stefan-lange]

set log level to warning. That has no impact. The log 'pollution' seems to be no problem. It is ugly and not ok, but no problem. Decreased the total_peer_count from 100 to 30. Every connection now has a block height, this proofs your theory (or knowledge) :).

The farm still does not work properly. I decrease the connections 20 or below and then I go to bed. Waiting for the new day... and new problems ;)

[Jacek-ghub]

You need just one peer to sync. Chia is not parallelizing syncing process. There is some round-robin mechanism, so having more than one peer makes you be less of a leech. 10 is a good number for things like this event.

Although, as I said, potentially the biggest problem is that the code that handles those transactions is a single threaded one, so will choke one core, and at that point the node will start falling behind. There is no simple fix to address that, other than code rewrite.

Actually, my understanding is that RPi 3 is good enough as far as running harvesters. Maybe you could get another RPi, and leave one just for the full node, and the other to host both the farmer and the harvester. That could give some more breathing room to your node.

[stefan-lange]

I have the RPI 4/4GB with old 128 GB MLC SSD and docker swarm, 12 containers, fullnode, farmer and harvester, complete promethus and grafana stack and 2 websites. During normal days, it is >85% in idle.

Since the reduction of the peer count I have no more stales.

[Jacek-ghub]

Yeah, that peer count is a retarded magical number that should not exist in the production code. The network code should adjust to what is out there and play accordingly. To make a p2p network, one can start with just 3 connections (so the network can grow). Of course, that would suck as the network would be really fragile, but it means that anything more than that starts to be workable.

[Jacek-ghub]

By the way, here is a nice chart about for transaction count. It looks like right now a full wave is going on.
https://graphchia.com/Mempool.php
I think that chart is using Pacific time zone, or just reflects what the browser tells it to use.