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.

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

Add ability to cache/push compressed layers #517

Closed
wants to merge 16 commits into from

Conversation

choo-stripe
Copy link
Contributor

Hey!

I did a bunch of profiling on the library and made some optimizations. For the image I was experimenting with, push timing went from 2mins, 25 seconds to 49 seconds.

I know I've done some bad things here, but would love to work together to get some of these savings merged in some form or another.

I'll leave some comments throughout to share some thoughts so we can move forward.

@googlebot
Copy link

Thanks for your pull request. It looks like this may be your first contribution to a Google open source project (if not, look below for help). Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please visit https://cla.developers.google.com/ to sign.

Once you've signed (or fixed any issues), please reply here with @googlebot I signed it!) and we'll verify it.


What to do if you already signed the CLA

Individual signers
Corporate signers

ℹ️ Googlers: Go here for more info.

@@ -148,7 +153,13 @@ func (i *uncompressedImageExtender) Manifest() (*v1.Manifest, error) {
},
}

ls, err := i.Layers()
// TODO this shouldn't depend on layers being populated
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't pass options into manifest generation, so we do some hackery here. Calling i.Layers() is slow, so this saved 10s of seconds.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is Layers slow?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I imagine it was calculating digests for the first time (since we called CompressedLayers above but I'm not 100% sure.

return nil
})
}
if err := g.Wait(); err != nil {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Parallelizing here saved >1 minute.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we might actually want to move the parallelization into here?

for _, add := range i.adds {
diffID, err := add.Layer.DiffID()
if err != nil {
return err
}
diffIDs = append(diffIDs, diffID)
history = append(history, add.History)
diffIDMap[diffID] = add.Layer
}
m, err := i.base.Manifest()
if err != nil {
return err
}
manifest := m.DeepCopy()
manifestLayers := manifest.Layers
for _, add := range i.adds {
d := v1.Descriptor{}
var err error
if d.Size, err = add.Layer.Size(); err != nil {
return err
}
if d.Digest, err = add.Layer.Digest(); err != nil {
return err
}
if d.MediaType, err = add.Layer.MediaType(); err != nil {
return err
}
d.Annotations = add.Annotations
d.URLs = add.URLs
manifestLayers = append(manifestLayers, d)
digestMap[d.Digest] = add.Layer
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do uncompressed images back on to mutate? I haven't traced it deep enough into the stack.

gzipReadCloser := v1util.GzipReadCloser(uncompressedReader)

// TODO probably shouldnt cache the contents, should probably just re-gzip but aint nobody got time for that
buf := new(bytes.Buffer)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking about users passing in a io.ReadWriter to allocate their own storage or something. Any feedback welcome.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not 100% sure what's going on here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This reads the compressed layer into RAM - which comes with tradeoffs. Could run out of RAM, but also get super fast layer contents access.

}

// WriteMulti pushes the provided img to multiple specified image references.
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Writing multiple tags seemed to be expensive (digesting, compressing, whatever). Adding the ability to just push refs cut about 20 seconds at the end.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can partially solve some of this by just implementing an explicit tagging operation, see: #349

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep!


// WriteMulti pushes the provided img to multiple specified image references.
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error {
// dedupe registries
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

deduping is important for rate limits and for the network calls for checking if blobs exist. A lot of layers can really have an impact here - especially when pushing a bunch of tags to one repo.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Deduping per registry is interesting... I hadn't thought of that. I think this is mostly addressed by #349, but I can imagine deduping blobs across multiple images to avoid extraneous existence checks (but that's not covered here).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yep!

pkg/v1/image.go Outdated
// CompressedLayers returns the ordered collection of compressed filesystem layers that
// comprise this image. The order of the list is oldest/base layer first, and
// most-recent/top layer last. CompressedLayers are useful for optimized pushing.
CompressedLayers() ([]Layer, error)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is this better than just calling Compressed on each layer that gets returned? It's unclear to me why this is needed.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Through profiling today, I found out that Layers() was called multiple times and returned new layers. So the speedup was because CompressedLayers cached the compressed layers, while Layers did not.

@@ -148,7 +153,13 @@ func (i *uncompressedImageExtender) Manifest() (*v1.Manifest, error) {
},
}

ls, err := i.Layers()
// TODO this shouldn't depend on layers being populated
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why is Layers slow?

