Execution Worker unexpectedly timeouted

[luizv]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

Yesterday my validator incurred in 4 offenses related to Execution Worker hitting lenient timeout, leading to multiple disputes for voting invalid a valid candidate. Same issue as of #10121.

What happened
During Polkadot's session 12175, my validator luizv/StakeHarvest/v2, triggered 7 disputes regarding invalid voting against valid. It lead to 4 offenses on blocks 29084281 (3 times) and 29084282 (1 time). After 4 offenses over two blocks, my validator was off-chain disabled for 1 session.

Logs
This spammed a couple times before set it for off-chain disabled.

1765831076.164627 dot polkadot[4071360]: 2025-12-15 17:37:56 execution worker exceeded lenient timeout for execution, child worker likely stalled worker_pid=4081918 validation_code_hash=0x8835cd86a709e1491dccb7562a391e6f7f45f79ee6726b309235d9b0225052e0

1765831076.164627 dot polkadot[4071360]: 2025-12-15 17:37:56 execution worker concluded, error occurred: candidate validation: invalid: hard timeout artifact_id=ArtifactId { code_hash: 0x8835cd86a709e1491dccb7562a391e6f7f45f79ee6726b309235d9b0225052e0, executor_params_prep_hash: 0x50b16a713c0f8774ba3a0757c722b48c6eb4c1972f6e58c54fd0851f21a08633 } worker=Worker(1v1) worker_rip=true

1765831076.164627 dot polkadot[4071360]: 2025-12-15 17:37:56 Failed to validate candidate para_id=Id(3369) candidate_hash=0x28a6afca5f97a03efc20eec7edb79838d49cd1587a79a59a7dd01465a0f27243 error=Invalid(HardTimeout) traceID=54034606565267263698501495153445279800

1765831076.164627 dot polkadot[4071360]: 2025-12-15 17:37:56 Detected invalid candidate as an approval checker. reason=Timeout candidate_hash=0x28a6afca5f97a03efc20eec7edb79838d49cd1587a79a59a7dd01465a0f27243 para_id=Id(3369) traceID=54034606565267263698501495153445279800

1765831076.164627 dot polkadot[4071360]: 2025-12-15 17:37:56 New dispute initiated for candidate. candidate_hash=0x28a6afca5f97a03efc20eec7edb79838d49cd1587a79a59a7dd01465a0f27243 session=12175 traceID=54034606565267263698501495153445279800

Steps to reproduce

No idea how to reproduce it, but

Operational Context

• The disputes occurred during node normal operation.

• The problem occurred around 45 minutes after a successful node restart.

• This previous restart was due to changing connection from gateway (4 links, load-balanced) to a single router connected directly, with occurred also with no issues.

• Restart was successful and it operated well for ~40 minutes. Other 3 nodes with same configs didn't presented problems.

• Also no power issues.

• No CPU nor memory issues monitored over prometheus.

• My hardware is really performant and my node was performing really well with A+ rating on turboflakes.

• Run two nodes with this server, a KSM and a DOT. The DOT was the one that incurred on the offenses.

• Specs:

💻 Version: latest, 1.20.2
💻 CPU architecture: x86_64
💻 Target environment: gnu
💻 CPU: INTEL(R) XEON(R) GOLD 6526Y
💻 CPU cores: 16
💻 Memory: 63554MB
💻 Kernel: 6.12.0-55.24.1.el10_0.x86_64
💻 Linux distribution: Red Hat Enterprise Linux 10.0 (Coughlan)

[sandreim]

CC @s0me0ne-unkn0wn

[s0me0ne-unkn0wn]

We measure thread cpu clock using cpu_time::ThreadTime aka CLOCK_THREAD_CPUTIME_ID right? Can you trigger significant variations in the thread cpu clock by hitting swap?

If the thread accesses swapped memory then I'd hope the kernel would pause the thread cpu clock while it swaps the pages out and back in? If not, then that's a problem.

