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

gnovm/pkg/gnolang: Allocator invokes NewBlock seemingly with the same blocks too many times and consumes more than 127.94GB of RAM just to run TestStdlibs #3487

Open
odeke-em opened this issue Jan 12, 2025 · 1 comment
Open

gnovm/pkg/gnolang: Allocator invokes NewBlock seemingly with the same blocks too many times and consumes more than 127.94GB of RAM just to run TestStdlibs #3487

odeke-em opened this issue Jan 12, 2025 · 1 comment
Labels
🐞 bug Something isn't working non-security

Comments

@odeke-em
Copy link
Contributor

I noticed this while auditing and investigating to try to figure out why so much memory was being consumed by TestStdlibs

Showing nodes accounting for 200.89GB, 94.79% of 211.94GB total
Dropped 546 nodes (cum <= 1.06GB)
Showing top 10 nodes out of 71
      flat  flat%   sum%        cum   cum%
  127.94GB 60.37% 60.37%   127.94GB 60.37%  github.com/gnolang/gno/gnovm/pkg/gnolang.NewBlock
   27.62GB 13.03% 73.40%    27.62GB 13.03%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*ArrayValue).GetPointerAtIndexInt2
   15.15GB  7.15% 80.55%    15.15GB  7.15%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).PushFrameCall
    8.30GB  3.92% 84.46%     8.30GB  3.92%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*FuncValue).Copy (inline)
    7.35GB  3.47% 87.93%    11.71GB  5.53%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*PackageNode).PrepareNewValues
    4.91GB  2.32% 90.25%     9.06GB  4.27%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*TypedValue).GetPointerToFromTV
    3.16GB  1.49% 91.74%    87.72GB 41.39%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpExec
    2.60GB  1.23% 92.96%     2.60GB  1.23%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewDataArray
    2.12GB     1% 93.96%     2.12GB     1%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).PushFrameBasic
    1.74GB  0.82% 94.79%     1.74GB  0.82%  github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewListArray

which has this tree

Showing nodes accounting for 127.94GB, 60.37% of 211.94GB total
Dropped 17 nodes (cum <= 1.06GB)
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context 	 	 
----------------------------------------------------------+-------------
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewBlock
  127.94GB 60.37% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/gnolang.NewBlock
----------------------------------------------------------+-------------
                                           77.33GB 60.44% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpExec
                                           50.61GB 39.55% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpCall
         0     0% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewBlock
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.NewBlock
----------------------------------------------------------+-------------
                                           99.20GB   100% |   github.com/gnolang/gno/gnovm/pkg/test.(*TestOptions).runTestFiles
         0     0% 60.37%    99.20GB 46.80%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Eval
                                           99.20GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Run
----------------------------------------------------------+-------------
                                           99.20GB 77.53% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Eval
                                           28.74GB 22.47% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runDeclaration
         0     0% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Run
                                           77.33GB 60.44% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpExec
                                           50.61GB 39.55% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpCall
----------------------------------------------------------+-------------
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/test.(*TestOptions).runTestFiles
         0     0% 60.37%    28.74GB 13.56%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).RunFiles
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls
----------------------------------------------------------+-------------
                                           50.61GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Run
         0     0% 60.37%    50.61GB 23.88%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpCall
                                           50.61GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewBlock
----------------------------------------------------------+-------------
                                           77.33GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Run
         0     0% 60.37%    77.33GB 36.49%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).doOpExec
                                           77.33GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Allocator).NewBlock
----------------------------------------------------------+-------------
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls.func1
         0     0% 60.37%    28.74GB 13.56%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runDeclaration
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Run
----------------------------------------------------------+-------------
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).RunFiles
         0     0% 60.37%    28.75GB 13.56%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls.func1
----------------------------------------------------------+-------------
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls
         0     0% 60.37%    28.74GB 13.56%                | github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runFileDecls.func1
                                           28.74GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).runDeclaration
----------------------------------------------------------+-------------
                                          127.94GB   100% |   testing.tRunner
         0     0% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/gnolang_test.TestStdlibs.func2.1
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/test.Test
----------------------------------------------------------+-------------
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/test.Test
         0     0% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/test.(*TestOptions).runTestFiles
                                           99.20GB 77.53% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).Eval
                                           28.74GB 22.47% |   github.com/gnolang/gno/gnovm/pkg/gnolang.(*Machine).RunFiles
----------------------------------------------------------+-------------
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang_test.TestStdlibs.func2.1
         0     0% 60.37%   127.94GB 60.37%                | github.com/gnolang/gno/gnovm/pkg/test.Test
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/test.(*TestOptions).runTestFiles
----------------------------------------------------------+-------------
         0     0% 60.37%   127.94GB 60.37%                | testing.tRunner
                                          127.94GB   100% |   github.com/gnolang/gno/gnovm/pkg/gnolang_test.TestStdlibs.func2.1
----------------------------------------------------------+-------------

Fingerprinting to prove the theory about being heavy handed with allocations

I decided to fingerprint the results of NewBlock and alas they were alarming

diff --git a/gnovm/pkg/gnolang/values.go b/gnovm/pkg/gnolang/values.go
index 4c2e2835..fac9a7c0 100644
--- a/gnovm/pkg/gnolang/values.go
+++ b/gnovm/pkg/gnolang/values.go
@@ -1,6 +1,8 @@
 package gnolang
 
 import (
+	"bytes"
+	"crypto/sha256"
 	"encoding/binary"
 	"fmt"
 	"math"
@@ -2354,7 +2356,15 @@ type Block struct {
 }
 
 // NOTE: for allocation, use *Allocator.NewBlock.
-func NewBlock(source BlockNode, parent *Block) *Block {
+func NewBlock(source BlockNode, parent *Block) (b *Block) {
+	defer func() {
+		hash, str := b.fingerprint()
+		dupes[hash] += 1
+		if n := dupes[hash]; n > 15 {
+			fmt.Printf("Dupe detected: %d\n\t%s => %s\n", n, hash, str)
+		}
+	}()
+
 	var values []TypedValue
 	if source != nil {
 		values = make([]TypedValue, source.GetNumNames())
@@ -2366,10 +2376,35 @@ func NewBlock(source BlockNode, parent *Block) *Block {
 	}
 }
 
+var dupes = make(map[string]int)
+
 func (b *Block) String() string {
 	return b.StringIndented("    ")
 }
 
+func (b *Block) fingerprint() (string, string) {
+	buf := new(bytes.Buffer)
+	fmt.Fprintf(buf, "%v%p%s%p", b.ObjectInfo.ID, b, toString(b.Source), b.Parent)
+
+	if b.Source != nil {
+		if _, ok := b.Source.(RefNode); ok {
+			fmt.Fprintf(buf, "(RefNode names not shown)")
+			goto fini
+		}
+
+		for i, n := range b.Source.GetBlockNames() {
+			if len(b.Values) <= i {
+				fmt.Fprintf(buf, "%s: undefined", n)
+			} else {
+				fmt.Fprintf(buf, "%s: %s", n, b.Values[i].String())
+			}
+		}
+	}
+
+fini:
+	return fmt.Sprintf("%x", sha256.Sum256(buf.Bytes())), buf.String()
+}
+
 func (b *Block) StringIndented(indent string) string {
 	source := toString(b.Source)
 	if len(source) > 32 {

Prints

$ go test -run=Stdlibs -count=1
Dupe detected: 16
	9c830546c6d6e2cbbb631d7c947800bd2b7468cefa839085128e842fab8ad592 => 0000000000000000000000000000000000000000:00xc00bd7da40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	752c55b805d29999aaf85b79b79486937b585edf58e9286453fb2b552c36282a => 0000000000000000000000000000000000000000:00xc004662000func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	8c7fa7792cefb8f3c3658c8d08f7ab31bc6c5d61381155216c3f32e0bdceaa2e => 0000000000000000000000000000000000000000:00xc007965860func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 17
	9c830546c6d6e2cbbb631d7c947800bd2b7468cefa839085128e842fab8ad592 => 0000000000000000000000000000000000000000:00xc00bd7da40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	22fd7b382383c365bde65388127e5b575aa10f3f59fa559808fd7eb86261c2c5 => 0000000000000000000000000000000000000000:00xc00bfb6000func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	f058d8b6e079fcd3e4717b25aff4b42a5a5adeb813099658f18337011b01d6fa => 0000000000000000000000000000000000000000:00xc009cf7c20func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 17
	8c7fa7792cefb8f3c3658c8d08f7ab31bc6c5d61381155216c3f32e0bdceaa2e => 0000000000000000000000000000000000000000:00xc007965860func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	dbad054b8689d0423142255e7fdafcff111994391252a17a64ca5e3d1c10dfee => 0000000000000000000000000000000000000000:00xc00626af00func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	bfaff8413b77a59f513a3af51df18db3ca350cd58ffafcdc9f6ed8a7b0261b79 => 0000000000000000000000000000000000000000:00xc00581fa40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	7262093a78f873258ffff0af68479fc47f23d13db42f34e5ebf7ece43112c052 => 0000000000000000000000000000000000000000:00xc009a5e5a0func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	840391a7786207c2db7c9f057a3fd6e9b69383afd845510ce8d4e9042b8b8938 => 0000000000000000000000000000000000000000:00xc00a19e960func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 18
	9c830546c6d6e2cbbb631d7c947800bd2b7468cefa839085128e842fab8ad592 => 0000000000000000000000000000000000000000:00xc00bd7da40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	31d297134f204394fdcf03554ce343508af30f9d0283561a4b1e6330821bbcfb => 0000000000000000000000000000000000000000:00xc009cf6b40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 17
	f058d8b6e079fcd3e4717b25aff4b42a5a5adeb813099658f18337011b01d6fa => 0000000000000000000000000000000000000000:00xc009cf7c20func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	141498f641627a6f0aea04dd28e6f0ec2dcc1972057ef63f9d55549d20ec1520 => 0000000000000000000000000000000000000000:00xc0074fab40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	554f658ca624e0dd9c4b8423eafd9a8b38a00b9b73bee44e8dc9e605f1deb698 => 0000000000000000000000000000000000000000:00xc00baecf00func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	ce0730bdbefa5ce59469185a38a9998c718d3e39d200fd103dc8f268a9e3a1aa => 0000000000000000000000000000000000000000:00xc00055e1e0func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 19
	9c830546c6d6e2cbbb631d7c947800bd2b7468cefa839085128e842fab8ad592 => 0000000000000000000000000000000000000000:00xc00bd7da40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	5a549c98814e0a5368e4a421c61ec0267a71237231e6baa2fc9dd8201e577d27 => 0000000000000000000000000000000000000000:00xc00d1d0780func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	961eb8768f3ebce807ea192acd6f15b76dd94ce5c45fe08310cd6a84b25d1ad9 => 0000000000000000000000000000000000000000:00xc00c5e6f00func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 17
	31d297134f204394fdcf03554ce343508af30f9d0283561a4b1e6330821bbcfb => 0000000000000000000000000000000000000000:00xc009cf6b40func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)
Dupe detected: 16
	d40af40a1d15bbb4c95f4306a6c1797e9915768996321b42911eb3cf4ec12243 => 0000000000000000000000000000000000000000:00xc002aecd20func len(x interface {  })  int<VPBlock(1,8)> {  }0x0x: (undefined).res_0: (undefined)

Suggestions

Without too much I highly suggest that if we can, let's get more creative and perhaps cache nodes with the same fingerprints if necessary which would massively speed up Gno and even reduce the memory bloat. I feel like this would be a great win for the launch and getting production ready.

Kindly cc-ing @n2p5 @petar-dambovaliev @jaekwon @moul @thehowl @notJoon
@odeke-em odeke-em added the 🐞 bug Something isn't working label Jan 12, 2025
@thehowl
Copy link
Member

thehowl commented Jan 20, 2025

Some ideas that can be tried out:

  • Keep in machine a way to cache Block with the same BlockNode and parent (useful for functions being repeatedly called, as is the case for the stdlib tests)
  • Move Block.Blank to a static value, so it doesn't occupy space when allocating a node.
  • sync.Pool of []TypedValue (always zeroed in, possibly of fixed size, like 32)

Thank you for reporting this, I've known it for a while and it's annoying.

@thehowl thehowl mentioned this issue Jan 23, 2025
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
🐞 bug Something isn't working non-security
Projects
🧙‍♂️gno.land core team
Status: Triage
Milestone
No milestone
Development

No branches or pull requests
3 participants
@thehowl @odeke-em @kristovatlas