return nil
})
}
if err := g.Wait(); err != nil {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we might actually want to move the parallelization into here?

for _, add := range i.adds {
diffID, err := add.Layer.DiffID()
if err != nil {
return err
}
diffIDs = append(diffIDs, diffID)
history = append(history, add.History)
diffIDMap[diffID] = add.Layer
}
m, err := i.base.Manifest()
if err != nil {
return err
}
manifest := m.DeepCopy()
manifestLayers := manifest.Layers
for _, add := range i.adds {
d := v1.Descriptor{}
var err error
if d.Size, err = add.Layer.Size(); err != nil {
return err
}
if d.Digest, err = add.Layer.Digest(); err != nil {
return err
}
if d.MediaType, err = add.Layer.MediaType(); err != nil {
return err
}
d.Annotations = add.Annotations
d.URLs = add.URLs
manifestLayers = append(manifestLayers, d)
digestMap[d.Digest] = add.Layer
}

gzipReadCloser := v1util.GzipReadCloser(uncompressedReader)

// TODO probably shouldnt cache the contents, should probably just re-gzip but aint nobody got time for that
buf := new(bytes.Buffer)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not 100% sure what's going on here.

}

// WriteMulti pushes the provided img to multiple specified image references.
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can partially solve some of this by just implementing an explicit tagging operation, see: #349


// WriteMulti pushes the provided img to multiple specified image references.
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error {
// dedupe registries
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Deduping per registry is interesting... I hadn't thought of that. I think this is mostly addressed by #349, but I can imagine deduping blobs across multiple images to avoid extraneous existence checks (but that's not covered here).

@jonjohnsonjr
Copy link
Collaborator

Hey!

Hello! 👋

I did a bunch of profiling on the library and made some optimizations. For the image I was experimenting with, push timing went from 2mins, 25 seconds to 49 seconds.

This is awesome, thanks for taking the time to experiment with this 😄

I know I've done some bad things here, but would love to work together to get some of these savings merged in some form or another.

I'll leave some comments throughout to share some thoughts so we can move forward.

Absolutely. I'm really interested in how you're using this package -- we might be able to optimize things further, or I could point you in a better direction. Could you put together a small, representative program that demonstrates some of the slowness you're seeing? I'd love to be able to have a reproducible test to benchmark any changes against. We have a small registry package for testing that implements most of the registry protocol, if that helps.

@jonjohnsonjr
Copy link
Collaborator

There's also https://godoc.org/github.com/google/go-containerregistry/pkg/v1/cache which might be useful for caching gzipped things.

Raw logs:
2019/09/11 10:33:37 WRITE-PROFILING Write start
2019/09/11 10:33:37 WRITE-PROFILING pulled layers
2019/09/11 10:33:37 WRITE-PROFILING made options
2019/09/11 10:33:37 WRITE-PROFILING created writer
2019/09/11 10:33:39 WRITE-PROFILING got digest for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 10:33:40 WRITE-PROFILING got digest for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 10:33:40 WRITE-PROFILING got digest for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 10:33:43 WRITE-PROFILING got digest for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 10:33:52 WRITE-PROFILING got digest for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 10:33:52 WRITE-PROFILING got digest for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 10:33:54 WRITE-PROFILING got digest for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 10:33:54 WRITE-PROFILING got digest for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 10:33:54 WRITE-PROFILING got digest for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 10:33:54 WRITE-PROFILING got digest for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 10:33:54 WRITE-PROFILING got digest for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 10:33:55 WRITE-PROFILING got digest for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 10:33:55 WRITE-PROFILING got digest for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 10:33:55 WRITE-PROFILING got digest for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 10:33:56 WRITE-PROFILING got digest for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 10:33:56 WRITE-PROFILING got digest for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 10:33:56 WRITE-PROFILING got digest for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 10:33:57 WRITE-PROFILING got digest for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 10:33:57 WRITE-PROFILING got digest for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 10:34:21 WRITE-PROFILING done waiting for layers + config
2019/09/11 10:34:37 WRITE-PROFILING committed
--- FAIL: TestPerf (59.64s)
    write_test.go:1259: time: 59.641539406s

Notes:
1) The first 20 seconds are spent getting digests
2) Then 24 seconds are spent waiting for gzip/upload
3) Finally, 16 seconds are spent committing
2019/09/11 11:42:19 WRITE-PROFILING Write start
2019/09/11 11:42:19 WRITE-PROFILING pulled layers
2019/09/11 11:42:19 WRITE-PROFILING made options
2019/09/11 11:42:19 WRITE-PROFILING created writer
2019/09/11 11:42:19 WRITE-PROFILING got first digest for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:42:19 WRITE-PROFILING got first digest for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:42:20 WRITE-PROFILING got first digest for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:42:20 WRITE-PROFILING got first digest for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:42:20 WRITE-PROFILING got first digest for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:42:22 WRITE-PROFILING got first digest for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:42:23 WRITE-PROFILING got first digest for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:42:24 WRITE-PROFILING got first digest for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:42:24 WRITE-PROFILING got first digest for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:42:30 WRITE-PROFILING got first digest for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:42:30 WRITE-PROFILING done parallel computing digests
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:42:30 WRITE-PROFILING got digest for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:43:12 WRITE-PROFILING done waiting for layers + config
2019/09/11 11:43:27 WRITE-PROFILING committed
--- FAIL: TestPerf (68.81s)
    write_test.go:1259: time: 1m8.808613609s

