debug_traceCall timeout not respected

[Doucars]

System information

Geth version: v1.2.4
OS & Version: Linux

Expected behaviour

When using debug_traceCall with "timeout": "200ms", there should be a timeout error after 200ms of processing.

Actual behaviour

The timeout occurs sometimes after more than 200ms that cause the node to potentially slow down.

Backtrace

t=2023-05-31T21:00:13+0000 lvl=warn msg="Served debug_traceCall"                 reqid=1      t=2.183403272s             err="execution timeout at step (<eval>:1:1(0))    in server-side tracer function 'step'" X-Forwarded-For=nil
t=2023-05-31T21:00:13+0000 lvl=warn msg="Served debug_traceCall"                 reqid=1      duration=2.183402988s err="execution timeout at step (<eval>:1:1(0))    in server-side tracer function 'step'"
t=2023-05-31T21:00:13+0000 lvl=warn msg="Served debug_traceCall"                 reqid=1      t=2.215554813s             err="execution timeout at step (<eval>:1:1(0))    in server-side tracer function 'step'" X-Forwarded-For=nil
t=2023-05-31T21:00:13+0000 lvl=warn msg="Served debug_traceCall"                 reqid=1      duration=2.215554529s err="execution timeout at step (<eval>:1:1(0))    in server-side tracer function 'step'"

[deepcrazy]

Hi there, Is it for mainnet or testnet? And what are your hardware specs?

Can you also provide more logs while this error occurred please. Also please the sharing following as well:

• startup command
• Is there any issue in node syncing? If so, what is the output of eth.syncing, eth.blockNumber, and net.peerCount during the time of this issue?

P.S: Which snapshot you used if running mainnet (full node - official one or fast node - 48Club one)?
Thanks.

[MatusKysel]

@Doucars timeout doesn't stop tracer straight away. Here is important comment from the code.

// Stop terminates execution of the tracer at the first opportune moment.

[MatusKysel]

but if you provide more info e.g. contract + call you are calling I could debug it if this is actually happening

[Doucars]

Hi there, Is it for mainnet or testnet? And what are your hardware specs?

Can you also provide more logs while this error occurred please. Also please the sharing following as well:

• startup command
• Is there any issue in node syncing? If so, what is the output of eth.syncing, eth.blockNumber, and net.peerCount during the time of this issue?

P.S: Which snapshot you used if running mainnet (full node - official one or fast node - 48Club one)? Thanks.

Thank you for your answer.

Network: mainnet / Fast node using 48Club snapshot
Hardware: Intel Core i9-9900K / 64GB RAM DDR4 / 2TB SSD NVME
Startup command: ./geth/build/bin/geth --config ./config.toml --datadir ./node --cache 4096 --http --ws --tries-verify-mode none --rpc.allow-unprotected-txs --txlookuplimit 0 --syncmode full --pruneancient --diffsync --metrics

I do not have any syncing issues and maxpeers is set to 300. The value of net.peerCount is 300.
I can't provide more logs actually as the log level is set to info. I am going to modify it to debug.

I am sending around 50 debug_traceCall per second on my node and these timeout errors happen a few times per second. I always run these call on latest block so a full node is not necessary I think. When a debug_traceCall takes a lot of time, what happens ? Can other debug_traceCall be run in parallel or the node is stuck and can't do anything else ?

[chengjiao]

I am indexing the block by debug_traceBlockByNumber once there is any block sync'd done.

the node is full node and keeps sync'd with the latest hight, only the debug trace is low.

this is the log I get:

2023-06-19_14:23:00 slow rpcWrapper debug_traceBlockByNumber 29239889 1.1425981521606445
2023-06-19_14:23:04 slow rpcWrapper debug_traceBlockByNumber 29239890 2.963583469390869
2023-06-19_14:23:08 slow rpcWrapper debug_traceBlockByNumber 29239892 2.2410926818847656

2023-06-19_14:23:37 slow rpcWrapper debug_traceBlockByNumber 29239901 2.26417875289917
2023-06-19_14:23:43 slow rpcWrapper debug_traceBlockByNumber 29239903 4.490878582000732
2023-06-19_14:23:47 slow rpcWrapper debug_traceBlockByNumber 29239904 2.028808355331421
2023-06-19_14:23:57 slow rpcWrapper debug_traceBlockByNumber 29239905 9.542121887207031

[MatusKysel]

@Doucars do you know how to build bsc from source code? I have PR #1739 with timer cancellation in API handler, this should resolve your issue. I would be nice if you could confirm that