`gasleft()` returns incorrect value within calback

[zaqk]

Component

Forge

Have you ensured that all of these are up to date?

• [X] Foundry
• [X] Foundryup

What version of Foundry are you on?

forge 0.2.0 (dffdfde 2023-08-14T00:22:15.788827000Z)

What command(s) is the bug in?

forge test

Operating System

macOS (Apple Silicon)

Describe the bug

It seems that gasleft() is returning an extremely high gas usage amount within a function callback. I ran into this issue when trying to measure gas usage in a UniswapV3Pool callback.

Heres an example that you can test with forge test:

contract Callback {
    function execute(uint256 startGas) external returns (uint256, uint256) {
        uint256 g1 = GasTester(msg.sender).callbackResponse(startGas); // inaccurate value
        uint256 g2 = startGas - gasleft(); // inaccurate value
        return (g1, g2);
    }
}

contract GasTester {

    Callback callback;

    constructor() {
        callback = new Callback();
    }

    function run() public returns (uint256, uint256, uint256, uint256, uint256) {
        uint256 startGas = gasleft();  // accurate value

        // use some gas
        require(msg.sender == msg.sender && msg.sender != address(0));

        uint256 g0 = startGas - gasleft(); // accurate value

        (uint256 g1, uint256 g2) = callback.execute(startGas); // inaccurate values

        uint256 g3 = startGas - gasleft(); // accurate value

        return (startGas, g0, g1, g2, g3);
    }

    function callbackResponse(uint256 startGas) external returns (uint256) {
        return startGas - gasleft(); // inaccurate value
    }

}

the test case:

    function test_gas() public {
        GasTester gasTester = new GasTester();
        (uint256 startGas, uint256 g0, uint256 g1, uint256 g2, uint256 g3) = gasTester.run();
        console2.log("startGas", startGas);
        console2.log("g0", g0);
        console2.log("g1", g1);
        console2.log("g2", g2);
        console2.log("g3", g3);
    }

and finally the log output:

[PASS] test_gas() (gas: 291458)
Logs:
  startGas 9079256848778620484
  g0 26
  g1 281510161082736559
  g2 141863388262167292
  g3 1732

Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 2.64ms
Ran 1 test suites: 1 tests passed, 0 failed, 0 skipped (1 total tests)

It seems that any gas usage calculated using gasleft() is accurate but if execution context changes gasleft() becomes extremely large. g0 ad g3 are accurate while g1 and g2 which are calculated in a callback or a separate contract are inaccurate.

I also ran into this previously closed issue which may be related (not 100% sure): https://github.com/foundry-rs/foundry/issues/3863

[ulasacikel]

I am facing the exact same issue. In externall calls gasleft() returns inconsistent gas amounts.

[Cycxyz]

+1

[trojanMcAfee]

+1

My case, on top, reflects the extremely large gas amount in the total gas used by the test:

I'm using try/catch, so it's a call made to an external contract:

try IDiamond(myAddr_).useUnderlying(asset(), owner_, amts) returns(uint amountOut) {
      //some code

    return shares;
} catch Error(string memory reason) {
      revert(reason);
}

[trojanMcAfee]

Opened #7451

[zerosnacks]

Able to reproduce though with different values:

With forge test -vvvv

Ran 1 test for test/Counter.t.sol:CounterTest
[PASS] test_gas() (gas: 18221)
Logs:
  startGas 1056938680
  g0 26
  g1 32776688
  g2 16520467
  g3 6256

Traces:
  [18221] CounterTest::test_gas()
    ├─ [6639] GasTester::run()
    │   ├─ [1114] Callback::execute(1056938680 [1.056e9])
    │   │   ├─ [368] GasTester::callbackResponse(1056938680 [1.056e9])
    │   │   │   └─ ← [Return] 32776688 [3.277e7]
    │   │   └─ ← [Return] 32776688 [3.277e7], 16520467 [1.652e7]
    │   └─ ← [Return] 1056938680 [1.056e9], 26, 32776688 [3.277e7], 16520467 [1.652e7], 6256
    ├─ [0] console::log("startGas", 1056938680 [1.056e9]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g0", 26) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g1", 32776688 [3.277e7]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g2", 16520467 [1.652e7]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g3", 6256) [staticcall]
    │   └─ ← [Stop] 
    └─ ← [Stop] 

Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.11ms (156.25µs CPU time)

Ran 1 test suite in 201.05ms (1.11ms CPU time): 1 tests passed, 0 failed, 0 skipped (1 total tests)

With forge test -vvvv --isolate

Ran 1 test for test/Counter.t.sol:CounterTest
[PASS] test_gas() (gas: 39285)
Logs:
  startGas 29978803
  g0 26
  g1 934914
  g2 474219
  g3 6256

Traces:
  [39285] CounterTest::test_gas()
    ├─ [27703] GasTester::run()
    │   ├─ [1114] Callback::execute(29978803 [2.997e7])
    │   │   ├─ [368] GasTester::callbackResponse(29978803 [2.997e7])
    │   │   │   └─ ← [Return] 934914 [9.349e5]
    │   │   └─ ← [Return] 934914 [9.349e5], 474219 [4.742e5]
    │   └─ ← [Return] 29978803 [2.997e7], 26, 934914 [9.349e5], 474219 [4.742e5], 6256
    ├─ [0] console::log("startGas", 29978803 [2.997e7]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g0", 26) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g1", 934914 [9.349e5]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g2", 474219 [4.742e5]) [staticcall]
    │   └─ ← [Stop] 
    ├─ [0] console::log("g3", 6256) [staticcall]
    │   └─ ← [Stop] 
    └─ ← [Stop] 

Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.29s (124.96ms CPU time)

Ran 1 test suite in 1.47s (1.29s CPU time): 1 tests passed, 0 failed, 0 skipped (1 total tests)