Notes:
1) The first 11 seconds are spent getting digests - computing in parallel shaved off 9 seconds
2) Then 42 seconds are spent waiting for gzip/upload (much higher than before! maybe we got unlucky with the first run. I'm not about to do multiple trials and average.)
3) Finally, 15 seconds are spent committing (inline with before)

Our overall time is up but I'm fairly confident the optimization did not negatively impact the later stages.
2019/09/11 11:55:57 WRITE-PROFILING Write start
2019/09/11 11:55:57 WRITE-PROFILING pulled layers
2019/09/11 11:55:57 WRITE-PROFILING made options
2019/09/11 11:55:57 WRITE-PROFILING created writer
2019/09/11 11:56:06 WRITE-PROFILING done parallel computing digests
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484: 25.271µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea: 20.235µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda: 16.998µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830: 8.048µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a: 8.355µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607: 5.648µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7: 21.606µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c: 6.016µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331: 7.279µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb: 5.918µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb: 5.771µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468: 5.505µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b: 5.678µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5: 4.991µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4: 4.778µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac: 5.426µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f: 6.268µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61: 5µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e: 15.116µs
2019/09/11 11:56:06 UPLOAD-ONE-PROFILING time to get digest for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516: 7.333µs
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING streamed sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING again got digest sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING upload initiated for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:56:07 UPLOAD-ONE-PROFILING compressed for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:56:12 UPLOAD-ONE-PROFILING streamed sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:56:12 UPLOAD-ONE-PROFILING again got digest sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:56:13 UPLOAD-ONE-PROFILING streamed sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:56:13 UPLOAD-ONE-PROFILING again got digest sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:56:13 UPLOAD-ONE-PROFILING streamed sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:56:13 UPLOAD-ONE-PROFILING again got digest sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:56:14 UPLOAD-ONE-PROFILING committed sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 11:56:14 UPLOAD-ONE-PROFILING streamed sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:56:14 UPLOAD-ONE-PROFILING again got digest sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:56:14 UPLOAD-ONE-PROFILING streamed sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:56:14 UPLOAD-ONE-PROFILING again got digest sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:56:15 UPLOAD-ONE-PROFILING streamed sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:56:15 UPLOAD-ONE-PROFILING again got digest sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:56:20 UPLOAD-ONE-PROFILING streamed sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:56:20 UPLOAD-ONE-PROFILING again got digest sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:56:21 UPLOAD-ONE-PROFILING streamed sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:56:21 UPLOAD-ONE-PROFILING again got digest sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING streamed sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING again got digest sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING streamed sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING again got digest sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING streamed sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:56:22 UPLOAD-ONE-PROFILING again got digest sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:56:23 UPLOAD-ONE-PROFILING streamed sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:56:23 UPLOAD-ONE-PROFILING again got digest sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:56:42 UPLOAD-ONE-PROFILING streamed sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:56:42 UPLOAD-ONE-PROFILING again got digest sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:56:42 UPLOAD-ONE-PROFILING streamed sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:56:42 UPLOAD-ONE-PROFILING again got digest sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:56:43 UPLOAD-ONE-PROFILING streamed sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:56:43 UPLOAD-ONE-PROFILING again got digest sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:56:43 UPLOAD-ONE-PROFILING streamed sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:56:43 UPLOAD-ONE-PROFILING again got digest sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:56:44 UPLOAD-ONE-PROFILING streamed sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:56:44 UPLOAD-ONE-PROFILING again got digest sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:56:44 UPLOAD-ONE-PROFILING streamed sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:56:44 UPLOAD-ONE-PROFILING again got digest sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING streamed sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING again got digest sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING committed sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING committed sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING committed sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING committed sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 11:56:47 UPLOAD-ONE-PROFILING committed sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 11:56:48 UPLOAD-ONE-PROFILING committed sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 11:56:49 UPLOAD-ONE-PROFILING committed sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 11:56:49 WRITE-PROFILING done waiting for layers + config
2019/09/11 11:57:06 WRITE-PROFILING committed
--- FAIL: TestPerf (69.38s)
    write_test.go:1259: time: 1m9.376608216s

