From b85d917e9fc99cf875623faf63e3ddb3222ba67d Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Wed, 23 Feb 2022 23:31:05 +0100 Subject: [PATCH] jar: reuse buffers for nested .jar's MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit is a further optimization of allocation behaviour (see parent). As before, this read is responsible for a bit more than half the bytes allocated observed in a very highly scaled up instance of this [1]. To sanity check this, I added some printf statements to the tests. It appears to work (we clearly see buffer reuse). ``` $ go test Need realloc desired=419430572 len=4096 cap=4096, extending with 419426476 Reallocated desired=419430572 len=419430572 cap=419438592 Buffer reused desired=12691 len=419430572 cap=419438592 Need realloc desired=10951 len=4096 cap=4096, extending with 6855 Reallocated desired=10951 len=10951 cap=12288 Need realloc desired=12691 len=4096 cap=4096, extending with 8595 Reallocated desired=12691 len=12691 cap=13568 Need realloc desired=17631 len=12691 cap=13568, extending with 4940 Reallocated desired=17631 len=17631 cap=21760 Buffer reused desired=16072 len=17631 cap=21760 Buffer reused desired=15537 len=16072 cap=21760 Need realloc desired=17631 len=10951 cap=12288, extending with 6680 Reallocated desired=17631 len=17631 cap=20480 Buffer reused desired=14121 len=17631 cap=20480 Buffer reused desired=16072 len=15537 cap=21760 Buffer reused desired=17631 len=16072 cap=21760 Buffer reused desired=48 len=17631 cap=21760 Buffer reused desired=16072 len=48 cap=21760 Buffer reused desired=48 len=16072 cap=21760 Buffer reused desired=12691 len=48 cap=21760 Buffer reused desired=48 len=12691 cap=21760 Need realloc desired=42374 len=48 cap=21760, extending with 42326 Reallocated desired=42374 len=42374 cap=49152 Buffer reused desired=15537 len=42374 cap=49152 Buffer reused desired=17631 len=14121 cap=20480 Buffer reused desired=440 len=17631 cap=20480 Buffer reused desired=440 len=15537 cap=49152 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Buffer reused desired=440 len=4096 cap=4096 Need realloc desired=17631 len=4096 cap=4096, extending with 13535 Reallocated desired=17631 len=17631 cap=18432 Buffer reused desired=15537 len=17631 cap=18432 Need realloc desired=17631 len=4096 cap=4096, extending with 13535 Reallocated desired=17631 len=17631 cap=18432 Buffer reused desired=17631 len=17631 cap=18432 Buffer reused desired=48 len=17631 cap=18432 Buffer reused desired=12691 len=48 cap=18432 Buffer reused desired=10951 len=12691 cap=18432 Buffer reused desired=12691 len=15537 cap=18432 Buffer reused desired=12691 len=12691 cap=18432 Buffer reused desired=48 len=12691 cap=18432 Need realloc desired=17631 len=4096 cap=4096, extending with 13535 Reallocated desired=17631 len=17631 cap=18432 Buffer reused desired=15537 len=17631 cap=18432 Need realloc desired=17631 len=4096 cap=4096, extending with 13535 Reallocated desired=17631 len=17631 cap=18432 Buffer reused desired=17631 len=15537 cap=18432 Buffer reused desired=48 len=17631 cap=18432 Buffer reused desired=12691 len=48 cap=18432 Buffer reused desired=10951 len=12691 cap=18432 Need realloc desired=12691 len=4096 cap=4096, extending with 8595 Reallocated desired=12691 len=12691 cap=13568 Buffer reused desired=12691 len=12691 cap=13568 Buffer reused desired=48 len=12691 cap=13568 Need realloc desired=16252 len=4096 cap=4096, extending with 12156 Reallocated desired=16252 len=16252 cap=16384 Buffer reused desired=14113 len=16252 cap=16384 Need realloc desired=16252 len=4096 cap=4096, extending with 12156 Reallocated desired=16252 len=16252 cap=16384 Buffer reused desired=16252 len=16252 cap=16384 Buffer reused desired=48 len=16252 cap=16384 Buffer reused desired=12691 len=48 cap=16384 Buffer reused desired=10951 len=12691 cap=16384 Buffer reused desired=12691 len=14113 cap=16384 Buffer reused desired=12691 len=12691 cap=16384 Buffer reused desired=48 len=12691 cap=16384 Need realloc desired=18688 len=48 cap=16384, extending with 18640 Reallocated desired=18688 len=18688 cap=21760 Buffer reused desired=17631 len=18688 cap=21760 PASS ok github.com/google/log4jscanner/jar 21.074s ``` Benchmarks using hyperfine(1) ``` $ for commit in 9d3aceeff48dc332d314d938ef6f3ed7837dfc1e 2932093ea7873a0df400ec12980ed6206b120ad7 f6c1ebcfb928f724f174e9c8ccd818534840a10a 22621447c08378c564d64d6b6809897db5958596 ; do git checkout $commit go build hyperfine -i './log4jscanner jar/testdata' rm log4jscanner done ``` HEAD is now at 9d3acee Document commit that removed InitialContext Time (mean ± σ): 1.386 s ± 0.329 s [User: 1.397 s, System: 0.882 s] Range (min … max): 1.014 s … 2.219 s 10 runs HEAD is now at 2932093 jar: close the zip.File reader before recursing Time (mean ± σ): 1.552 s ± 0.146 s [User: 1.503 s, System: 0.940 s] Range (min … max): 1.252 s … 1.739 s 10 runs HEAD is now at f6c1ebc jar: prefer io.ReadFull over io.ReadAll Time (mean ± σ): 470.5 ms ± 74.0 ms [User: 391.9 ms, System: 100.8 ms] Range (min … max): 379.2 ms … 624.3 ms 10 runs HEAD is now at 2262144 jar: reuse buffers for nested .jar's Time (mean ± σ): 532.5 ms ± 111.8 ms [User: 486.7 ms, System: 146.1 ms] Range (min … max): 438.1 ms … 805.2 ms 10 runs It looks like re-using buffers doesn't have a positive impact on speed, while switching from `io.ReadAll` to `io.ReadFull` does. The differences are small though, and I think it may still help in our production context. [1]: ``` (pprof) list checkJAR Total: 213.06GB ... . 9.89MB 334: f, err := zf.Open() . . 335: if err != nil { . . 336: return fmt.Errorf("open file %s: %v", p, err) . . 337: } . . 338: defer f.Close() . 169.96GB 339: data, err := io.ReadAll(f) . . 340: if err != nil { . . 341: return fmt.Errorf("read file %s: %v", p, err) . . 342: } . . 343: br := bytes.NewReader(data) . 3.40GB 344: r2, err := zip.NewReader(br, br.Size()) ... (pprof) list ReadAll Total: 213.06GB ROUTINE ======================== io.ReadAll in third_party/go/gc/src/io/io.go 113.40GB 169.96GB (flat, cum) 79.77% of Total . . 638:func ReadAll(r Reader) ([]byte, error) { . . 639: b := make([]byte, 0, 512) . . 640: for { . . 641: if len(b) == cap(b) { . . 642: // Add more capacity (let append pick how much). 113.40GB 113.40GB 643: b = append(b, 0)[:len(b)] . . 644: } . 56.56GB 645: n, err := r.Read(b[len(b):cap(b)]) . . 646: b = b[:len(b)+n] . . 647: if err != nil { . . 648: if err == EOF { . . 649: err = nil . . 650: } ``` --- jar/jar.go | 31 ++++++++++++++++++++++--------- 1 file changed, 22 insertions(+), 9 deletions(-) diff --git a/jar/jar.go b/jar/jar.go index 2810028..a00aae8 100644 --- a/jar/jar.go +++ b/jar/jar.go @@ -249,11 +249,18 @@ func (c *checker) bad() bool { const bufSize = 4 << 10 // 4 KiB -var bufPool = sync.Pool{ - New: func() interface{} { - return make([]byte, bufSize) - }, -} +var ( + bufPool = sync.Pool{ + New: func() interface{} { + return make([]byte, bufSize) + }, + } + dynBufPool = sync.Pool{ + New: func() interface{} { + return make([]byte, bufSize) + }, + } +) func (c *checker) checkJAR(r *zip.Reader, depth int, size int64, jar string) error { if depth > c.maxDepth() { @@ -385,7 +392,9 @@ func (c *checker) checkFile(zf *zip.File, depth int, size int64, jar string) err if err != nil { return fmt.Errorf("open file %s: %v", p, err) } - buf, err := readFull(f, fi) + buf := dynBufPool.Get().([]byte) + buf, err = readFull(f, fi, buf) + defer dynBufPool.Put(buf) f.Close() // Recycle the flate buffer earlier, we're going to recurse. if err != nil { return fmt.Errorf("read file %s: %v", p, err) @@ -405,14 +414,18 @@ func (c *checker) checkFile(zf *zip.File, depth int, size int64, jar string) err return nil } -func readFull(r io.Reader, fi os.FileInfo) ([]byte, error) { +func readFull(r io.Reader, fi os.FileInfo, buf []byte) ([]byte, error) { if !fi.Mode().IsRegular() { return io.ReadAll(r) // If not a regular file, size may not be accurate. } - buf := make([]byte, fi.Size()) + size := int(fi.Size()) + if cap(buf) < size { + buf = append(buf[:cap(buf)], make([]byte, size-cap(buf))...) // Make the buffer large enough. + } + buf = buf[:size] n, err := io.ReadFull(r, buf) if err != nil || n != len(buf) { - return nil, err + return buf, err } return buf, nil }