geth t8n is 2x slower when built with `make all`

[winsvega]

Rationale

Currently because of teh kzg module, tests execution/generation on geths t8n takes very long time. not as bad as ethereumjs or besu but still very long time. If init t8n as a daemon all init operations could be done once, and then listener can accept and process t8n calls. Also would be possible to run remote t8n.

Implementation

t8n daemon process that listen requests on http kind of socket. Example from ethereumjs request

curl -X POST -d "${1} ${2} ${3} ${4} ${5} ${6} ${7} ${8} ${9} ${10} ${11} ${12} ${13} ${14} ${15} ${16} ${17} ${18} ${19} ${20}" --silent http://localhost:3000/

[holiman]

We've discussed this a bit. It's a tad complicated.

We could parse the input line with the flag library, and would then interpret the line as if it were input to the main program. However, some of the inputs can be stdin, like --input.env=stdin, which would make it read from stdin. And that would clash with this feature (if the next line is read from stdin. If the next cmd is read from http server, then this would still be a bit undefined and wonky).

A potentially better quickfix would be to add a possibility to not init kzg. It would panic if kzg is used, but would be faster otherwise. Would that work?

[karalabe]

@winsvega Can you please provide an example where this is getting slow? KZG is lazy inited in our code on first use (and was always like that) apart from Geth startup, which you are not using in t8n.

[karalabe]

time evm t8n --input.alloc=./testdata/1/alloc.json --input.txs=./testdata/1/txs.json --input.env=./testdata/1/env.json --state.fork=Berlin

34ms

[winsvega]

Registering geth evm performance drop on 11th of may

Last good commit #0fb1be0 Bad results commit #2169fa3

Exex time on legacy tests 7300 vs 4300

The test generation now from 6k jumped to 16k State test run from 3k to 6k So since 11th of may it got even worse

[holiman]

Current master:

[user@work evm]$ time for i in {1..100}; do ./evm-master t8n --input.alloc=./testdata/1/alloc.json --input.txs=./testdata/1/txs.json --input.env=./testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m5.167s
user    0m3.884s
sys 0m1.713s

The 'bad' commit:

[user@work evm]$ time for i in {1..100}; do ./evm-2169fa3 t8n --input.alloc=./testdata/1/alloc.json --input.txs=./testdata/1/txs.json --input.env=./testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m5.231s
user    0m3.938s
sys 0m1.762s

And the 'last good':

[user@work evm]$ time for i in {1..100}; do ./evm-0fb1be0 t8n --input.alloc=./testdata/1/alloc.json --input.txs=./testdata/1/txs.json --input.env=./testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m5.152s
user    0m3.888s
sys 0m1.689s

I am not able to reproduce any differences

[winsvega]

I narrowed down the issue to this line. With this line I get 100 seconds increase on 5000 t8n calls

https://github.com/ethereum/go-ethereum/pull/27155/files#diff-23cbee8dfceeffd19bd666419f9dd598398795d8638d6a7e0c6fa245f97a98caR58

[holiman]

I redid the test, this time not doing go build.. but using make The 'last good' clocks in at 5s:

[user@work bin]$ time for i in {1..100}; do ./evm-0fb1be0 t8n --input.alloc=../../cmd/evm/testdata/1/alloc.json --input.txs=../../cmd/evm/testdata/1/txs.json --input.env=../../cmd/evm/testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m5.156s
user    0m3.868s
sys 0m1.616s

The 'bad' commit bumps it to 7s:

[user@work bin]$ time for i in {1..100}; do ./evm-2169fa3 t8n --input.alloc=../../cmd/evm/testdata/1/alloc.json --input.txs=../../cmd/evm/testdata/1/txs.json --input.env=../../cmd/evm/testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m7.371s
user    0m6.010s
sys 0m1.794s
[user@work bin]$ 

And current master at 7s

[user@work bin]$ time for i in {1..100}; do ./evm-ceca4578 t8n --input.alloc=../../cmd/evm/testdata/1/alloc.json --input.txs=../../cmd/evm/testdata/1/txs.json --input.env=../../cmd/evm/testdata/1/env.json --state.fork=Berlin 2>/dev/null ;  done

real    0m7.339s
user    0m5.999s
sys 0m1.826s

So yes, the issue is reproducable, but needs to use the make system, which in essence is go run build/ci.go install ./cmd/evm.

[holiman]

Can be reproed using just evm -h too, showing that it's nothing to do with actual evm execution.

[user@work bin]$ time for i in {1..100}; do ./evm-0fb1be0 t8n -h >/dev/null ;  done

real    0m4.718s
user    0m3.494s
sys 0m1.370s
[user@work bin]$ time for i in {1..100}; do ./evm-2169fa3 t8n -h >/dev/null ;  done

real    0m7.161s
user    0m5.798s
sys 0m1.580s

So it appears that the BLST_PORTABLE compiler directive to blst somehow adds ~25ms static startup overhead time.

[holiman]

This seems fixed now Compiled by go run build/ci.go install ./cmd/evm:

[user@work go-ethereum]$ time for i in {1..100}; do ./build/bin/evm t8n -h >/dev/null ;  done

real    0m5.879s
user    0m4.460s
sys     0m1.726s
[user@work go-ethereum]$ time for i in {1..100}; do ./build/bin/evm t8n -h >/dev/null ;  done

real    0m4.938s
user    0m3.657s
sys     0m1.595s

Compiled by go build ./cmd/evm:

[user@work go-ethereum]$ time for i in {1..100}; do ./evm t8n -h >/dev/null ;  done

real    0m5.443s
user    0m4.113s
sys     0m1.707s
[user@work go-ethereum]$ time for i in {1..100}; do ./evm t8n -h >/dev/null ;  done

real    0m5.411s
user    0m4.060s
sys     0m1.717s