I picked some random shas to trace through:
Following 481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7:
1) 14 seconds spent streaming, 11:56:07 to 11:56:21
2) 27 seconds spent committing, 11:56:21 to 11:56:48

Following f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468:
1) 35 seconds spent streaming, 11:56:07 to 11:56:42
2) 7 seconds spent committing, 11:56:42 to 11:56:49

Following 5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac:
1) 15 seconds spent streaming, 11:56:07 to 11:56:22
2) 26 seconds spent committing, 11:56:22 to 11:56:48

Following 1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b:
1) 37 seconds spent streaming, 11:56:07 to 11:56:44
2) 5 seconds spent committing, 11:56:44 to 11:56:49

Since these timestamps are whack I ran some real analysis (all timestamps in seconds):
time to streamed: 14.0
time to streamed: 37.0
time to streamed: 7.0
time to streamed: 35.0
time to streamed: 15.0
time to streamed: 6.0
time to streamed: 15.0
time to streamed: 16.0
time to streamed: 7.0
time to streamed: 15.0
time to streamed: 5.0
time to streamed: 40.0
time to streamed: 0.0
time to streamed: 6.0
time to streamed: 37.0
time to streamed: 36.0
time to streamed: 35.0
time to streamed: 13.0
time to streamed: 36.0
time to streamed: 8.0
time to committed: 27.0
time to committed: 5.0
time to committed: 33.0
time to committed: 7.0
time to committed: 26.0
time to committed: 34.0
time to committed: 26.0
time to committed: 25.0
time to committed: 33.0
time to committed: 26.0
time to committed: 35.0
time to committed: 2.0
time to committed: 7.0
time to committed: 34.0
time to committed: 5.0
time to committed: 6.0
time to committed: 7.0
time to committed: 28.0
time to committed: 6.0
time to committed: 33.0
total: 41.0
total: 42.0
total: 40.0
total: 42.0
total: 41.0
total: 40.0
total: 41.0
total: 41.0
total: 40.0
total: 41.0
total: 40.0
total: 42.0
total: 7.0
total: 40.0
total: 42.0
total: 42.0
total: 42.0
total: 41.0
total: 42.0
total: 41.0

What we notice here is that either streaming or committing take a long time, but the totals are always the same.

