-
Notifications
You must be signed in to change notification settings - Fork 548
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
Conversation
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 What to do if you already signed the CLAIndividual signers
Corporate signers
ℹ️ Googlers: Go here for more info. |
pkg/v1/partial/uncompressed.go
Outdated
@@ -148,7 +153,13 @@ func (i *uncompressedImageExtender) Manifest() (*v1.Manifest, error) { | |||
}, | |||
} | |||
|
|||
ls, err := i.Layers() | |||
// TODO this shouldn't depend on layers being populated |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why is Layers
slow?
There was a problem hiding this comment.
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.
pkg/v1/partial/uncompressed.go
Outdated
return nil | ||
}) | ||
} | ||
if err := g.Wait(); err != nil { |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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?
go-containerregistry/pkg/v1/mutate/mutate.go
Lines 153 to 190 in b02d448
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 | |
} |
There was a problem hiding this comment.
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.
pkg/v1/partial/uncompressed.go
Outdated
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) |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
pkg/v1/remote/write.go
Outdated
} | ||
|
||
// WriteMulti pushes the provided img to multiple specified image references. | ||
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error { |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep!
pkg/v1/remote/write.go
Outdated
|
||
// WriteMulti pushes the provided img to multiple specified image references. | ||
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error { | ||
// dedupe registries |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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).
There was a problem hiding this comment.
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) |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
pkg/v1/partial/uncompressed.go
Outdated
@@ -148,7 +153,13 @@ func (i *uncompressedImageExtender) Manifest() (*v1.Manifest, error) { | |||
}, | |||
} | |||
|
|||
ls, err := i.Layers() | |||
// TODO this shouldn't depend on layers being populated |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why is Layers
slow?
pkg/v1/partial/uncompressed.go
Outdated
return nil | ||
}) | ||
} | ||
if err := g.Wait(); err != nil { |
There was a problem hiding this comment.
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?
go-containerregistry/pkg/v1/mutate/mutate.go
Lines 153 to 190 in b02d448
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 | |
} |
pkg/v1/partial/uncompressed.go
Outdated
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) |
There was a problem hiding this comment.
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.
pkg/v1/remote/write.go
Outdated
} | ||
|
||
// WriteMulti pushes the provided img to multiple specified image references. | ||
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error { |
There was a problem hiding this comment.
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
pkg/v1/remote/write.go
Outdated
|
||
// WriteMulti pushes the provided img to multiple specified image references. | ||
func WriteMulti(refs []name.Reference, img v1.Image, options ...Option) error { | ||
// dedupe registries |
There was a problem hiding this comment.
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).
Hello! 👋
This is awesome, thanks for taking the time to experiment with this 😄
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 |
There's also https://godoc.org/github.com/google/go-containerregistry/pkg/v1/cache which might be useful for caching gzipped things. |
This reverts commit e75d4e6.
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
@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:
|
Codecov Report
@@ 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
Continue to review full report at Codecov.
|
For that test image, you could drop the Dockerfile and just use this:
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 |
pkg/v1/remote/write.go
Outdated
ref: ref, | ||
client: client, | ||
layerCachePath: cacheDir, | ||
layerCache: cache.NewFilesystemCache(cacheDir), |
There was a problem hiding this comment.
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
83d4e95
to
e4e5b52
Compare
Re using Re
Btw, I really appreciate you taking the time to work through this with me. |
Ah! One more thing - with the image cache, with uncompressed images being read of disk, they get compressed twice:
Do you have ideas on how to combine those ops?
I don't see a clean way to do this, but it would save us a lot of time. |
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 |
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: That 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 We actually have an implementation for this, 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.
Your pre-calculation of digests runs afoul of this code in 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: (this is basically the implementation of 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 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: E.g., when we call
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:
For 2, I think we probably want to switch over to using 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 |
(quick drive-by comment; I haven't deeply reviewed the code yet)
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
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.
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:
I'm not sure how y'all are consuming this code internally. If you're using |
I absolutely did not pull it out of my head 🙄 |
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). |
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.