From 5d2f1205f9e3208f3e6aa60604d75de64c2e175d Mon Sep 17 00:00:00 2001 From: Jesse Brown Date: Wed, 11 Sep 2024 09:47:38 -0500 Subject: [PATCH] Adjust exporter App Layer log output The 1/N app layer logs are emitted _after_ the layers have been added. This can sometimes be an expensive operation depending on the layer size and export target. When trying to understand performance during builds, this wording implies the previous log line before the app layers was responsible for the time between the log lines. Adjusting the wording will make it a bit clearer that the time between the two log lines includes both steps. Before: ```bash 03:50:00 Adding layer 'buildpacksio/lifecycle:launch.sbom' 03:51:00 Adding 5/5 app layer(s) ```` After: ```bash 03:50:00 Adding layer 'buildpacksio/lifecycle:launch.sbom' 03:51:00 Added 5/5 app layer(s) ```` If we are more interested in going the other direction, where we keep "Adding 1/N app layers" and emitting multiple times or something I'm happy to iterate. Signed-off-by: Jesse Brown --- phase/exporter.go | 8 +++++--- phase/exporter_test.go | 10 +++++----- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/phase/exporter.go b/phase/exporter.go index 4808e8572..759668149 100644 --- a/phase/exporter.go +++ b/phase/exporter.go @@ -446,6 +446,8 @@ func (e *Exporter) addLauncherLayers(opts ExportOptions, buildMD *files.BuildMet func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta *files.LayersMetadata) error { // creating app layers (slices + app dir) + e.Logger.Debugf("Adding app layers") + sliceLayers, err := e.LayerFactory.SliceLayers(opts.AppDir, slices) if err != nil { return errors.Wrap(err, "creating app layers") @@ -453,6 +455,7 @@ func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta var numberOfReusedLayers int for _, slice := range sliceLayers { + e.Logger.Debugf("Layer '%s' SHA: %s\n", slice.ID, slice.Digest) var err error found := false @@ -471,16 +474,15 @@ func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta if err != nil { return err } - e.Logger.Debugf("Layer '%s' SHA: %s\n", slice.ID, slice.Digest) meta.App = append(meta.App, files.LayerMetadata{SHA: slice.Digest}) } delta := len(sliceLayers) - numberOfReusedLayers if numberOfReusedLayers > 0 { - e.Logger.Infof("Reusing %d/%d app layer(s)\n", numberOfReusedLayers, len(sliceLayers)) + e.Logger.Infof("Reused %d/%d app layer(s)\n", numberOfReusedLayers, len(sliceLayers)) } if delta != 0 { - e.Logger.Infof("Adding %d/%d app layer(s)\n", delta, len(sliceLayers)) + e.Logger.Infof("Added %d/%d app layer(s)\n", delta, len(sliceLayers)) } return nil } diff --git a/phase/exporter_test.go b/phase/exporter_test.go index 96ee824d9..63267503e 100644 --- a/phase/exporter_test.go +++ b/phase/exporter_test.go @@ -227,8 +227,8 @@ func testExporter(t *testing.T, when spec.G, it spec.S) { _, err := exporter.Export(opts) h.AssertNil(t, err) h.AssertContains(t, fakeAppImage.ReusedLayers(), "slice-1-digest") - assertLogEntry(t, logHandler, "Reusing 1/3 app layer(s)") - assertLogEntry(t, logHandler, "Adding 2/3 app layer(s)") + assertLogEntry(t, logHandler, "Reused 1/3 app layer(s)") + assertLogEntry(t, logHandler, "Added 2/3 app layer(s)") }) }) @@ -248,7 +248,7 @@ func testExporter(t *testing.T, when spec.G, it spec.S) { h.AssertNil(t, err) assertHasLayer(t, fakeAppImage, "app") - assertLogEntry(t, logHandler, "Adding 1/1 app layer(s)") + assertLogEntry(t, logHandler, "Added 1/1 app layer(s)") }) it("creates config layer on Run image", func() { @@ -873,7 +873,7 @@ version = "4.5.6" it("exports slice layers", func() { _, err := exporter.Export(opts) h.AssertNil(t, err) - assertLogEntry(t, logHandler, "Adding 3/3 app layer(s)") + assertLogEntry(t, logHandler, "Added 3/3 app layer(s)") }) }) @@ -906,7 +906,7 @@ version = "4.5.6" h.AssertNil(t, err) assertHasLayer(t, fakeAppImage, "app") - assertLogEntry(t, logHandler, "Adding 1/1 app layer(s)") + assertLogEntry(t, logHandler, "Added 1/1 app layer(s)") }) it("creates config layer on Run image", func() {