Skip to content

Improve GC sweep logging

João Pereira requested to merge 10-improve-logging into 10-optimize-the-s3-storage-driver-s-delete-function

Context

This change is part of !24 and related to #10.

Changes

Following !39 (comment 268761265), this MR improves the GC sweep stage logs with the following changes:

  • Use structured logging everywhere. Stop using emit, which is nothing more than fmt.Printf. This should make it easier to filter logs in Kibana.

  • Augment logs with additional key/value pairs, most notably a duration key, which shows how long it took to remove blobs and manifests (individually) as well as the whole sweep stage.

  • Blob enumeration should be considered part of the mark stage, not the sweep stage.

  • Nothing should be deleted before the log line X blobs marked, Y blobs and Z manifests eligible for deletion. Currently manifests are being deleted before this.

Notes

I thought about using different log levels here as well, namely using debug when logging each blob and manifest being deleted. However, the debug level is being used across the source code to denote when a method is executed. By turning the debug level on we would see something like the following:

DEBU[0000] filesystem.List("/docker/registry/v2/repositories/myorg3/myproj3/golang/_manifests/tags")  go.version=go1.13.6 instance.id=3504090e-fde9-47ae-819d-c603019ef631 trace.duration=50.178µs trace.file="/Users/jpereira/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).List" trace.id=8c6b2fb2-ef57-4e30-be2c-713378c2a97b trace.line=170
DEBU[0000] filesystem.GetContent("/docker/registry/v2/repositories/myorg3/myproj3/golang/_manifests/tags/1.12rc1/current/link")  go.version=go1.13.6 instance.id=3504090e-fde9-47ae-819d-c603019ef631 trace.duration=358.934µs trace.file="/Users/jpereira/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).GetContent" trace.id=33916d4e-eec1-46b2-ad20-90a6c45f6da6 trace.line=95
myorg3/myproj3/golang: marking manifest sha256:b4be7a6cc0a69eece53c1895146e5c4e8065636dc855048ec288b07438abcc32 
DEBU[0000] (*manifestStore).Get                          go.version=go1.13.6 instance.id=3504090e-fde9-47ae-819d-c603019ef631

Which is not useful for users.

Example

Before (6db1e43b)

...
myorg3/myproj3/registry
myorg3/myproj3/registry: marking manifest sha256:b1165286043f2745f45ea637873d61939bff6d9a59f76539d6228abf79f87774 
myorg3/myproj3/registry: marking blob sha256:f32a97de94e13d29835a19851acd6cbc7979d1d50f703725541e44bb89a1ce91
myorg3/myproj3/registry: marking blob sha256:c87736221ed0bcaa60b8e92a19bec2284899ef89226f2a07968677cf59e637a4
myorg3/myproj3/registry: marking blob sha256:1cc8e0bb44dfaefdc7f0d0ce35f7bcb5bd2b91467a0ad7501499e34de27e3ee4
myorg3/myproj3/registry: marking blob sha256:54d33bcb37f53c65d2678796a458525d291c18058ff65c137d0aea45849e3f14
myorg3/myproj3/registry: marking blob sha256:e8afc091c171595794b2c72071946d2e34c0ecbc00de8b5f8a80dda0f7dfc801
myorg3/myproj3/registry: marking blob sha256:b4541f6d3db6307e43bad1ca823a3221d4c2689bcae8bbd8a312371815e1d1bf
INFO[0000] preparing to delete manifest tag reference    go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea path="/docker/registry/v2/repositories/myorg2/myproj1/memcached/_manifests/tags/1.5.15-alpine/index/sha256/583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68/link"
INFO[0000] preparing to delete manifest                  go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea path="/docker/registry/v2/repositories/myorg2/myproj1/memcached/_manifests/revisions/sha256/583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68/link"
INFO[0000] deleting manifests                            count=2 go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea
INFO[0000] manifests deleted                             count=2 go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea

426 blobs marked, 6 blobs and 1 manifests eligible for deletion
blob eligible for deletion: sha256:4f068b59d6a0b9e9502529a5786b94eaaabea8555694dbbd55e26c866f9b848d
blob eligible for deletion: sha256:583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68
blob eligible for deletion: sha256:8235f906e6129607f6aade38ce3dbc31b38463c76048c3e8dd072bccd71f482b
blob eligible for deletion: sha256:b0113cedc2c899c6b9902513dba936c9a63745f827e2127e81686595fa8bf072
blob eligible for deletion: sha256:d105c5fc1045fbedba42cb5b7396053f07e97661affa8dabebcc2cd646deaaf0
blob eligible for deletion: sha256:2a0ecd252c2d3303818e2cac6e6baf335fa0d7eb5345fcd95f78a2c2f1289eb6
INFO[0000] deleting blobs                                count=6 go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea
INFO[0000] blobs deleted                                 count=6 go.version=go1.13.6 instance.id=60050296-fbe4-4076-b3e6-2790b9349fea

