aleth icon indicating copy to clipboard operation
aleth copied to clipboard

Published 20 hours ago • verified publisher icon ethereum

EVMC tracing for interpreter

Open chfast opened this issue 6 years ago • 16 comments

This is a preview of the EVMC feature https://github.com/ethereum/evmc/pull/32.

Changes

  1. The trace reflects the state of the VM after the execution of an opcode.
  2. This allows to include the error code in the trace.
  3. You can also show the result of the opcode execution (top stack item).
  4. The full VM stack is not reported, only the result of the opcode pushed on the stack (if any). This limits the amount of data transferred, but tracking SWAP and DUP instructions requires some work on the Client side.
  5. Only the fragment of the memory modified by the opcode is reported to the Client. It is easy to incrementally patch the Client's memory view if needed.
  6. The opcode is not reported. The Client knows what code is executed and can get the opcode using the code_offset. It might be convenient to revert this decision and send the opcode to the Client.
  7. The tracing data collection is separated from formatting.
  8. I believe you can construct a formatter which will replicate the behavior of legacy traces.

Examples

testeth -t GeneralStateTests/stCallCodes -- --verbosity 2 --singlenet Byzantium --singletest callcallcallcode_001_SuicideMiddle --vmtrace --vm interpreter

>>>> CALL gas: 2979000
0000  PUSH1 (40)
0002  PUSH1 (0)
0004  PUSH1 (40)
0006  PUSH1 (0)
0008  PUSH1 (0)
000a  PUSH20 (1000000000000000000000000000000000000001)
001f  PUSH3 (249F0)
0023  CALL (40)
>>>>  CALL gas: 150000
0000   PUSH1 (40)
0002   PUSH1 (0)
0004   PUSH1 (40)
0006   PUSH1 (0)
0008   PUSH1 (0)
000a   PUSH20 (1000000000000000000000000000000000000002)
001f   PUSH3 (186A0)
0023   CALL (40)
>>>>   CALL gas: 100000
0000    PUSH20 (1000000000000000000000000000000000000000)
0015    SELFDESTRUCT
<<<<
0024   PUSH1 (1)
0026   SSTORE
<<<<
0024  PUSH1 (0)
0026  SSTORE
<<<<

test/testeth -t 'GeneralStateTests/stCreateTest' -- --verbosity 2 --singlenet Byzantium --singletest CREATE_EmptyContractWithStorageAndCallIt_0wei --vmtrace --vm interpreter

>>>> CALL gas: 579000
0000  GAS (8D5B6)
0001  PUSH1 (0)
0003  SSTORE
0004  PUSH32 (600C6000556000600060006000600073C94F5374FCE5EDBC8E2A8697C1533167)
0025  PUSH1 (0)
0027  MSTORE
0028  PUSH32 (7E6EBF0B61EA60F1000000000000000000000000000000000000000000000000)
0049  PUSH1 (20)
004b  MSTORE
004c  PUSH1 (40)
004e  PUSH1 (0)
0050  PUSH1 (0)
0052  CREATE (40)
>>>>  CREATE gas: 518729
0000   PUSH1 (C)
0002   PUSH1 (0)
0004   SSTORE
0005   PUSH1 (0)
0007   PUSH1 (0)
0009   PUSH1 (0)
000b   PUSH1 (0)
000d   PUSH1 (0)
000f   PUSH20 (C94F5374FCE5EDBC8E2A8697C15331677E6EBF0B)
0024   PUSH2 (EA60)
0027   CALL (0)
>>>>   CALL gas: 60000
0000    PUSH1 (C)
0002    PUSH1 (1)
0004    SSTORE
<<<<
0028   STOP
<<<<
0053  PUSH1 (1)
0055  SSTORE
0056  GAS (71D30)
0057  PUSH1 (2)
0059  SSTORE
005a  PUSH1 (0)
005c  PUSH1 (0)
005e  PUSH1 (0)
0060  PUSH1 (0)
0062  PUSH1 (0)
0064  PUSH1 (1)
0066  SLOAD (F1ECF98489FA9ED60A664FC4998DB699CFA39D40)
0067  PUSH2 (EA60)
006a  CALL (0)
006b  PUSH1 (3)
006d  SSTORE
006e  GAS (67D4F)
006f  PUSH1 (64)
0071  SSTORE
<<<<

As you may see, there are at least 2 nice features here:

  1. Internal calls are properly attached to call instructions.
  2. You can see the outcome of an instruction, e.g. ADD (3) means that the result of the addition was 3.

The call instructions are not handled correctly yet. Now they are reported just before the internal call, but I want them to be reported after because this is more consistent and allows showing the returned values (CALL (1), CALL (0), CREATE (<created address>)).

