Ganache produces shifted or even negative gas costs in debug_traceTransaction

[LogvinovLeon]

Expected Behavior

I expect the trace to contain all the gas used by the transaction assigned to opcodes.

Current Behavior

In reality, when I sum all the costs found in a trace I get much less than the gas found on a transaction receipt.

(The image is actually from geth and is here just for visual purposes)

Possible Solution

Investigate and either fix or explain why is it like that.

Steps to Reproduce (for bugs)

1. Create truffle project from a metacoin box.
2. Run JS test that calls sendCoin
3. Look at ganache logs to see the gas usage.
4. Request the transaction trace and sum up gas costs of opcodes.

You don't need that exact box. Just any smart contract transaction. This is probably the simplest one.
You could probably also use remix.

Context

I'm building a profiler based on traces and I can only assign half of the gas to opcodes. I'd like to know where is the other half.

BTW, Geth has the same problem, so there is probably some fundamental misunderstanding on my side about how gas/traces work.

Your Environment

• Version used: Latest and latest beta.
• Environment name and version (e.g. PHP 5.4 on nginx 1.9.1):
• Server type and version:
• Operating System and version: Mac latest
• Link to your project: https://0x.org

[LogvinovLeon]

@benjamincburns @cgewecke

[davidmurdoch]

At first glance this looks like you may not be accounting for gas refunds. Check the transaction receipt for refunds and let me know if that makes up the difference.

[LogvinovLeon]

@davidmurdoch

I don't have the gas refund field on a transaction receipt.

{
  "tx": "0xb96de1919cc8268432339972c840a6a4852ca46d80d26bb658b14a54481b2d2b",
  "receipt": {
    "transactionHash": "0xb96de1919cc8268432339972c840a6a4852ca46d80d26bb658b14a54481b2d2b",
    "transactionIndex": 0,
    "blockHash": "0x811b451ae66ef866ab750d07e3bec92b1d802b144c0fbad5b4525dd31b4e3e8b",
    "blockNumber": 8,
    "from": "0x165e8d458e567b0568d1600646a804ad856e67b9",
    "to": "0x64fabd680c1f2f4bc0a12e5f51ee1f98eeae0baa",
    "gasUsed": 39437,
    "cumulativeGasUsed": *39437*,
    "contractAddress": null,
    "logs": [],
    "status": true,
    "logsBloom": "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
    "v": "0x1b",
    "r": "0xebe9c6dfab9b6ef321ac62600f01055f807f7f889aa3c56e8297d08573fc4e80",
    "s": "0x303804a3d55110afdb13ca4de12b50a45325ceb9d0812256a43cd9c527253b2a",
    "rawLogs": []
  },
  "logs": []
}

The whole gas that's in the trace is: 26735. Trace file.
I know what's happening inside of that transaction and it does free up one storage slot.
When I'm running it against the Geth node I can find 28837 gas in the trace. Which is bigger but still not enough.

SSTORE refunds 15.000 gas so I would expect the difference to be round.

If you substract 26735 from 39437 you get 12702 (missing gas).
For geth it's 10600 which makes slightly more sense because it's more round, but still makes no sense because it's less that the refund amount.

[LogvinovLeon]

I've digged deeped into ganache trace and it seems like it's shifted.

[
    {
      "gasCost": 24216,
      "op": "PUSH1",
    },
    {
      "gasCost": 3,
      "op": "PUSH1",
    },
    {
      "gasCost": 3,
      "op": "MSTORE",
    },
    {
      "gasCost": 12,
      "op": "PUSH1",
    },
    {
      "gasCost": 3,
      "op": "CALLDATASIZE",
    },
    {
      "gasCost": 2,
      "op": "LT",
    },

When in reality if I check here or in yellowpaper here are the costs:
PUSH1 -> 3
MSTORE -> 3 * length
CALLDATASIZE -> 2 *

[davidmurdoch]

Thanks for this additional info, @LogvinovLeon! It's not immediately clear what's going wrong in the accounting in trace transaction.

I suspect that because the EVM step event we listen to is a pre-opcode event (and thus doesn't include the opcode's base cost and memory costs) we are attributing gas costs to the wrong op codes in the trace file, as well as always ommitting the cost of the final op code. In your linked trace file the first PUSH1 opcode cost is 24280, which should only cost 3 gas, per the yellow paper. There are also negative gas costs, which is suspicious, but I suspect this is due to the way the EVM handles EIP-150 gas accounting internally, which we likely don't properly account for in the transaction trace (pinging @nicholasjpaterno, our resident EIP-150 guru).

[LogvinovLeon]

Good catch with the negative gas costs. It's worth noting that this one is immediately after the REVERT.

[LogvinovLeon]

Ok, so part of that issue is my bad. OpCodes gas costs should not sum up to the transaction gas cost.
There is also callDataCost and baseTransactionCost (21k) for regular transactions.
On top of that, we have createCost (32k) and a cost for a byte of deployed bytecode (200) for contract creations.

Negative and shifted gas costs should not happen either way though.

[LogvinovLeon]

I'd like to inform you that shifting gasCosts works. I've just done it on my side and now I'm able to reconstruct the whole gas use by a transaction and profile it. I will not close the issue because it should be fixed on your side.