Looking at https://github.com/google/go-containerregistry/blob/8b1ae43a6dc3b266d2f46cf6b207dd14abc6711a/pkg/registry/blobs.go, this actually makes a lot of sense. Most of the time is spent waiting for locks, because the server holds locks while the client is compressing. In the next commit, I'll try compressing first, and then send the compressed blob.
2019/09/11 13:53:19 WRITE-PROFILING Write start
2019/09/11 13:53:19 WRITE-PROFILING pulled layers
2019/09/11 13:53:19 WRITE-PROFILING made options
2019/09/11 13:53:19 WRITE-PROFILING created writer
2019/09/11 13:53:28 WRITE-PROFILING done parallel computing digests
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484: 30.444µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61: 15.324µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb: 12.993µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb: 22.964µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5: 18.705µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7: 5.551µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830: 12.939µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda: 7.527µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a: 5.401µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4: 6.499µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607: 5.338µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516: 5.759µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac: 5.151µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c: 5.527µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e: 5.084µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f: 4.844µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331: 5.134µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468: 5.505µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b: 5.634µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING time to get digest for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea: 15.331µs
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING upload initiated for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING compressed for sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING streamed sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING again got digest sha256:56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING committed sha256:08d50fa7ff8660d0ffa2c9d6f3212408b76a52a71b1ce5f1b02b97030948ef2d
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING upload initiated for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING compressed for sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING streamed sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING again got digest sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 13:53:28 UPLOAD-ONE-PROFILING committed sha256:f50724a8040f2a0e8af9cdc2072d0ba3bf6021aa3a49a7586da414e136072468
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING upload initiated for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 13:53:31 UPLOAD-ONE-PROFILING compressed for sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 13:53:32 UPLOAD-ONE-PROFILING streamed sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 13:53:32 UPLOAD-ONE-PROFILING again got digest sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING upload initiated for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING compressed for sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING upload initiated for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING compressed for sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING upload initiated for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING compressed for sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING streamed sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 13:53:33 UPLOAD-ONE-PROFILING again got digest sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 13:53:34 UPLOAD-ONE-PROFILING streamed sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 13:53:34 UPLOAD-ONE-PROFILING again got digest sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 13:53:34 UPLOAD-ONE-PROFILING streamed sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 13:53:34 UPLOAD-ONE-PROFILING again got digest sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 13:53:35 UPLOAD-ONE-PROFILING streamed sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 13:53:35 UPLOAD-ONE-PROFILING again got digest sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 13:53:35 UPLOAD-ONE-PROFILING streamed sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 13:53:35 UPLOAD-ONE-PROFILING again got digest sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING streamed sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING again got digest sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING streamed sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING again got digest sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING streamed sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING again got digest sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING streamed sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 13:53:36 UPLOAD-ONE-PROFILING again got digest sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING streamed sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING again got digest sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING committed sha256:3fbee64400b6eaf26cd277beb8468025a391720528edf9461f1f34e10b88924e
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING streamed sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING again got digest sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING streamed sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING again got digest sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING streamed sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING again got digest sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING committed sha256:03895926db4d49c34c0c25f425f269feb67ac640df1a3e82d9dcd1592eb8348f
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING upload initiated for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING compressed for sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 13:53:37 UPLOAD-ONE-PROFILING committed sha256:5126e156a78ed932e561054c5484d8ccbcee91f67e600cfa959ab155089455ac
2019/09/11 13:53:38 UPLOAD-ONE-PROFILING committed sha256:0fbd64e1bea64e032bc54d9d8946e8c515f89cf38f7b3f2f20aa4cc5c799be61
2019/09/11 13:53:38 UPLOAD-ONE-PROFILING committed sha256:f6c5ec4049e6e96fe1b89575d80979844ce55b645580cdc701582453f68a5bd4
2019/09/11 13:53:38 UPLOAD-ONE-PROFILING committed sha256:1c21e3a1b98d5a7bde5c4d3ee77d1fd6022d5c89525ba8a4f9f561fe9613900b
2019/09/11 13:53:38 UPLOAD-ONE-PROFILING committed sha256:e2b6891c9e6b1053dfce96dc758122b433e09308b92c0d8e9e4e4f7528de5bc5
2019/09/11 13:53:38 UPLOAD-ONE-PROFILING committed sha256:fd862fd9cdee525ba48148bb749d33bd50a545ba2be8dd080e7425117d5fe47c
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:ef869d53b9981a8374813b01764292f0302b056ac38c4b62d197d865065ec607
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:d5af1d234e50b043f6dfe9859f9e46bbaa34163c742e1ff6ddda626eee8d1331
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:481b2c064d3cae8012d4a78ae35d7771f729b02eba32e306bc4057534552d2b7
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:633638cc12386f9ce64e337aa64feb6f403d1794faea8cef1159bc66644b3830
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:a2650247b5cb56138bdfc8b12c5646f87b4f94b79e911413b57d9216b714e9fb
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING committed sha256:006641632718d88f91d7104b7fb73a0a51983bf4745064a05fb17cef08b9c484
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING streamed sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 13:53:39 UPLOAD-ONE-PROFILING again got digest sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 13:53:40 UPLOAD-ONE-PROFILING committed sha256:4dd7cdc1f480b0b5494142027ebb812352d1959a56b2b74e105a587ba06a00fb
2019/09/11 13:53:41 UPLOAD-ONE-PROFILING upload initiated for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 13:53:41 UPLOAD-ONE-PROFILING compressed for sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 13:53:41 UPLOAD-ONE-PROFILING streamed sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 13:53:41 UPLOAD-ONE-PROFILING again got digest sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 13:53:41 UPLOAD-ONE-PROFILING committed sha256:c8e59f11a9adb71a018b9c3181c1d1037ff502d97937b4d4c196517a25ee23ea
2019/09/11 13:53:42 UPLOAD-ONE-PROFILING upload initiated for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 13:53:42 UPLOAD-ONE-PROFILING compressed for sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 13:53:42 UPLOAD-ONE-PROFILING streamed sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 13:53:42 UPLOAD-ONE-PROFILING again got digest sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 13:53:42 UPLOAD-ONE-PROFILING committed sha256:da4412f2af4d9b08a7177d55ab649d9908486f71ea02dfd5e40ccb3820cae67a
2019/09/11 13:53:54 UPLOAD-ONE-PROFILING upload initiated for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 13:53:54 UPLOAD-ONE-PROFILING compressed for sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 13:53:56 UPLOAD-ONE-PROFILING streamed sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 13:53:56 UPLOAD-ONE-PROFILING again got digest sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 13:53:57 UPLOAD-ONE-PROFILING committed sha256:2dc6074bf8b452bf7404088a7be1ca02c205352224a4054943fb5ba78d47a516
2019/09/11 13:53:57 WRITE-PROFILING done waiting for layers + config
2019/09/11 13:54:13 WRITE-PROFILING committed
--- FAIL: TestPerf (53.96s)
    write_test.go:1259: time: 53.96065864s

