eth/tracers: support for golang tracers + add golang callTracer

[s1na]

Implements a native call tracer along with a way to register such native tracers. Custom tracers can be implemented that adhere to the interface and dropped in ./eth/tracers/native while calling Register(name, constructorFn) in their init function.

[s1na]

Weird that for some cases it's slower than the new js call tracer:

Tracers/create-8                      29.5µs ± 1%    41.2µs ± 1%   +39.98%  (p=0.008 n=5+5)
Tracers/deepCalls-8                   3.57ms ± 6%    0.35ms ± 0%   -90.22%  (p=0.016 n=5+4)
Tracers/delegatecall-8                 256µs ± 2%      41µs ± 0%   -84.09%  (p=0.008 n=5+5)
Tracers/innerCreateOogOuterThrow-8     220µs ± 1%      91µs ± 1%   -58.87%  (p=0.008 n=5+5)
Tracers/innerInstafail-8              9.37µs ± 2%   12.30µs ± 2%   +31.17%  (p=0.008 n=5+5)
Tracers/innerThrowOuterRevert-8        158µs ± 1%      38µs ± 1%   -75.80%  (p=0.008 n=5+5)
Tracers/oog-8                         19.9µs ± 1%    23.3µs ± 0%   +17.04%  (p=0.008 n=5+5)
Tracers/revert-8                      10.8µs ±12%    12.2µs ± 1%   +12.83%  (p=0.016 n=5+5)
Tracers/revertReason-8                17.3µs ± 1%    18.0µs ± 1%    +4.48%  (p=0.008 n=5+5)
Tracers/selfdestruct-8                 242µs ± 2%      18µs ± 1%   -92.45%  (p=0.008 n=5+5)
Tracers/simple-8                       235µs ± 2%      25µs ± 0%   -89.19%  (p=0.008 n=5+5)
Tracers/throw-8                       17.7µs ± 2%    18.2µs ± 0%    +3.03%  (p=0.016 n=5+4)

Edit: seems like allocations are higher for the slow cases:

Tracers/create-8                      8.97kB ± 0%   33.73kB ± 0%  +275.84%  (p=0.000 n=10+10)
Tracers/deepCalls-8                    113kB ± 0%     115kB ± 0%    +1.34%  (p=0.000 n=10+10)
Tracers/delegatecall-8                12.1kB ± 0%    14.0kB ± 0%   +16.31%  (p=0.000 n=10+10)
Tracers/innerCreateOogOuterThrow-8     113kB ± 0%      91kB ± 0%   -19.42%  (p=0.000 n=10+10)
Tracers/innerInstafail-8              3.42kB ± 0%    5.74kB ± 0%   +68.15%  (p=0.000 n=10+10)
Tracers/innerThrowOuterRevert-8       8.51kB ± 0%   10.54kB ± 0%   +23.89%  (p=0.000 n=10+6)
Tracers/oog-8                         4.07kB ± 0%    6.57kB ± 0%   +61.36%  (p=0.000 n=8+10)
Tracers/revert-8                      2.93kB ± 0%    6.85kB ± 0%  +133.95%  (p=0.000 n=10+9)
Tracers/revertReason-8                4.57kB ± 0%    7.40kB ± 0%   +62.03%  (p=0.000 n=9+9)
Tracers/selfdestruct-8                7.16kB ± 0%    9.21kB ± 0%   +28.53%  (p=0.000 n=9+10)
Tracers/simple-8                      7.18kB ± 0%    9.58kB ± 0%   +33.49%  (p=0.000 n=10+10)
Tracers/throw-8                       3.93kB ± 0%    6.17kB ± 0%   +56.99%  (p=0.000 n=10+9)

Edit2: To my surprise even commenting out all of the native call tracer's logic leads to 8776 bytes alloc in Tracers/create which is equivalent to that of the JS call tracer. I'm starting to think the allocs reported for the JS tracer are not accurate, maybe because of cgo?

[s1na]

The benchmark wasn't doing GetResult and that made the difference because the native tracer does some work on start which js tracer does only in result. Now we're talking:

