[BUG] observing peer can't change a role

[timofeevmd]

OS and Environment

longevity cluster: linux x86, k8s, 5 peer's, 2.9 vCPU/6RAM on each peer

GIT commit hash

f348b9a

Minimum working example / Steps to reproduce

When conducting performance testing to find the maximum capacity, I encountered an issue with transaction queue buildup on one of the peers.

Based on the data obtained from Grafana, logs, and profiling tools, I assume that the problem is related to errors occurring when attempting to change the role of a specific peer after each round of Iroha.

To obtain a comprehensive analysis of the current state of the product, three performance tests were conducted:

1. With the PARCA profiler enabled
2. With the profiler disabled and logging level set to INFO
   Test start time: 2025-02-26 11:53:36
   Test end time: 2025-02-26 11:58:36

After the test was completed, we observed only peer synchronization.
The issue with queue desynchronization was observed on peers iroha2-1 and iroha2-4, whose roles are observing peer.

Test result:

• open search
• transaction of iroha
• utilization
• k8s utilization

3. With the profiler disabled and logging level set to TRACE
   Test result:

• open search
• transaction of iroha
• utilization
• k8s utilization

Since the issue was observed in all three tests with identical characteristics, we can assume that the data obtained from different tests is consistent.

Full logs are attached to this ticket.

During the tests, the issue was observed on peers iroha2-0 and iroha2-2.

PREPARATION LONGEVITY ENV

Access to standard monitoring tools

On the perf generator

git clone https://github.com/soramitsu/iroha2-perf.git &&
git checkout iroha/2_0_0-rc_1/keypair &&
cd performance-generator/ &&
mvn -N io.takari:maven:wrapper &&
./mvnw gatling:test -Dgatling.simulationClass=simulation.transactions.standard.TransferAssetSimulation -DtargetURL= -DremoteLogin= -DremotePassword= -Dintensity=67000 -DrampDuration=300 -DmaxDuration=301

Actual result

Peers are not synchronizing, errors occur when changing the peer's role, and there is a message about forced container shutdown.

Expected result

Peers are synchronizing, no errors occur when changing the peer's role.

Logs

log files:

• logs_iroha2_0.log
• logs_iroha2_2.log
• logs_iroha2_3.log

parca profile

• https://pprof.me/0fdba38b151786ecc7938b88bd35cf1e
• profile (2).pb.gz

Who can help to reproduce?

@timofeevmd @RamilMus

Notes

No response

[0x009922]

Managed to set up a local environment and reproduce a similar picture. Here is a preliminary analysis.

Environment:

• 5 peers, genesis with 1 domain, account, and asset.
• Submitting 10,000 transactions, randomly to all peers, with 1 second delay.
• All of the transactions are rejected.
• Metrics are collected each 5 seconds.

Analysis:

• Unlike others, peer_3 and peer_4 are struggling with the queue. Remarkably, initially their rate is exactly the same.
• peer_3, and later peer_4, start to fall behind in sync
• The turning point seems to be some acute expansion of the queue.
• The lag starts slightly before the time the queue is full.

From the logs of peer_3 I see it starts to log "Block validation error" repeatedly, with the expected block being further and further behind:

PrevBlockHeightMismatch { expected: 382, actual: 383 }
PrevBlockHeightMismatch { expected: 383, actual: 384 }
PrevBlockHeightMismatch { expected: 383, actual: 385 }
PrevBlockHeightMismatch { expected: 383, actual: 386 }
PrevBlockHeightMismatch { expected: 383, actual: 387 }
PrevBlockHeightMismatch { expected: 383, actual: 388 }
PrevBlockHeightMismatch { expected: 383, actual: 389 }
PrevBlockHeightMismatch { expected: 387, actual: 390 }
PrevBlockHeightMismatch { expected: 387, actual: 391 }
PrevBlockHeightMismatch { expected: 387, actual: 392 }
PrevBlockHeightMismatch { expected: 387, actual: 393 }
PrevBlockHeightMismatch { expected: 387, actual: 394 }
PrevBlockHeightMismatch { expected: 387, actual: 395 }
PrevBlockHeightMismatch { expected: 387, actual: 396 }
PrevBlockHeightMismatch { expected: 387, actual: 397 }

[0x009922]

Observing peer is not supposed to change a role, by the way.

My current working hypothesis is the following:

Actually, I've just got an idea what could be the issue and why it occurs with the ObservingPeer only. Sumeragi works in a way so that all other, non-observing peers are rotating roles. Each peer becomes a leader every other round. When a peer is Leader, it creates a block from its local transactions cache, emptying it. So, all peers have this opportunity to eventually empty their local cache.

It is fortunate, because sometimes, on high load, some transactions do not reach other peers through gossiping. This leads to local cache being isolated from others to some extent.

So, what happens to the ObservingPeer, I suppose, is that it overflows with these local transactions, which others never happen to know about. The ObservingPeer itself cannot get rid of them because it never¹ becomes a Leader. Thus, it becomes stuck.

Footnotes

1. When the system is on a really high load and all peers have full queues, peers rotate their roles completely. I observed this happening, though haven't researched why exactly this behaviour happens. Anyway, it isn't the point of this issue. ↩

[timofeevmd]

проведены новые тесты с понижением нагрузки
1 test:
params:
performace volume: -Dintensity=33500 -DrampDuration=300 -DmaxDuration=301
iroha config

[logger]
level = "INFO"
format = "json"

[network]
block_gossip_period_ms = 10_000
transaction_gossip_size = 500
transaction_gossip_period_ms = 1000
idle_timeout_ms = 10_000

[queue]
capacity = 655360
capacity_per_user = 655360
transaction_time_to_live_ms = 86400000

Result:
opensearch

Kubernetes Deployments

Transaction

test 2
params:
performance volume: -Dintensity=33500 -DrampDuration=300 -DmaxDuration=301
iroha config: transaction_gossip_size = 500 -> transaction_gossip_size = 2000

[logger]
level = "INFO"
format = "json"

[network]
block_gossip_period_ms = 10_000
transaction_gossip_size = 2000 -> 4000
transaction_gossip_period_ms = 1000 -> 500
idle_timeout_ms = 10_000

[queue]
capacity = 655360
capacity_per_user = 655360
transaction_time_to_live_ms = 86400000

Result
open search

Kubernetes Deployment

Transaction

I also tried running the test with modified parameters... The results are the same: one or two peers cannot synchronize, and their queues keep growing. I will provide more detailed information with logs and graphs soon.

[timofeevmd]

test 1
performance volume: -Dintensity=33500 -DrampDuration=300 -DmaxDuration=301

Config

[logger]
level = "TRACE"
format = "json"

[network]
block_gossip_period_ms = 10_000
transaction_gossip_size = 4000
transaction_gossip_period_ms = 500
idle_timeout_ms = 10_000

[queue]
capacity = 655360
capacity_per_user = 655360
transaction_time_to_live_ms = 86400000

open search

Kubernetes deployment

Transaction

test 2

performance volume: -Dintensity=43000 -DrampDuration=300 -DmaxDuration=301

Config

[logger]
level = "TRACE"
format = "json"

[network]
block_gossip_period_ms = 10_000
transaction_gossip_size = 4000
transaction_gossip_period_ms = 500
idle_timeout_ms = 10_000

[queue]
capacity = 655360
capacity_per_user = 655360
transaction_time_to_live_ms = 86400000

open search

Kubernetes deployment

Transaction

[0x009922]

Hi @timofeevmd, that's interesting. But I am a bit confused as for what exact parameters are set for each test. In the TOML snippets you've provided there is an invalid syntax and they are all the same. Could you perhaps update them with actual config you've set?

In the meantime, I'll post here an update in my investigation. I've somewhat proved that the reason ObservingPeer falls behind is due to the queue overflow with unique transactions. Here are some charts:

The background on the last chart shows the amount of unique transactions peer has in its queue.

It is also visible here that peer_3 doesn't fall behind in block sync immediately upon reaching its queue limits. I am investigating why this primary issue happens.

[timofeevmd]

snippets was fixed