search

foundry-rs / foundry

Foundry is a blazing fast, portable and modular toolkit for Ethereum application development written in Rust.
https://getfoundry.sh
Apache License 2.0
7.86k stars 1.56k forks source link

Unusual high memory usage #8283

Closed Inphi closed 1 day ago

Inphi commented 3 days ago

Component

Forge

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

What version of Foundry are you on?

forge 0.2.0 (c4a984fbf 2024-06-28T01:21:07.093727947Z)

What command(s) is the bug in?

forge test

Operating System

Linux

Describe the bug

Summary

Running forge test --debug uses a lot of memory for certain tests. This issue does not occur when running forge test without debug.

Reproducer

// SPDX-License-Identifier: UNLICENSED
pragma solidity ^0.8.13;

import {Test, console} from "forge-std/Test.sol";
import {Counter} from "../src/Counter.sol";

contract CounterTest is Test {
    Counter public counter;
    address addr = address(uint160(uint256(keccak256("ekans"))));

    function setUp() public {
        bytes memory buffer = new bytes(2000000);
        vm.etch(address(addr), buffer);

        counter = new Counter();
        counter.setNumber(0);
    }

    function test_Increment() public {
        counter.increment();
        assertEq(counter.number(), 1);
    }

    function testFuzz_SetNumber(uint256 x) public {
        counter.setNumber(x);
        assertEq(counter.number(), x);
    }
}

Running forge test --debug test_Increment --mc CounterTest consumes over 32 GB on my machine before the kernel kills it. I think the critical part is this line here:

vm.etch(address(addr), buffer)

Etching a really large runtime code seems to trigger the issue. I use an empty buffer for illustrative purposes, but the run still consumes alot of memory even when a valid runtime bytecode is used. Reducing the size of the runtime code seems to work, with minimal memory usage. I'm sure there's some buffer size threshold where memory usage spikes, but I haven't narrowed it down.

Inphi commented 3 days ago

I profiled forge a bit just to make sure it's not because of solc. I found a steady increase in the size of anonymous memoryrequested via mmap (so most likely regular mem allocations), which indicates some kind of accidentally quadratic behavior:

[pid 897075] mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c64000000
[pid 897075] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f2d01245000
[pid 897075] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c702ff000
[pid 897075] mmap(NULL, 4190208, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c70100000
[pid 897075] mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c70000000
[pid 897074] mmap(NULL, 2621440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6bd80000
[pid 897074] mmap(NULL, 3145728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6ba80000
[pid 897074] mmap(NULL, 3670016, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6b700000
[pid 897074] mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6b300000
[pid 897074] mmap(NULL, 5242880, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6ae00000
[pid 897074] mmap(NULL, 6291456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6a800000
[pid 897074] mmap(NULL, 7340032, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c6a100000
[pid 897074] mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c69900000
[pid 897074] mmap(NULL, 10485760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c68f00000
[pid 897074] mmap(NULL, 12582912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c68300000
[pid 897074] mmap(NULL, 14680064, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c63200000
[pid 897074] mmap(NULL, 16777216, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c62200000
[pid 897074] mmap(NULL, 20971520, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c60e00000
[pid 897074] mmap(NULL, 25165824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c5f600000
[pid 897074] mmap(NULL, 29360128, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c5da00000
[pid 897074] mmap(NULL, 33554432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c5ba00000
[pid 897074] mmap(NULL, 41943040, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c59200000
[pid 897074] mmap(NULL, 50331648, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c56200000
[pid 897074] mmap(NULL, 58720256, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c52a00000
[pid 897074] mmap(NULL, 67108864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c4ea00000
[pid 897074] mmap(NULL, 83886080, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c49a00000
[pid 897074] mmap(NULL, 100663296, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c43a00000
[pid 897074] mmap(NULL, 117440512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c3ca00000
[pid 897074] mmap(NULL, 134217728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c34a00000
[pid 897074] mmap(NULL, 167772160, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c2aa00000
[pid 897074] mmap(NULL, 201326592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c1ea00000
[pid 897074] mmap(NULL, 234881024, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c10a00000
[pid 897074] mmap(NULL, 268435456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2c00a00000
[pid 897074] mmap(NULL, 335544320, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2beca00000
[pid 897074] mmap(NULL, 402653184, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2bd4a00000
[pid 897074] mmap(NULL, 469762048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2bb8a00000
[pid 897074] mmap(NULL, 10485760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2bb8000000
[pid 897074] mmap(NULL, 536870912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2b98000000
[pid 897074] mmap(NULL, 671088640, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2b70000000
[pid 897074] mmap(NULL, 805306368, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2b40000000
[pid 897074] mmap(NULL, 939524096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2b08000000
[pid 897074] mmap(NULL, 1073741824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2ac8000000
[pid 897074] mmap(NULL, 1342177280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2a78000000
[pid 897074] mmap(NULL, 12582912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2a77400000
[pid 897074] mmap(NULL, 1610612736, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2a17400000
[pid 897074] mmap(NULL, 1879048192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f29a7400000
[pid 897074] mmap(NULL, 2147483648, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2927400000
[pid 897074] mmap(NULL, 14680064, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2926600000
[pid 897074] mmap(NULL, 2684354560, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2886600000
[pid 897074] mmap(NULL, 3221225472, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f27c6600000
[pid 897074] mmap(NULL, 16777216, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f27c5600000
[pid 897074] mmap(NULL, 3758096384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f26e5600000
[pid 897074] mmap(NULL, 4294967296, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f25e5600000
[pid 897074] mmap(NULL, 20971520, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f25e4200000
[pid 897074] mmap(NULL, 5368709120, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f24a4200000

Confirmed that this is coming directly from forge via gdb:

$ b mmap
$ condition 1 $rsi > 4073741824
$ c 5
$ bt
#0  __GI___mmap64 (addr=addr@entry=0x0, len=len@entry=6442450944, prot=3, flags=16418, fd=fd@entry=-1, offset=offset@entry=0) at ../sysdeps/unix/sysv/linux/mmap64.c:47
<omitted>
#23 forge::_::__rust_realloc (ptr=0x0, align=1, new_size=4050816, size=<optimized out>) at crates/forge/bin/main.rs:18
...
#34 revm_inspectors::tracing::types::RecordedMemory::resize (self=0x7ffb114e1020, len=<optimized out>)
    at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-inspectors-0.2.0/src/tracing/types.rs:663
#35 0x000055555840f739 in revm_inspectors::tracing::TracingInspector::fill_step_on_step_end<&mut foundry_evm_core::backend::Backend> (self=0x7fff6db75728, interp=0x7fff6d7c8280, context=0x7fff6db72f70)
    at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-inspectors-0.2.0/src/tracing/mod.rs:421
#36 0x0000555558465498 in revm_inspectors::tracing::{impl#1}::step_end<&mut foundry_evm_core::backend::Backend> (self=<optimized out>, interp=<optimized out>, context=<optimized out>)
    at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-inspectors-0.2.0/src/tracing/mod.rs:480
#37 foundry_evm::inspectors::stack::{impl#4}::step_end::{closure#0}<&mut foundry_evm_core::backend::Backend> () at crates/evm/evm/src/inspectors/stack.rs:668
#38 foundry_evm::inspectors::stack::{impl#4}::step_end<&mut foundry_evm_core::backend::Backend> (interpreter=0x7fff6d7c8280, ecx=0x7fff6db72f70, self=<optimized out>)
    at crates/evm/evm/src/inspectors/stack.rs:203
#39 foundry_evm::inspectors::stack::{impl#6}::step_end<&mut foundry_evm_core::backend::Backend> (self=0x7fff6db75200, interpreter=0x7fff6d7c8280, ecx=0x7fff6db72f70)
    at crates/evm/evm/src/inspectors/stack.rs:908
#40 revm::inspector::_::{impl#0}::step_end<&mut foundry_evm_core::backend::Backend, foundry_evm::inspectors::stack::InspectorStack> (self=0x7fff6db73180, interp=0x7fff6d7c8280, context=0x7fff6db72f70)
    at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-10.0.0/src/inspector.rs:31
#41 revm::inspector::handler_register::inspector_instruction<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::Backend> (prev=..., interpreter=0x7fff6d7c8280,
    host=0x7fff6db72f70) at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-10.0.0/src/inspector/handler_register.rs:245
#42 0x00005555584b76aa in alloc::boxed::{impl#50}::call<(&mut revm_interpreter::interpreter::Interpreter, &mut revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>), dyn core::ops::function::Fn<(&mut revm_interpreter::interpreter::Interpreter, &mut revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>), Output=()>, alloc::alloc::Global> (self=0x7fff6db77322, args=...) at /rustc/8f9080db423ca0fb6bef0686ce9a93940cdf1f13/library/alloc/src/boxed.rs:2036
#43 revm_interpreter::interpreter::Interpreter::step<alloc::boxed::Box<dyn core::ops::function::Fn<(&mut revm_interpreter::interpreter::Interpreter, &mut revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>), Output=()>, alloc::alloc::Global>, revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>> (self=<optimized out>, instruction_table=<optimized out>, host=<optimized out>)
    at /home/inphi/.cargo/registry/src/index.crates.io-6f17d22bba15001f/revm-interpreter-6.0.0/src/interpreter.rs:356
#44 revm_interpreter::interpreter::Interpreter::run<alloc::boxed::Box<dyn core::ops::function::Fn<(&mut revm_interpreter::interpreter::Interpreter, &mut revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>), Output=()>, alloc::alloc::Global>, revm::context::Context<&mut foundry_evm::inspectors::stack::InspectorStack, &mut foundry_evm_core::backend::cow::CowBackend>> (self=0x7fff6d7c8280, shared_memory=..., instruction_table=0x7fff6db73300, host=0x7fff6db72f70)
...
DaniPopes commented 3 days ago

cc @klkvr https://github.com/foundry-rs/foundry/pull/8249

this is 99% of the time spent in copying memory, foundry Debugger inspector used to look at previous opcode to determine whether to copy memory: https://github.com/foundry-rs/foundry/blob/c8db1e4b56fe469e353d8f6c697db499988c9483/crates/evm/evm/src/inspectors/debugger.rs#L72-L78

this doesn't happen in revm-inspectors tracer: https://github.com/paradigmxyz/revm-inspectors/blob/bc01e0501a42c6b0e6f28dd824fdda345c223ca4/src/tracing/mod.rs#L374-L378

which is what https://github.com/paradigmxyz/revm-inspectors/pull/84 would be doing

we need to get that PR in

DaniPopes commented 1 day ago

FYI #8300 will fix the excessive memory usage, but your test case will still cost a ton of memory because it will record 62.5k MSTOREs each with its own 2M + idx*32 of memory (2M base because for some reason solidity needs 2 buffers and doesn't know that memory is zerod by default (: ), which I think is the case also before https://github.com/foundry-rs/foundry/pull/8249

MSTORE(0x00000040, 128)
 MLOAD(0x00000040)
MSTORE(0x00000080, 2000000)
MSTORE(0x00000040, 2000160)
 MLOAD(0x00000040)
MSTORE(0x001e8520, 32)
 MLOAD(0x00000080)
MSTORE(0x001e8540, 2000000)
 MLOAD(0x000000a0)
MSTORE(0x001e8560, 0)
 MLOAD(0x000000c0)
MSTORE(0x001e8580, 0)
 MLOAD(0x000000e0)
MSTORE(0x001e85a0, 0)
 MLOAD(0x00000100)
MSTORE(0x001e85c0, 0)
 MLOAD(0x00000120)
MSTORE(0x001e85e0, 0)
 MLOAD(0x00000140)
MSTORE(0x001e8600, 0)
...