Skip to content

Commit

Permalink
jar: reuse buffers for nested .jar's
Browse files Browse the repository at this point in the history 
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 $(git log --pretty=oneline | head -4 | awk '{print $1}' | tac) ; 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.754 s ±  0.260 s    [User: 1.711 s, System: 1.264 s]
  Range (min … max):    1.411 s …  2.182 s    10 runs

HEAD is now at 2932093 jar: close the zip.File reader before recursing
  Time (mean ± σ):      1.761 s ±  0.312 s    [User: 1.778 s, System: 1.124 s]
  Range (min … max):    1.271 s …  2.239 s    10 runs

HEAD is now at f6c1ebc jar: prefer io.ReadFull over io.ReadAll
  Time (mean ± σ):     444.8 ms ±  95.3 ms    [User: 353.5 ms, System: 122.3 ms]
  Range (min … max):   337.2 ms … 683.2 ms    10 runs

HEAD is now at 5a28952 jar: reuse buffers for nested .jar's
  Time (mean ± σ):     398.0 ms ±  44.7 ms    [User: 330.6 ms, System: 89.9 ms]
  Range (min … max):   339.7 ms … 471.1 ms    10 runs

It looks like re-using buffers has only a small positive effect on
speed, switching from `io.ReadAll` to `io.ReadFull` has the most impact.
Still, I believe re-using allocations may really help in our production
context 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: use make instead of append
  • Loading branch information
@aktau
aktau committed Feb 28, 2022
1 parent 4b23cd3 commit 37376ef
Showing 1 changed file with 22 additions and 9 deletions.
31 changes: 22 additions & 9 deletions jar/jar.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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)
Expand All @@ -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())
if size := int(fi.Size()); cap(buf) < size {
buf = make([]byte, size)
} else {
buf = buf[:size]
}
n, err := io.ReadFull(r, buf)
if err != nil || n != len(buf) {
return nil, err
return buf, err
}
return buf, nil
}
Expand Down

0 comments on commit 37376ef

Please sign in to comment.