chfast avatar Jun 05 '18 16:06 chfast

cc @cdetrio

chfast avatar Jun 05 '18 16:06 chfast

@gumb0 The cpp-ethereum part is a prototype to check if the EVMC API is ok.

chfast avatar Jun 07 '18 13:06 chfast

Needs to be rebased and adapted to the latest version of https://github.com/ethereum/evmc/pull/32.

axic avatar Jul 25 '18 16:07 axic

@gumb0 Do you maybe have some spare time to take it over?

chfast avatar Jul 26 '18 08:07 chfast

Codecov Report

Merging #5065 into master will decrease coverage by 0.08%. The diff coverage is 73.82%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #5065      +/-   ##
==========================================
- Coverage   60.81%   60.73%   -0.09%     
==========================================
  Files         341      341              
  Lines       28127    28307     +180     
  Branches     3247     3260      +13     
==========================================
+ Hits        17106    17192      +86     
- Misses       9891     9975      +84     
- Partials     1130     1140      +10

codecov-io avatar Aug 02 '18 10:08 codecov-io

I moved trace() call to a common place, but didn't deal with exceptions yet.

gumb0 avatar Aug 07 '18 13:08 gumb0

@gumb0 Can you make the example how the trace looks like now? Maybe reuse the example from the description.

Do you want me to take it over and make the exception changes?

chfast avatar Aug 08 '18 10:08 chfast

I'm getting now assertion failure at the STOP opcode (startPC out of bounds of evmc->m_code). So the test from the description looks like

Running tests using path: "C:\dev\cpp-ethereum\test\jsontests"
Running 1 test case...
Test Case "vmIOandFlowOperations":
100%
TEST mstore0:
2018-08-08 12:24:08 main vmtrace EVMC message START 0 @cd1722f3… -> @0f572e52… gas: 100000

2018-08-08 12:24:08 main vmtrace EVMC  0 0 PUSH32 0 99997 1 +[115792089237316195423570985008687907853269984665640564039457584007913129639935] 0
2018-08-08 12:24:08 main vmtrace EVMC  1 33 PUSH1 0 99994 2 +[1] 0
2018-08-08 12:24:08 main vmtrace EVMC  2 35 MSTORE 0 99985 0 64
2018-08-08 12:24:08 main vmtrace EVMC  3 36 PUSH1 0 99982 1 +[1] 64
2018-08-08 12:24:08 main vmtrace EVMC  4 38 MLOAD 0 99979 1 +[115792089237316195423570985008687907853269984665640564039457584007913129639935] 64
2018-08-08 12:24:08 main vmtrace EVMC  5 39 PUSH1 0 99976 2 +[1] 64
2018-08-08 12:24:08 main vmtrace EVMC  6 41 SSTORE 0 79976 0 64
Assertion failed: _i < m_count, file c:\dev\cpp-ethereum\libdevcore\vector_ref.h, line 96

Not sure what to do with it yet, so yes, you can take it over.

gumb0 avatar Aug 08 '18 10:08 gumb0

I'm guessing it's virtual STOP that is not physically in the code. So the tracer try to read out of code's bounds. This probably should be handled in the tracer.

uint8_t opcode = _codeOffset < evmc->m_code.size() ? evmc->m_code[_codeOffset] : 0;

chfast avatar Aug 08 '18 13:08 chfast

The test that executes all valid opcodes, might be useful for testing this:

testeth -t GeneralStateTests/stTransactionTest -- --vmtrace --singletest Opcodes_TransactionInit --vm interpreter

But the output is huge...

gumb0 avatar Aug 09 '18 14:08 gumb0

@gumb0 @chfast What is the status of this now?

axic avatar Aug 20 '18 14:08 axic

Please rebase because there were changes regarding EVMC, not sure why not conflicts were detected.

axic avatar Aug 28 '18 17:08 axic

Still needs to be rebased 😉

axic avatar Sep 07 '18 16:09 axic

Updated, please check the description. cc @holiman @karalabe.

chfast avatar Nov 20 '18 15:11 chfast

Here's the summary of what is affected in aleth by changes in tracing:

  • VM trace output in logs at TRACE verbosity for aleth and testeth
  • --jsontrace option of testeth
  • Trace output and opcode stats counting in aleth-vm tool
  • admin_eth_vmTrace and debug_trace* RPC methods
  • some VM unit tests use trace callback to check the opcode price

gumb0 avatar Jun 17 '19 09:06 gumb0

The tracing API in EVMC has some flaws and will have to redesigned. But the amount of data transferred from the VM is good.

chfast avatar Jun 17 '19 09:06 chfast