Further analysis:
time to streamed: 6.0
time to streamed: 4.0
time to streamed: 4.0
time to streamed: 2.0
time to streamed: 5.0
time to streamed: 5.0
time to streamed: 3.0
time to streamed: 2.0
time to streamed: 1.0
time to streamed: 4.0
time to streamed: 0.0
time to streamed: 2.0
time to streamed: 0.0
time to streamed: 5.0
time to streamed: 4.0
time to streamed: 5.0
time to streamed: 0.0
time to streamed: 0.0
time to streamed: 4.0
time to streamed: 3.0
time to committed: 2.0
time to committed: 3.0
time to committed: 2.0
time to committed: 1.0
time to committed: 2.0
time to committed: 3.0
time to committed: 3.0
time to committed: 4.0
time to committed: 5.0
time to committed: 3.0
time to committed: 0.0
time to committed: 1.0
56c1cab9a21ab143544fca5b24abbf1b377edd5396d27d0a42f1b5d9899c7bda was not committed
time to committed: 2.0
time to committed: 2.0
time to committed: 3.0
time to committed: 0.0
time to committed: 0.0
time to committed: 2.0
time to committed: 4.0
total: 8.0
total: 7.0
total: 6.0
total: 3.0
total: 7.0
total: 8.0
total: 6.0
total: 6.0
total: 6.0
total: 7.0
total: 0.0
total: 3.0
total: 7.0
total: 6.0
total: 8.0
total: 0.0
total: 0.0
total: 6.0
total: 7.0

Previously: 52 seconds til all layers uploaded, 17 seconds to commit
Now: 38 seconds til all layers uploaded, 15 seconds to commit

We've gone from 69 seconds to 54 - a modest improvement but still needs
work.
2019/09/11 15:45:55 MANIFEST-PROFILING start
2019/09/11 15:45:55 MANIFEST-PROFILING RawConfigFile
2019/09/11 15:45:55 MANIFEST-PROFILING cfgHash
2019/09/11 15:45:55 MANIFEST-PROFILING Layers
2019/09/11 15:46:12 MANIFEST-PROFILING filled descriptors
2019/09/11 15:46:12 PUT /v2/test/image/manifests/tag
2019/09/11 15:46:12 MANIFEST-PROFILING start
2019/09/11 15:46:12 WRITE-PROFILING committed

So, it's re-digesting all the layers. That's clowning.
2019/09/11 15:59:03 MANIFEST-PROFILING start
2019/09/11 15:59:03 MANIFEST-PROFILING RawConfigFile
2019/09/11 15:59:03 MANIFEST-PROFILING cfgHash
2019/09/11 15:59:03 MANIFEST-PROFILING Layers
2019/09/11 15:59:03 MANIFEST-PROFILING filled descriptors
2019/09/11 15:59:03 PUT /v2/test/image/manifests/tag
2019/09/11 15:59:03 MANIFEST-PROFILING start
2019/09/11 15:59:03 WRITE-PROFILING committed
--- FAIL: TestPerf (36.32s)
    write_test.go:1259: time: 36.314556402s

Now we're down to 36 seconds - this looks pretty good
--- FAIL: TestPerf (20.64s)
    write_test.go:1259: time: 20.641068214s
@choo-stripe
Copy link
Contributor Author

@jonjohnsonjr given your questions and ideas, I tried to come up with a less invasive way to speed things up (how to make the existing implementation fast instead of replacing it entirely). Given that, I did a bunch of profiling and clearly wrote out my findings for each commit. For the test harness that I wrote here, we went from ~1 minute to 20 seconds - which matches my old implementation.

I hope that by reading commit messages from oldest to newest, you'll be able to see at each stage what was slow and how the optimization helped.

I think this PR is now in a much better place.

Remaining issues that concern me:

  1. We now push the config layer compressed instead of uncompressed. We need to verify that this doesn't break any assumptions (i.e. making sure the manifest doesn't use the uncompressed sha - I don't think it should)
  2. We may not want to pull layers into ram before uploading. That Pull layers into RAM before sending them sped things up quite a bit for our specific test harness here, but I'm not convinced it would materially impact perf with a more robust/parallellizable registry. I image we want to revert d16f7f9.

@codecov-io
Copy link

codecov-io commented Sep 12, 2019

Codecov Report

