Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unusual high memory usage #8283

Closed
2 tasks done
Inphi opened this issue Jun 28, 2024 · 3 comments · Fixed by #8300
Closed
2 tasks done

Unusual high memory usage #8283

Inphi opened this issue Jun 28, 2024 · 3 comments · Fixed by #8300
Labels
C-forge Command: forge Cmd-forge-test Command: forge test T-bug Type: bug

Comments

@Inphi
Copy link
Contributor

Inphi commented Jun 28, 2024

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 (c4a984f 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 Inphi added the T-bug Type: bug label Jun 28, 2024
@Inphi
Copy link
Contributor Author

Inphi commented Jun 28, 2024 •
edited
Loading

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)
...

@zerosnacks zerosnacks added Cmd-forge-test Command: forge test C-forge Command: forge labels Jun 28, 2024
@DaniPopes
Copy link
Member

DaniPopes commented Jun 28, 2024 •
edited
Loading

cc @klkvr #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:

foundry/crates/evm/evm/src/inspectors/debugger.rs

Lines 72 to 78 in c8db1e4

// Reuse the memory from the previous step if the previous opcode did not modify it.
let memory = self.arena.arena[self.head]
.steps
.last()
.filter(|step| !step.opcode_modifies_memory())
.map(|step| step.memory.clone())
.unwrap_or_else(|| interp.shared_memory.context_memory().to_vec().into());

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 paradigmxyz/revm-inspectors#84 would be doing

we need to get that PR in

@Inphi Inphi mentioned this issue Jun 28, 2024
Closed
2 tasks
@DaniPopes DaniPopes mentioned this issue Jun 29, 2024
Merged
@DaniPopes
Copy link
Member

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 #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)
...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-forge Command: forge Cmd-forge-test Command: forge test T-bug Type: bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

chore(deps): bump revm-inspectors foundry-rs/foundry
3 participants
@Inphi @DaniPopes @zerosnacks