After

...
myorg3/myproj3/registry
myorg3/myproj3/registry: marking manifest sha256:b1165286043f2745f45ea637873d61939bff6d9a59f76539d6228abf79f87774 
myorg3/myproj3/registry: marking blob sha256:f32a97de94e13d29835a19851acd6cbc7979d1d50f703725541e44bb89a1ce91
myorg3/myproj3/registry: marking blob sha256:c87736221ed0bcaa60b8e92a19bec2284899ef89226f2a07968677cf59e637a4
myorg3/myproj3/registry: marking blob sha256:1cc8e0bb44dfaefdc7f0d0ce35f7bcb5bd2b91467a0ad7501499e34de27e3ee4
myorg3/myproj3/registry: marking blob sha256:54d33bcb37f53c65d2678796a458525d291c18058ff65c137d0aea45849e3f14
myorg3/myproj3/registry: marking blob sha256:e8afc091c171595794b2c72071946d2e34c0ecbc00de8b5f8a80dda0f7dfc801
myorg3/myproj3/registry: marking blob sha256:b4541f6d3db6307e43bad1ca823a3221d4c2689bcae8bbd8a312371815e1d1bf

426 blobs marked, 6 blobs and 1 manifests eligible for deletion
INFO[0000] starting sweep stage                          go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3
INFO[0000] manifest eligible for deletion                digest=sha256:583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/repositories/myorg2/myproj1/memcached/_manifests/revisions/sha256/583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68/link"
INFO[0000] manifest tag reference eligible for deletion  go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/repositories/myorg2/myproj1/memcached/_manifests/tags/1.5.15-alpine/index/sha256/583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68/link" tag=1.5.15-alpine
INFO[0000] deleting manifests                            go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 manifests=1 tags=1 total=2
INFO[0000] manifests deleted                             count=2 duration=1.090256ms go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3
INFO[0000] blob eligible for deletion                    digest=sha256:2a0ecd252c2d3303818e2cac6e6baf335fa0d7eb5345fcd95f78a2c2f1289eb6 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/2a/2a0ecd252c2d3303818e2cac6e6baf335fa0d7eb5345fcd95f78a2c2f1289eb6/data"
INFO[0000] blob eligible for deletion                    digest=sha256:4f068b59d6a0b9e9502529a5786b94eaaabea8555694dbbd55e26c866f9b848d go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/4f/4f068b59d6a0b9e9502529a5786b94eaaabea8555694dbbd55e26c866f9b848d/data"
INFO[0000] blob eligible for deletion                    digest=sha256:583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/58/583f421299828f7c550ac2a42886bce104e726c3fb1105f90221a8a69d1e1d68/data"
INFO[0000] blob eligible for deletion                    digest=sha256:8235f906e6129607f6aade38ce3dbc31b38463c76048c3e8dd072bccd71f482b go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/82/8235f906e6129607f6aade38ce3dbc31b38463c76048c3e8dd072bccd71f482b/data"
INFO[0000] blob eligible for deletion                    digest=sha256:b0113cedc2c899c6b9902513dba936c9a63745f827e2127e81686595fa8bf072 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/b0/b0113cedc2c899c6b9902513dba936c9a63745f827e2127e81686595fa8bf072/data"
INFO[0000] blob eligible for deletion                    digest=sha256:d105c5fc1045fbedba42cb5b7396053f07e97661affa8dabebcc2cd646deaaf0 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3 path="/docker/registry/v2/blobs/sha256/d1/d105c5fc1045fbedba42cb5b7396053f07e97661affa8dabebcc2cd646deaaf0/data"
INFO[0000] deleting blobs                                count=6 go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3
INFO[0000] blobs deleted                                 count=6 duration=1.455641ms go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3
INFO[0000] sweep stage complete                          duration=2.606779ms go.version=go1.13.6 instance.id=8eb7d0f0-9288-45b9-95c4-8e93b2cbc0a3

Next Steps

  • Refactor the mark stage logs (up to X blobs marked, Y blobs and Z manifests eligible for deletion) for consistency.
  • Log the duration of each stage on the release/2.7-gitlab branch, to easily compare the before vs after when testing the S3 optimizations.
Edited by João Pereira

Merge request reports