Now the kernel has no information about cpu cache misses, so these could easily run up the thread cpu clock. I've read cpu cache misses cost 300 x on much older architectures, so today god knows what they cost. A swap might even be preferable for accounting since the kernel has recently accessed the same memory, while hopefully not spinning the thread cpu clock.

@burdges swapping out was my first thought, but "no memory issues at prometheus" suggests it's not the cause 🤷
And 64 Gb should be well enough for a validator unless it runs a lot of other tasks.

Some esoteric stuff I may think about from the top of my head... If the worker process were reaped by the OS for some reason and became a zombie for some time because of being stuck in I/O (state db access problems, SSD overheating, etc.?) it still possessed a PID (thus not being reported as the "ambiguous worker death") and was reaped (most likely unsuccessfully) by the PVF host. But such scenarios is hard to debug. I'd start from looking into all the system logs — dmesg, syslog, SSD SMART log for temperature issues — to find something that coincides with the incident.

It's also worth a try to run memtest86+ on the machine.

[burdges]

Afaik cpu cache alone could cause this: (1) It'll go fast if you've some loop that reads and writes but only cycling through an L1 cache sized block of memory. (2) It'll take maybe 1000x longer if you do the same number of reads and writes but hit only one word out of each 64 byte cache line across a some memory buffer much larger than the L3 cache.

If you run both (1) and (2) together of idfferent threads then (1) could take even as long as (2). If you verify a block at the same time as running (2) then you should see a massive slowdown for verifying the block.

At what times do we stress CPU cache?

We're hopefully verifying the PoV data sanely, meaning the PoV data should be one traversal of the state tree, adding leaves where required, and copath elements whenever we do not require deeper. I'm worred we do not do this because of the past interest in gziping the blocks, but hopefully. Assumine the sane way, then we access each copath element exactly one time, meaning this looks like (2) above. We'd benefit from using cpu instructions that speed up cache eviction for the copath elements, but maybe not for the data elements in the PoV data, although wasm might not support these instructions.

As an aside, we employ fixed base scalar multiplications in schnorr signatures like ed25519 and sr25519, both for the nonce during signing, and for the proof part s during verifying, via {EdwardsPoint,Ristretto}::vartime_double_scalar_mul_basepoint. These fixed base scalar multiplications speeds up computation using what looks like a 24kb table, which works the cpu cache kinda hard. At present we check each signature seperately, but if we do batch verification then this disapears into a single table access during on_finalize. in theory, batch verification would only save 40% of the CPU time, but avoiding 24kb going into CPU cache maybe saves way more.

I suppose the PVF artifact precheck, and even just PVF artifact loading, would not be cache friendly either, but loading would depends upon how the kernel instructs the cache during these operations. And swap could similarly be cache friendly or unfriendly depending upo the applicaiton.

[burdges]

Another thought, it might depend how the data winds up distributed in the drive. If the kernel loads data from disk, then it might "bill" that time to the thread cpu clock for the requesting process, maybe not the fetching time, but surely the process' own async polling time. Assuming the SSDs internal cache only knows sectors, and maybe levelling etc, then if some file winds up spread wildly, then fetching could be unfriendly to the SSD cache, and have much longer load times. We might've some places where we should do a sync after doing mmap, but before starting the block verificaiton.

[s0me0ne-unkn0wn]

Assumine the sane way, then we access each copath element exactly one time, meaning this looks like (2) above.

It's a beautiful hypothesis, but why the hell do we hit it on a single validator in the whole network, then? I bet we have quite a few validators running on Xeon Gold with the same cache architecture and coherence protocol. As a general thought, if only a single validator causes a problem, I'd blame the validator hardware, setup, or OS, not our code.

Another thought, it might depend how the data winds up distributed in the drive.

Candidates being validated on validators do not have storage access (they are not even provided with corresponding externalities). Only Merkle proofs are checked.

[luizv]

I bet we have quite a few validators running on Xeon Gold with the same cache architecture and coherence protocol.

I failed to mention it, but I'm running a KSM and a DOT on the same server, for the last 3 months. Problem occurred only with the DOT one.
Also a couple months ago I disabled THP and didn't had any swap memory spiking since then.