name                                old time/op    new time/op    delta
Tracers/create-8                      7.86ms ± 4%    0.06ms ±11%  -99.26%  (p=0.008 n=5+5)
Tracers/deepCalls-8                   11.6ms ± 1%     0.4ms ± 1%  -96.69%  (p=0.008 n=5+5)
Tracers/delegatecall-8                7.65ms ± 3%    0.05ms ± 2%  -99.37%  (p=0.008 n=5+5)
Tracers/innerCreateOogOuterThrow-8    8.04ms ± 0%    0.12ms ± 1%  -98.49%  (p=0.016 n=4+5)
Tracers/innerInstafail-8              7.70ms ± 5%    0.02ms ± 4%  -99.78%  (p=0.008 n=5+5)
Tracers/innerThrowOuterRevert-8       7.64ms ± 3%    0.04ms ± 0%  -99.41%  (p=0.008 n=5+5)
Tracers/oog-8                         7.72ms ± 1%    0.03ms ± 1%  -99.63%  (p=0.008 n=5+5)
Tracers/revert-8                      7.62ms ± 1%    0.02ms ± 1%  -99.77%  (p=0.008 n=5+5)
Tracers/revertReason-8                7.78ms ± 9%    0.02ms ± 1%  -99.70%  (p=0.008 n=5+5)
Tracers/selfdestruct-8                7.58ms ± 2%    0.02ms ± 3%  -99.69%  (p=0.008 n=5+5)
Tracers/simple-8                      7.54ms ± 1%    0.03ms ± 3%  -99.59%  (p=0.008 n=5+5)
Tracers/throw-8                       7.47ms ± 4%    0.02ms ± 2%  -99.70%  (p=0.008 n=5+5)

[holiman]

🤯

[holiman]

But wait. What are you comparing to?
The current js tracer should already be in the sub-ms region: #23087 (comment)

EDIT: Ah, I see, the result was deferred. I agre it should be included in the benchmark, yes, the way you've done it here

[holiman]

The native tracer, when doing calltracer, took 2 hours to reach the point where it could swap out the mem-trie to a disk-trie

Previously, when I did the native no-op-tracer, it was almost the same time -- a bit less than 2 hours until the mem-drop. That's pretty cool, it means that the tracecall overhead is almost negligible for the native tracer.

[holiman]

native call-tracer results:

INFO [11-04|23:54:59.040] Chain tracing finished                   start=13,401,259 end=13,431,259 transactions=5,786,835 elapsed=4h25m6.580980692s

[holiman]

Some more charts

The run is not finished yet, but looks like a factor 2.5 speedup between native calltracer vs duktape calltracer (started at midnight). First native-memdrop after 2 hours, first js-memdrop after 4h30m.

[holiman]

Doing some comparisons. Here's the first difference I found

native:
00000000000000000000000000000000000000000000000","output":"0x","error":"execution reverted"}},{"resu
jscript:
00000000000000000000000000000000000000000000000","error":"execution reverted"}},{"result":{"type":"C

[holiman]

And we have the results in:

INFO [11-04|23:54:59.040] Chain tracing finished                   start=13,401,259 end=13,431,259 transactions=5,786,835 elapsed=4h25m6.580980692s

vs js:

INFO [11-05|10:05:46.920] Chain tracing finished                   start=13,401,259 end=13,431,259 transactions=5,786,835 elapsed=10h0m33.057605432s

4h25 vs 10h0m

[holiman]

LGTM. However, apparently this is not covered by the tests, think you can add a test that flags this?

[holiman]

Not required for this PR though

[holiman]

For the most part, the diffs seem to be of the type

{
    ...skipped 1 object property...,
    "params": {
        "result": {
            "traces": [
                ...skipped 179 array elements...,
                {
                    "result": {
                        ...skipped 6 object properties...,
                        "output": "0x" => "",
                        ...skipped 3 object properties...
                    }
                },
                ...skipped 29 array elements...
            ]
        }
    }
}

But if I work around it by applying your patch in the parser, it works fine (it's gone through 20K blocks now, comparing the outputs)

[FeurJak]

I have to say that this is some amazing work.. My CallTracer calls have gone down now from avg. ~20ms to avg. ~6ms when using the native Call Tracer. You guys are on another level.