compiling tests via-ir causes issues with warp & block.timestamp stored in memory

[wminshew]

Component

Forge

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

• Foundry
• Foundryup

What version of Foundry are you on?

forge 0.2.0 (276a122 2022-04-20T18:04:32.540251+00:00)

What command(s) is the bug in?

forge test

Operating System

macOS (amd)

Describe the bug

Can explore with this repo on commit b2dd8cfafa79d02394826e8f01138e849d78f784

1. forge install
2. make test
3. see tests passing
4. update foundry.toml to build via-ir = true
5. forge test -vvv --match-test createERC20
6. see test failing

the error appears to be with vestingStart, which is block.timestamp saved to memory at the beginning & later tested against. It appears to jump forward with the warp. My guess (not confirmed browsing opcode output) is that via-ir is trying to save me gas by skipping the m{store,load} for the timestamp (bc in regular contracts block timestamps don't change w/i execution of a fn) & just re-loading block.timestamp freshly on later reference

(to debug this I had to use emit log_uint -- couldn't seem to get console2 or console to output to trace.. but that's a separate topic)

fortunately this is easy enough to fix in my own case since vestingStart is only ever 0 how/where I was currently using it (and via-ir doesn't appear to save any gas for these contracts)

wanted to flag for others in the meantime

[onbjerg]

I'm not surethis is a Foundry issue. When you call vm.warp, then the block's timestamp is set to what you pass to warp for the remainder of the test until vm.warp is called with a new value. For that reason, if Solidity optimized things by calling block.timestamp again, you would see whatever you passed to warp.

It might be that Solidity instead optimizes by putting block.timestamp on the stack before it is actually called and then does a pop or other stack operation later. This is sound for normal Solidity since block.timestamp is immutable under normal circumstances, but obviously breaks things for us.

For example this is what I imagine is happening (pseudo-code):

// test code (without IR this passes)
vm.warp(100);
assertEq(block.timestamp, 100);
vm.warp(200);
assertEq(block.timestamp, 200);

// solidity IR optimization (crudely)
uint256 timestamp = block.timestamp; // for us, this is 0 here
vm.warp(100); // sets block.timestamp, so accessing it directly would result in 100
assertEq(timestamp, 100); // but its already on the stack, and solc reuses that, so this assertion fails
vm.warp(200);
assertEq(timestamp, 200);

The only real fix we could do is track the location of stack items that have been produced by block.timestamp (and other immutables too like block.number, further complicating things), however, this would break tests like:

uint256 timestampBefore = block.timestamp;
vm.warp(block.timestamp + x);
assertEq(timestamp - x, timestampBefore);

I'm not really sure what we should do here. Pinging @hrkrshnn and @gakonst

[brockelmore]

ye so likely we will need to provide a helper function here that blackboxes it from the compiler. @hrkrshnn what do you think about going more general and native with a blackbox inside solidity?

[onbjerg]

Hmm, looking at this more: the TIMESTAMP opcode costs 2 gas, so this is a weird optimization. DUP1 costs 3 gas and POP costs 2 gas, so really, there isn't any gas saving here?

Edit: Also, another fix would be to bump priority on per-contract optimizations, e.g. disabling the optimizer for test contracts always but enabling it for the user contracts, if possible. I don't think there's a specific reason you'd want to run tests with the optimizer on for test contracts other than measuring gas of your actual contracts

Edit: Ok last edit I swear, I just remembered that the optimizer might be relevant for test contracts if you hit the "stack too deep" or w/e error 😞

[cgewecke]

the optimizer might be relevant for test contracts if you hit the "stack too deep" error

@onbjerg Might be possible to config the compiler so that optimization is mostly off but "stack too deep" doesn't happen.

• solidity issue 10354 comment
• solidity-coverage issue 675 comment

[onbjerg]

Interesting as a workaround, but I'm not sure we can do that in Forge since it would require some knowledge of the expected test outcome, and for us to bruteforce the optimizer settings until it might work? 🤔

[hrkrshnn]

Hmm, looking at this more: the TIMESTAMP opcode costs 2 gas, so this is a weird optimization. DUP1 costs 3 gas and POP costs 2 gas, so really, there isn't any gas saving here?

Good point. I think it's easiest to fix this: made ethereum/solidity#12963 to track. @onbjerg

[gakonst]

Thanks for flagging @wminshew, closing given:

1. we've tracked it down to Solidity and have the relevant issues tracked.
2. you have a workaround for this in your case

[hrkrshnn]

It might be that Solidity instead optimizes by putting block.timestamp on the stack before it is actually called and then does a pop or other stack operation later. This is sound for normal Solidity since block.timestamp is immutable under normal circumstances, but obviously breaks things for us.

@onbjerg Just checked this. This doesn't seem to be true:

interface VM {
    function warp(uint) external;
}
contract C {
    VM vm = VM(address(0));
    function f() external {
        // test code (without IR this passes)
        vm.warp(100);
        assert(block.timestamp == 100);
        vm.warp(200);
        assert(block.timestamp == 200);
    }
}

Looked at both the --ir-optimized --optimize and --asm --via-ir --optimize for the above code. There are two references to timestamp. So it's not getting dup-ed.

[onbjerg]

Right, I think I had it confused; what is actually happening is that you replace all occurrences of a variable that just contains block.timestamp with block.timestamp (which is a fair optimization but muddies things for us). See this example:

interface VM {
    function warp(uint) external;
}
contract C {
    VM vm = VM(address(0x7109709ECfa91a80626fF3989D68f67F5b1DD12D));

    function testF() external {
        // test code (without IR this passes)
        uint256 start = block.timestamp;
        vm.warp(100);
        assert(start == 0);
    }
}

Not sure if we should re-open @gakonst, I don't know if there is anything we can do on our side. Any way to get around this @hrkrshnn?

[wminshew]

added a minimal repro in ethereum/solidity#12963 (comment)

[kyzia551]

Hi guys, I'm facing the same on 0.8.27

[xenide]

I'm facing this in 0.8.28.

function testGetPastAccumulator_ExactMatch_OldestAccumulator(
        uint32 aStartTime,
        uint256 aBlockTime,
        uint256 aObservationsToWrite
    ) external randomizeStartTime(aStartTime) {
        // assume
        uint256 lBlockTime = bound(aBlockTime, 1, 30);
        uint16 lObservationsToWrite = uint16(bound(aObservationsToWrite, 3, Buffer.SIZE * 3)); // go around it 3 times maximum

        // arrange
        uint256 lStartTime = block.timestamp;
        console2.log("after assignment", lStartTime);
        _fillBuffer(lBlockTime, lObservationsToWrite);
        (,,, uint16 lIndex) = _pair.getReserves();

        // act
        vm.startPrank(address(_queryProcessor));
        console2.log("start", lStartTime);
        console2.log(_pair.observation(lIndex.next()).timestamp);
        uint256 lAgo = lObservationsToWrite > Buffer.SIZE
            ? block.timestamp - _pair.observation(lIndex.next()).timestamp
            : block.timestamp - (lStartTime + lBlockTime);
        int256 lAcc = _queryProcessor.getPastAccumulator(_pair, PriceType.RAW_PRICE, lIndex, lAgo);

        // assert
        Observation memory lObs = _pair.observation(lObservationsToWrite > Buffer.SIZE ? lIndex.next() : 0);
        assertEq(lAcc, lObs.logAccRawPrice);
        vm.stopPrank();
    }

In this case lStartTime gets arbitrarily modified and therefore the two console logs output different values even though there is no modification to lStartTime

The workaround I managed to find was to do:

uint256 lStartTime = (block.timestamp << 1) >> 1;
console2.log(lStartTime);
// use lStartTime later
... = lStartTime + ... 

Since timestamp is way smaller than 256 bits i guess this is safe enough in my case.

[penandlim]

I am also getting the similar issue in 0.8.28 where I store block.timestamp as uint256 in memory in test, and then it gets arbitrarily modified without modification.

The workaround suggested by @xenide worked for me
#1373 (comment)

uint256 startTimestamp = (block.timestamp << 1) >> 1;

[zerosnacks]

These cheatcodes could potentially be useful:

    /// Gets the current `block.number`.
    /// You should use this instead of `block.number` if you use `vm.roll`, as `block.number` is assumed to be constant across a transaction,
    /// and as a result will get optimized out by the compiler.
    /// See https://github.com/foundry-rs/foundry/issues/6180
    function getBlockNumber() external view returns (uint256 height);

    /// Gets the current `block.timestamp`.
    /// You should use this instead of `block.timestamp` if you use `vm.warp`, as `block.timestamp` is assumed to be constant across a transaction,
    /// and as a result will get optimized out by the compiler.
    /// See https://github.com/foundry-rs/foundry/issues/6180
    function getBlockTimestamp() external view returns (uint256 timestamp);

https://github.com/foundry-rs/forge-std/blob/master/src/Vm.sol#L577-L587