Tracing in 1.10 no longer returns results immediately

[tanmaster]

System information

Geth versions: 1.10.1-stable and 1.9.25-stable
OS & Version: Ubuntu 20.04.2 LTS (5.4.0-54-generic) and macOS Big Sur 11.2.2

Expected behaviour

When chain tracing via the Json RPC under 1.9.25-stable, the results of the processed transaction are returned immediately and I can instantly process them further. This does not happen under 1.10.*

Actual behaviour

Under 1.10.*, the results are no longer immediately returned. It seems geth is regenerating the state snapshots first (?) before returning any result. This is kind of undesired when tracing large chain segments, as it may take hours before returning any result.
Also, using htop I can observe geth's RAM usage growing while the historical state is regenerated. When the tracing range is large enough (e.g. block 0x0 to block 0xfffff) geth starts taking up my computer's entire memory before having finished state regeneration, and thus my system is becoming unresponsive before any result is returned.

This does not happen under version 1.9.25-stable. I can still observe a slight raise in memory usage, but nowhere as fast as in 1.10.1-stable. Results are returned to e.g. netcat immediately and i assume the regenerated states aren't kept in memory(?)

Steps to reproduce the behaviour

• Start geth using e.g.: ./build/bin/geth --rinkeby --maxpeers=0
• Connect via netcat to UDS socket: nc -U geth.ipc
• Issue command e.g. {"id": 1, "method": "debug_subscribe", "params": ["traceChain", "0x0", "0xfffff", {"tracer": "4byteTracer"}]} (when using a too small block range you might not notice the difference)

Doing these steps in both versions will result in the different behaviors described above.

I am unsure whether or not this is a bug. If this is intended behavior I would be very glad for some help on how to do chaintracing with custom JS tracers for the entire chain in the newest version. Also there seems to be another problem with JS tracers timing out instantly on most transactions, but I think that belongs into another issue...

[karalabe]

Ugh, this is a super ugly regression, #22161 made the chain tracer blocking instead of async :/

[karalabe]

@tanmaster Did chain tracing work for you in 1.9.25? We've found a bug which seems to almost always result in transaction traces reporting timeouts. How did you manage to do chainTracing?

[tanmaster]

I experienced the same issue. To circumvent, I commented out the line that was responsible for cancelation upon timeout.
Its line 746 in the following Screenshot (it was another line number in 1.9.25-stable before the code was refactored):

It worked fine for my use case and I was gonna make an issue about it, but you were faster than me :-)

[karalabe]

Ahahaha, ok then. :)

[tanmaster]

@tanmaster Did chain tracing work for you in 1.9.25? We've found a bug which seems to almost always result in transaction traces reporting timeouts. How did you manage to do chainTracing?

Quick question: will a fix for the timeout issue make it into version 1.10.2?

[karalabe]

There are some quite deeper issues that were broken in chain tracing. Working on it now.

[tanmaster]

Thank you for your work!!
Unfortunately, on the current master (commit a600dab) I am getting the following warning when issuing the RPC command of my original post:
WARN [04-07|16:11:35.456] Chain tracing failed start=0 end=255 transactions=0 elapsed=1.153217ms err="genesis state is missing"

Whats the reason for this? Do I need to let my node sync completely first before i can start chain tracing?

[karalabe]

Thx for the heads up, looking into it.

[karalabe]

@tanmaster Please check #22629

[tanmaster]

@tanmaster Please check #22629

Yes, this seems to have fixed the issue. Thank you very much 🙏🙏