Merging #517 into master will decrease coverage by 0.04%.
The diff coverage is 57.14%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #517      +/-   ##
==========================================
- Coverage   73.11%   73.07%   -0.05%     
==========================================
  Files          92       92              
  Lines        3917     3933      +16     
==========================================
+ Hits         2864     2874      +10     
- Misses        692      696       +4     
- Partials      361      363       +2
Impacted Files Coverage Δ
pkg/v1/partial/uncompressed.go 56.25% <33.33%> (-1.53%) ⬇️
pkg/v1/remote/write.go 64.38% <84.61%> (+0.58%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 03a1f32...e4e5b52. Read the comment docs.

@jonjohnsonjr
Copy link
Collaborator

For that test image, you could drop the Dockerfile and just use this:

img, err := random.Image(50*1024*1024, 10)

Though, then we are benchmarking whatever we save to a tarball instead of whatever docker saves to a tarball, which might not be representative of what you're seeing.

Instead of writing a test, you can add a go benchmark that we could check in: https://golang.org/pkg/testing/#hdr-Benchmarks

ref: ref,
client: client,
layerCachePath: cacheDir,
layerCache: cache.NewFilesystemCache(cacheDir),
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't actually want to embed the cache into the writer -- callers should wrap the image they are going to write with a cache.Image. This isn't very discoverable, so I opened a PR to add an example to the godoc: #522

@choo-stripe
Copy link
Contributor Author

Re using random.Image:
This is a great suggestion to clean up the tests. I still think it's valuable, but it's not representative of the perf issues I was seeing. I was seeing perf issues due to disk io. Caching the layer computation was only exposed because disk io was slow.

Re cache.Image:
This still combines risk read/compression/network into one unified op, which, from benchmarking, some registries don't deal with super well.

  1. How do you feel about the updated PR?
  2. How would you feel about a separate PR with an in-memory cache that could be pre-populated/pre-compressed so compression and digestion become constant-time ops?

Btw, I really appreciate you taking the time to work through this with me.

@choo-stripe
Copy link
Contributor Author

Ah! One more thing - with the image cache, with uncompressed images being read of disk, they get compressed twice:

  1. Once for Digest(), which throws away the compressed contents(!)
  2. Once when you need to read the Compressed() contents

Do you have ideas on how to combine those ops?

  • We could put them in v1/partial/uncompressed.go but that could allocate large amounts of memory in there which doesn't seem fitting.
  • We could put this in an in-memory cache, but that would break interface boundaries - we'd no longer be calling layer.Digest(), we'd be calculating it ourselves as we read Compressed() to load the layer into cache.

I don't see a clean way to do this, but it would save us a lot of time.

@choo-stripe
Copy link
Contributor Author

I made some minor modifications to the cache and added an in-memory cache which gave ~the same perf gains because it also dedupes a lot of the compression/digesting/etc - choo-stripe/go-containerregistry@choo/simplifying...choo-stripe:choo/inmemcache

@jonjohnsonjr
Copy link
Collaborator

jonjohnsonjr commented Sep 13, 2019

Btw, I really appreciate you taking the time to work through this with me.

Of course! Thanks for taking the time to do this!

Going to just explain a few things that might answer most of your questions, let me know if I missed anything:

In the happy case, we know the digest ahead of time, and our upload sequence should look like this:
image

That HEAD is cheap if we already know the digest; we just get a 404 and subsequently do the complete upload. If we get a 200, we can skip the entire upload, so that's a huge win.

In the sad case (what you're hitting, I believe), we have uncompressed blobs, and we don't know the digest ahead of time. I think we're still hitting the above strategy because we're eagerly calculating the digests when we read layers from the tarball. Ideally, we wouldn't do that at all! We would just skip the first HEAD request and hash the contents as we upload them:
image

We actually have an implementation for this, stream.Layer, which @imjasonh implemented, but it has some problems and we're not using it anywhere by default.

Sometimes the best thing to do is digest the content locally before uploading, so you can do an existence check first. E.g. if your internet is slow, it's better trade CPU time just in case the registry already has the blob. In most cases, though, it's better to just upload it.

How do you feel about the updated PR?

Your pre-calculation of digests runs afoul of this code in remote for handling stream.Layer, so I'd be reluctant to merge that bit.

It might be helpful to explain what needs to happen during an image upload. Here's a diagram of data flow through the system for an image with one layer, expressed via analogous tools:
image

(this is basically the implementation of stream.Layer)

We need to hash the uncompressed contents, compress them, hash the compressed contents, then upload them to the registry. The hash of the uncompressed contents is called the diffid, which ends up in a config file. The hash of the compressed contents is usually called the layer digest, which ends up in the image manifest. The hash of the config file also ends up in the manifest. It's a bit of a juggling act.

How I imagine this being fixed is that we cache the uncompressed contents as we read them, and we cache the compressed contents as we read them. We should also be memoizing the digest and diffid so that we avoid re-compressing or re-hashing anything:

image

E.g., when we call Digest() on a layer, it might have to read the layer from disk, gzip it, and sha256sum it, just to compute the digest. We throw away all that work, though! Ideally, that call to Digest() should write the gzipped layer to a cache (on disk or in memory) and memoize the sha256 value for both its uncompressed and compressed contents. Subsequent calls for Digest() and DiffID() would then just return the memoized values. Subsequent calls of Compressed() should read the compressed contents from the cache instead of re-zipping everything.

How would you feel about a separate PR with an in-memory cache that could be pre-populated/pre-compressed so compression and digestion become constant-time ops?

I'm somewhat surprised that you think your disk is the bottleneck here -- I would suspect it's actually gzip. If you do have a slow disk, though, being able to supply an in-memory cache would help a lot with that!

So here's what I'm thinking:

  1. An in-memory cache implementation sounds great, I'd love that in a separate PR.
  2. Let's figure out why we're re-compressing things even with a cache. I think this is because the tarball implementation is too eager. We shouldn't be calculating the digest until we need it.

For 2, I think we probably want to switch over to using stream.Layer for the tarball image, but it might just be that we need to make some operations lazy that are currently eager. I haven't looked at it recently, but I have a hunch that we could make it more amenable to composition with cache.Image than it is today.

I think some of your issues could have been solved by better documentation, which is mostly my fault 😄 if there's anything that could be clarified, doc issues and doc PRs are also super helpful.

Thanks again, @choo-stripe

@jmillikin-stripe
Copy link
Contributor

(quick drive-by comment; I haven't deeply reviewed the code yet)

Sometimes the best thing to do is digest the content locally before uploading, so you can do an existence check first. E.g. if your internet is slow, it's better trade CPU time just in case the registry already has the blob. In most cases, though, it's better to just upload it.

In our case both compression and uploading are slow, and pre-existing layers are common. We'd ideally like to compress the layers and compute all relevant checksums at build time, so that the push process is a stream of HEADs, then fetches of missing layers from our datastore, then pushing those (already compressed) layers to the image registry.

I'm somewhat surprised that you think your disk is the bottleneck here -- I would suspect it's actually gzip. If you do have a slow disk, though, being able to supply an in-memory cache would help a lot with that!

It depends on the image, but in general we're nearly maxed out on both disk IO and CPU time. For gzip we use a parallel implementation (https://zlib.net/pigz/), which can saturate a 48-thread CPU.

We need to hash the uncompressed contents, compress them, hash the compressed contents, then upload them to the registry.

In previous discussions with the maintainer of the Python containerregistry code, we brought up the idea of a more optimized image format -- one that stored compressed layers directly, and stored all of the relevant checksums. Do you think it would be practical to implement support for such a format in this new Go implementation?

@jonjohnsonjr
Copy link
Collaborator

In previous discussions with the maintainer of the Python containerregistry code, we brought up the idea of a more optimized image format -- one that stored compressed layers directly, and stored all of the relevant checksums. Do you think it would be practical to implement support for such a format in this new Go implementation?

Two things worth mentioning:

  1. When we write out tarballs, they are actually in the compressed form. We have the digests and the config, already, so we can derive the diffids from the config without any additional work. (I'm assuming we don't do anything stupid like re-hash things, but I have not confirmed this). When docker writes out tarballs, it uses an old format that has uncompressed tar files and doesn't record the digests. Some more info in Add repositories files to image tarballs #526
  2. IMO, the right answer to this is using an OCI image layout. This stores things (manifest, blobs, config) on disk in the same format as it's stored in the registry, so there's not any conversion that has to happen. We have an implementation of this. It has all the same benefits as the "faaaaast" format in containerregistry (I think this is what you're referring to?), with the added bonus of being an actual standard thing instead of something @mattmoor pulled out of his... head. Docker doesn't support this natively, but there's an open issue if you want to stir up trouble.

I'm not sure how y'all are consuming this code internally. If you're using crane, we could trivially add support for OCI layout in pull/push to crane. Let me know if that would help. If you have your own tools that rely on this library, please try it out!

@mattmoor
Copy link
Collaborator

with the added bonus of being an actual standard thing instead of something @mattmoor pulled out of his... head

I absolutely did not pull it out of my head 🙄

@jonjohnsonjr
Copy link
Collaborator

I had a long conversation with @imjasonh about how we could fix this "for real" and it's a bit involved. I'll write something up when I get a chance (possibly this week but probably next week).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants