Instruction tracing with EIP-3155 JSONL output #325

chfast · 2021-05-14T15:17:00Z

Implementation of EVM tracing following the EIP-3155 (draft). It outputs log line with JSON (jsonl) for every instruction to standard error output.

Differences from the spec:

All calls start with non-standard "start call" log:

{"kind":"call","static":false,"depth":0,"rev":"Berlin"}

All calls end with non-standard "end call" log as a replacement for single summerical info at the end of transaction execution.
```
{"error":null,"gas":964766,"gasUsed":35234,"output":"da39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000"}
```
- the "stateRoot" is omitted as there is no way to compute it,
- the "error" is taken from the instruction trace log, replaces "pass" or "successful".
The "gasCost" is omitted. This is difficult to compute as "dynamic" gas cost is calculated together with execution but the spec forces these to be separated.
The "depth" is omitted as already presented in "start call".
The "returnData" is not implemented. This is doable, but seems unnecessary because this is available in "output" in "end call".
The "refund" is omitted, currently not doable.
The "memory" was initially implemented, then removed because makes traces huge. It is recommended to enabled it with a flag. This is easy to implement in future.

Example (SHA1):

{"kind":"call","static":false,"depth":0,"rev":"Berlin"}
{"pc":0,"op":96,"opName":"PUSH1","gas":1000000,"stack":[],"memorySize":0}
{"pc":2,"op":96,"opName":"PUSH1","gas":999997,"stack":["0x80"],"memorySize":0}
{"pc":4,"op":82,"opName":"MSTORE","gas":999994,"stack":["0x40","0x80"],"memorySize":0}
{"pc":5,"op":52,"opName":"CALLVALUE","gas":999982,"stack":[],"memorySize":96}
{"pc":6,"op":128,"opName":"DUP1","gas":999980,"stack":["0x0"],"memorySize":96}
{"pc":7,"op":21,"opName":"ISZERO","gas":999977,"stack":["0x0","0x0"],"memorySize":96}
{"pc":8,"op":97,"opName":"PUSH2","gas":999974,"stack":["0x1","0x0"],"memorySize":96}
{"pc":11,"op":87,"opName":"JUMPI","gas":999971,"stack":["0x10","0x1","0x0"],"memorySize":96}
{"pc":16,"op":91,"opName":"JUMPDEST","gas":999961,"stack":["0x0"],"memorySize":96}
{"pc":17,"op":80,"opName":"POP","gas":999960,"stack":["0x0"],"memorySize":96}

...

{"pc":1207,"op":23,"opName":"OR","gas":964862,"stack":["0xda39a3ee5e6b4b0d3255bfef0000000000000000","0x9560189000000000","0xafd80709","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0x0","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1208,"op":23,"opName":"OR","gas":964859,"stack":["0xda39a3ee5e6b4b0d3255bfef9560189000000000","0xafd80709","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0x0","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1209,"op":96,"opName":"PUSH1","gas":964856,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0x0","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1211,"op":27,"opName":"SHL","gas":964853,"stack":["0x60","0xda39a3ee5e6b4b0d3255bfef95601890afd80709","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0x0","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1212,"op":148,"opName":"SWAP5","gas":964850,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0x0","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1213,"op":80,"opName":"POP","gas":964847,"stack":["0x0","0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1214,"op":80,"opName":"POP","gas":964845,"stack":["0xda39a3ee005e6b4b0d003255bfef009560189000afd80709","0x40","0x0","0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1215,"op":80,"opName":"POP","gas":964843,"stack":["0x40","0x0","0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1216,"op":80,"opName":"POP","gas":964841,"stack":["0x0","0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1217,"op":80,"opName":"POP","gas":964839,"stack":["0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1218,"op":145,"opName":"SWAP2","gas":964837,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xa0","0xd6","0x1605782b"],"memorySize":512}
{"pc":1219,"op":144,"opName":"SWAP1","gas":964834,"stack":["0xd6","0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":1220,"op":80,"opName":"POP","gas":964831,"stack":["0xa0","0xd6","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":1221,"op":86,"opName":"JUMP","gas":964829,"stack":["0xd6","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":214,"op":91,"opName":"JUMPDEST","gas":964821,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":215,"op":96,"opName":"PUSH1","gas":964820,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":217,"op":128,"opName":"DUP1","gas":964817,"stack":["0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":218,"op":81,"opName":"MLOAD","gas":964814,"stack":["0x40","0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":219,"op":107,"opName":"PUSH12","gas":964811,"stack":["0xa0","0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":232,"op":25,"opName":"NOT","gas":964808,"stack":["0xffffffffffffffffffffffff","0xa0","0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":233,"op":144,"opName":"SWAP1","gas":964805,"stack":["0xffffffffffffffffffffffffffffffffffffffff000000000000000000000000","0xa0","0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":234,"op":146,"opName":"SWAP3","gas":964802,"stack":["0xa0","0xffffffffffffffffffffffffffffffffffffffff000000000000000000000000","0x40","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x1605782b"],"memorySize":512}
{"pc":235,"op":22,"opName":"AND","gas":964799,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0xffffffffffffffffffffffffffffffffffffffff000000000000000000000000","0x40","0xa0","0x1605782b"],"memorySize":512}
{"pc":236,"op":130,"opName":"DUP3","gas":964796,"stack":["0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x40","0xa0","0x1605782b"],"memorySize":512}
{"pc":237,"op":82,"opName":"MSTORE","gas":964793,"stack":["0xa0","0xda39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000","0x40","0xa0","0x1605782b"],"memorySize":512}
{"pc":238,"op":81,"opName":"MLOAD","gas":964790,"stack":["0x40","0xa0","0x1605782b"],"memorySize":512}
{"pc":239,"op":144,"opName":"SWAP1","gas":964787,"stack":["0xa0","0xa0","0x1605782b"],"memorySize":512}
{"pc":240,"op":129,"opName":"DUP2","gas":964784,"stack":["0xa0","0xa0","0x1605782b"],"memorySize":512}
{"pc":241,"op":144,"opName":"SWAP1","gas":964781,"stack":["0xa0","0xa0","0xa0","0x1605782b"],"memorySize":512}
{"pc":242,"op":3,"opName":"SUB","gas":964778,"stack":["0xa0","0xa0","0xa0","0x1605782b"],"memorySize":512}
{"pc":243,"op":96,"opName":"PUSH1","gas":964775,"stack":["0x0","0xa0","0x1605782b"],"memorySize":512}
{"pc":245,"op":1,"opName":"ADD","gas":964772,"stack":["0x20","0x0","0xa0","0x1605782b"],"memorySize":512}
{"pc":246,"op":144,"opName":"SWAP1","gas":964769,"stack":["0x20","0xa0","0x1605782b"],"memorySize":512}
{"pc":247,"op":243,"opName":"RETURN","gas":964766,"stack":["0xa0","0x20","0x1605782b"],"memorySize":512}
{"error":null,"gas":964766,"gasUsed":35234,"output":"da39a3ee5e6b4b0d3255bfef95601890afd80709000000000000000000000000"}

sha1.txt

codecov · 2021-05-14T15:25:25Z

Codecov Report

Merging #325 (559b305) into master (dd229ca) will increase coverage by 0.00%.
The diff coverage is 100.00%.

@@           Coverage Diff            @@
##           master     #325    +/-   ##
========================================
  Coverage   99.77%   99.78%            
========================================
  Files          29       29            
  Lines        3999     4100   +101     
========================================
+ Hits         3990     4091   +101     
  Misses          9        9

Flag	Coverage Δ
consensus	`91.20% <0.00%> (-3.69%)`	⬇️
unittests	`99.78% <100.00%> (+<0.01%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
lib/evmone/baseline.cpp	`99.82% <100.00%> (ø)`
lib/evmone/tracing.cpp	`100.00% <100.00%> (ø)`
lib/evmone/tracing.hpp	`100.00% <100.00%> (ø)`
lib/evmone/vm.cpp	`100.00% <100.00%> (ø)`
test/unittests/tracing_test.cpp	`100.00% <100.00%> (ø)`

axic · 2021-05-14T20:56:49Z

lib/evmone/tracing.cpp

+        m_out << std::dec;  // Set number formatting to dec, JSON does not support other forms.
+
+        m_out << "{";
+        m_out << R"("start":true)";


Is this the EIP-3155 compatible format?

This is now change, but we additional "start call" log line.

axic · 2021-05-14T20:58:32Z

lib/evmone/vm.cpp

@@ -46,6 +46,11 @@ evmc_set_option_result set_option(evmc_vm* c_vm, char const* c_name, char const*
        }
        return EVMC_SET_OPTION_INVALID_VALUE;
    }
+    else if (name == "trace")


Again, this is missing coverage.

Will be done in the end.

lib/evmone/tracing.cpp

chfast · 2021-05-22T09:26:25Z

Funny. I output stack items from top to bottom, but apparently the traceview tool expects reversed order. The EIP-3155 does not specify the order.

gumb0 · 2021-05-25T16:35:41Z

lib/evmone/tracing.cpp

+    void on_execution_start(
+        evmc_revision rev, const evmc_message& msg, bytes_view code) noexcept override
+    {
+        m_contexts.emplace(code.data(), msg.gas, evmc_get_instruction_names_table(rev));


Couldn't we assume that all nested executions are on the same revision, and then save rev or opcode_names once for entire tracer in case m_contexts is empty, instead of putting it into each context?

Yes, we can assume this because this will not cause crashes if wrong.

I tried this and this requires some special conditions. E.g. we save it when depth=0? Then unit tests starting on other depth stops working. So maybe set it when not set? But when to null it then? At exit when depth=0?

I suggested to look at m_contexts.empty()

Yes, this works nicely, thanks.
However, I think it is better to do it separately not to modify the HistrogramTracer now.

gumb0 · 2021-05-25T16:48:21Z

lib/evmone/tracing.cpp

+
+        m_out << "{";
+        m_out << R"("kind":")"
+              << ((msg.kind == EVMC_CREATE || msg.kind == EVMC_CREATE2) ? "create" : "call") << '"';


If it's not standard, why not print all possible kinds?

This is known not being properly propagated. The EVM does not care. Only for Ewasm it was important to distinguish create from call. In first version I implemented full to_string(evmc_call_kind). Do you think this was better? We can also drop this.

I think to_string(evmc_call_kind) is better than create+call, but if it's not needed by anyone, then better to drop it.

lib/evmone/tracing.cpp

holiman · 2021-05-26T06:58:57Z

I output stack items from top to bottom, but apparently the traceview tool expects reversed order. The EIP-3155 does not specify the order.

@MariusVanDerWijden it should. So if the ops are 600160026003, the stack after the third op should be [0x01, 0x02, 0x03].

chfast · 2021-05-26T11:20:17Z

I output stack items from top to bottom, but apparently the traceview tool expects reversed order. The EIP-3155 does not specify the order.

@MariusVanDerWijden it should. So if the ops are 600160026003, the stack after the third op should be [0x01, 0x02, 0x03].

Yes, I have figured it out based on the traceview behavior. It was more natural to do it the other way, but I will just change it to what is expected.

lib/evmone/tracing.cpp

gumb0 · 2021-05-27T14:16:28Z

test/unittests/tracing_test.cpp

@@ -27,10 +27,13 @@ class tracing : public Test
        vm{*static_cast<evmone::VM*>(m_baseline_vm.get_raw_pointer())}
    {}

-    std::string trace(bytes_view code, int32_t depth = 0)
+    std::string trace(
+        bytes_view code, int32_t depth = 0, evmc_call_kind kind = EVMC_CALL, uint32_t flags = 0)


I guess this helper doesn't really need kind parameter now.

chfast requested review from axic, gumb0 and jwasinger May 14, 2021 18:38

axic reviewed May 14, 2021

View reviewed changes

lib/evmone/tracing.cpp Outdated Show resolved Hide resolved

chfast force-pushed the histogram_tracer branch 2 times, most recently from dd907fe to 174cc7e Compare May 21, 2021 06:59

Base automatically changed from histogram_tracer to master May 21, 2021 11:15

chfast force-pushed the instruction_trace branch 2 times, most recently from 053b68c to 07e739c Compare May 21, 2021 17:17

chfast changed the title ~~Instruction tracing~~ Instruction tracing with EIP-3155 JSONL output May 21, 2021

chfast marked this pull request as ready for review May 21, 2021 19:10

chfast requested a review from holiman May 21, 2021 19:10

gumb0 reviewed May 25, 2021

View reviewed changes

lib/evmone/tracing.cpp Show resolved Hide resolved

gumb0 reviewed May 26, 2021

View reviewed changes

lib/evmone/tracing.cpp Show resolved Hide resolved

chfast force-pushed the instruction_trace branch from cce43e5 to 649dea6 Compare May 26, 2021 20:01

gumb0 reviewed May 27, 2021

View reviewed changes

gumb0 approved these changes May 27, 2021

View reviewed changes

chfast force-pushed the instruction_trace branch 3 times, most recently from 16de9b9 to 0e5cbc3 Compare May 28, 2021 14:33

chfast added 2 commits May 31, 2021 09:18

Add execution state to Tracer::on_instruction_start()

c7d1df0

Add instruction tracing and "trace" option

ba58a29

test: Add --trace integration tests

559b305

chfast force-pushed the instruction_trace branch from 0e5cbc3 to 559b305 Compare May 31, 2021 07:18

chfast merged commit 09dc7b3 into master May 31, 2021

chfast deleted the instruction_trace branch May 31, 2021 07:44

This was referenced Jun 1, 2021

Logging binary. #99

Closed

Basic opcode tracing #285

Closed

perama-v mentioned this pull request Jul 20, 2023

fix(revm): EIP-3155 tracer tx output without debug artefact bluealloy/revm#552

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Instruction tracing with EIP-3155 JSONL output #325

Instruction tracing with EIP-3155 JSONL output #325

chfast commented May 14, 2021 •

edited

Loading

codecov bot commented May 14, 2021 •

edited

Loading

axic May 14, 2021

chfast May 21, 2021

axic May 14, 2021

chfast May 21, 2021

chfast commented May 22, 2021

gumb0 May 25, 2021

chfast May 25, 2021

chfast May 26, 2021

gumb0 May 27, 2021

chfast May 27, 2021

gumb0 May 25, 2021

chfast May 25, 2021

gumb0 May 26, 2021

holiman commented May 26, 2021

chfast commented May 26, 2021

gumb0 May 27, 2021

Instruction tracing with EIP-3155 JSONL output #325

Instruction tracing with EIP-3155 JSONL output #325

Conversation

chfast commented May 14, 2021 • edited Loading

codecov bot commented May 14, 2021 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

chfast commented May 22, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

holiman commented May 26, 2021

chfast commented May 26, 2021

Choose a reason for hiding this comment

chfast commented May 14, 2021 •

edited

Loading

codecov bot commented May 14, 2021 •

edited

Loading