Skip to content

chore: add logging to get timing info #400

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.

Sign up for GitHub

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

Jump to bottom
Merged
kzantow merged 1 commit into from
Apr 10, 2025
Merged

chore: add logging to get timing info #400

kzantow merged 1 commit into from
Apr 10, 2025

Conversation

@kzantow
Copy link
Contributor

@kzantow kzantow commented Apr 10, 2025 •
edited
Loading

This PR adds some timing info during stereoscope image processing to better understand where time is being spent: downloading, saving, indexing, etc..

I've tried to make the logging levels appropriately noisy. In other words, info has some approximation of these messages added:

[0000]  INFO docker pulling image image=golang:latest
[0000]  INFO docker pulled image image=golang:latest time=11.192994ms
[0013]  INFO docker saved image image=golang:latest path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-67844120/docker-daemon-image-2765683229/image.tar time=13.219155363s
[0017]  INFO completed image read digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac mediaType=application/vnd.docker.distribution.manifest.v2+json tags=[golang:latest] time=3.961071492s

Debug:

[0000]  INFO docker pulling image image=golang:latest
[0000]  INFO docker pulled image image=golang:latest time=8.318835ms
[0012]  INFO docker saved image image=golang:latest path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-651095740/docker-daemon-image-2341072489/image.tar time=12.185550926s
[0012] DEBUG got uncompressed image tarball image=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-651095740/docker-daemon-image-2341072489/image.tar time=1.945874ms
[0012] DEBUG reading image digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac mediaType=application/vnd.docker.distribution.manifest.v2+json tags=[golang:latest]
[0016]  INFO completed image read digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac mediaType=application/vnd.docker.distribution.manifest.v2+json tags=[golang:latest] time=4.111925849s

Trace:

[0000]  INFO docker pulling image image=golang:latest
[0000]  INFO docker pulled image image=golang:latest time=11.332431ms
[0000] TRACE docker validated image image=golang:latest time=2.731703ms
[0012]  INFO docker saved image image=golang:latest path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-daemon-image-357755956/image.tar time=12.054025775s
[0012] DEBUG got uncompressed image tarball image=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-daemon-image-357755956/image.tar time=756.562µs
[0012] DEBUG reading image digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac mediaType=application/vnd.docker.distribution.manifest.v2+json tags=[golang:latest]
[0012] TRACE reading uncompressed image layer digest=sha256:f7f2b929d8a55112a2db1bc16fb8731045c9572b84d6dfbbdbd5dc6dd2bd9fe4 index=0 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip
[0012] TRACE start uncompressed layer cache index=0 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:f7f2b929d8a55112a2db1bc16fb8731045c9572b84d6dfbbdbd5dc6dd2bd9fe4
[0012] TRACE completed uncompressed layer cache index=0 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:f7f2b929d8a55112a2db1bc16fb8731045c9572b84d6dfbbdbd5dc6dd2bd9fe4 time=185.777462ms
[0012] TRACE completed indexing image layer digest=sha256:f7f2b929d8a55112a2db1bc16fb8731045c9572b84d6dfbbdbd5dc6dd2bd9fe4 index=0 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip time=405.760535ms
[0012] TRACE completed layer search context index=0 time=2.334897ms
[0012] TRACE reading uncompressed image layer digest=sha256:7f0053786e6e2411ce577e795ef6c278601de3faa0817c071801b11a3f83fd0d index=1 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip
[0012] TRACE start uncompressed layer cache index=1 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:7f0053786e6e2411ce577e795ef6c278601de3faa0817c071801b11a3f83fd0d
[0012] TRACE completed uncompressed layer cache index=1 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:7f0053786e6e2411ce577e795ef6c278601de3faa0817c071801b11a3f83fd0d time=55.98348ms
[0012] TRACE completed indexing image layer digest=sha256:7f0053786e6e2411ce577e795ef6c278601de3faa0817c071801b11a3f83fd0d index=1 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip time=121.487649ms
[0012] TRACE completed layer search context index=1 time=1.39849ms
[0012] TRACE reading uncompressed image layer digest=sha256:b2bcbd8ebb2be9869ca3198b4c521f18b612b4287ee4b705678d7b85383b71af index=2 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip
...
[0015] TRACE reading uncompressed image layer digest=sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef index=6 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip
[0015] TRACE start uncompressed layer cache index=6 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef
[0015] TRACE completed uncompressed layer cache index=6 path=/var/folders/jc/fxkytj5j5sj8rwxsv7k5x1b80000gn/T/stereoscope-191422219/docker-tarball-image-2061478161/sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef time=282.378µs
[0015] TRACE completed indexing image layer digest=sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef index=6 mediaType=application/vnd.docker.image.rootfs.diff.tar.gzip time=55.364µs
[0015] TRACE completed layer search context index=6 time=1.337937ms
[0015] TRACE completed image layer copy digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac time=3.573271382s
[0016] TRACE completed image squash digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac time=367.027552ms
[0016] TRACE completed image search context digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac time=2.583331ms
[0016]  INFO completed image read digest=sha256:ec829c45babe26254b2b8aa569b45d60af9f2a8c3cc8d94f3240a4ca34ecfeac mediaType=application/vnd.docker.distribution.manifest.v2+json tags=[golang:latest] time=3.943010198s

@github-actions
Copy link

github-actions bot commented Apr 10, 2025

Benchmark Test Results

Benchmark results from the latest changes vs base branch 
make .tool/task
make[1]: Entering directory '/home/runner/work/stereoscope/stereoscope'
make[1]: Leaving directory '/home/runner/work/stereoscope/stereoscope'
.tool/task show-benchstat
?   	github.com/anchore/stereoscope	[no test files]
?   	github.com/anchore/stereoscope/examples	[no test files]
PASS
ok  	github.com/anchore/stereoscope/internal	0.003s
?   	github.com/anchore/stereoscope/internal/bus	[no test files]
PASS
ok  	github.com/anchore/stereoscope/internal/containerd	0.007s
PASS
ok  	github.com/anchore/stereoscope/internal/docker	0.004s
?   	github.com/anchore/stereoscope/internal/log	[no test files]
PASS
ok  	github.com/anchore/stereoscope/internal/podman	0.005s
?   	github.com/anchore/stereoscope/pkg/event	[no test files]
?   	github.com/anchore/stereoscope/pkg/event/parsers	[no test files]
goos: linux
goarch: amd64
pkg: github.com/anchore/stereoscope/pkg/file
cpu: AMD EPYC 7763 64-Core Processor                
BenchmarkTarIndex-4   	   34904	     34349 ns/op	    5700 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   34746	     34344 ns/op	    5700 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   34786	     35070 ns/op	    5700 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   34742	     34231 ns/op	    5699 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   34968	     34444 ns/op	    5699 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   31849	     34391 ns/op	    5701 B/op	      93 allocs/op
BenchmarkTarIndex-4   	   34526	     34926 ns/op	    5701 B/op	      93 allocs/op
PASS
ok  	github.com/anchore/stereoscope/pkg/file	10.799s
PASS
ok  	github.com/anchore/stereoscope/pkg/filetree	0.004s
?   	github.com/anchore/stereoscope/pkg/filetree/filenode	[no test files]
PASS
ok  	github.com/anchore/stereoscope/pkg/image	0.005s
PASS
ok  	github.com/anchore/stereoscope/pkg/image/containerd	0.008s
PASS
ok  	github.com/anchore/stereoscope/pkg/image/docker	0.005s
PASS
ok  	github.com/anchore/stereoscope/pkg/image/oci	0.005s
PASS
ok  	github.com/anchore/stereoscope/pkg/image/oci/credhelpers	0.005s
?   	github.com/anchore/stereoscope/pkg/image/podman	[no test files]
PASS
ok  	github.com/anchore/stereoscope/pkg/image/sif	0.004s
?   	github.com/anchore/stereoscope/pkg/imagetest	[no test files]
PASS
ok  	github.com/anchore/stereoscope/pkg/tree	0.003s
PASS
ok  	github.com/anchore/stereoscope/pkg/tree/node	0.003s
goos: linux
goarch: amd64
pkg: github.com/anchore/stereoscope/test/integration
cpu: AMD EPYC 7763 64-Core Processor                
BenchmarkSimpleImage_GetImage/docker-archive-4 	    1045	   1164459 ns/op	  279502 B/op	    2432 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	    1015	   1166997 ns/op	  279236 B/op	    2432 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	     870	   1281140 ns/op	  279197 B/op	    2432 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	     978	   1197457 ns/op	  279154 B/op	    2432 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	    1014	   1260823 ns/op	  278835 B/op	    2431 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	    1018	   1168844 ns/op	  278796 B/op	    2431 allocs/op
BenchmarkSimpleImage_GetImage/docker-archive-4 	    1029	   1206507 ns/op	  278732 B/op	    2431 allocs/op
--- FAIL: BenchmarkSimpleImage_GetImage/podman
    fixture_image_simple_test.go:175: could not get fixture image: unable to detect input for 'stereoscope-fixture-image-simple:04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7', errs: podman not available: no host address
#0 building with "default" instance using docker driver

#1 [internal] load build definition from Dockerfile
#1 transferring dockerfile: 345B done
#1 DONE 0.0s

#2 [internal] load .dockerignore
#2 transferring context: 2B done
#2 DONE 0.0s

#3 [internal] load build context
#3 transferring context: 209B done
#3 DONE 0.0s

#4 [1/3] ADD file-1.txt /somefile-1.txt
#4 CACHED

#5 [2/3] ADD file-2.txt /somefile-2.txt
#5 CACHED

#6 [3/3] ADD target /
#6 CACHED

#7 exporting to image
#7 exporting layers done
#7 writing image sha256:4a6c5176bccccd1f568ba0df554f5175173437f1154a5915399c01bf0165cf1d done
#7 naming to docker.io/library/stereoscope-fixture-image-simple:04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7 done
#7 naming to docker.io/library/stereoscope-fixture-image-simple:latest done
#7 DONE 0.0s
ctr: failed to dial "/run/containerd/containerd.sock": connection error: desc = "transport: error while dialing: dial unix /run/containerd/containerd.sock: connect: permission denied"
--- FAIL: BenchmarkSimpleImage_GetImage
    image_fixtures.go:193: using existing image tar: 'test-fixtures/cache/stereoscope-fixture-image-simple-04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7.tar' (size: 22528, modified: 2025-04-10 14:57:28.060663315 +0000 UTC, mode: -rw-r--r--)
    image_fixtures.go:241: Build docker image: name="stereoscope-fixture-image-simple" tag="04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7"
    image_fixtures.go:291: saveImage running: docker image save stereoscope-fixture-image-simple:04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7
    image_fixtures.go:286: 
        	Error Trace:	/home/runner/work/stereoscope/stereoscope/pkg/imagetest/image_fixtures.go:286
        	            				/home/runner/work/stereoscope/stereoscope/pkg/imagetest/image_fixtures.go:162
        	            				/home/runner/work/stereoscope/stereoscope/pkg/imagetest/image_fixtures.go:152
        	            				/home/runner/work/stereoscope/stereoscope/pkg/imagetest/image_fixtures.go:33
        	            				/home/runner/work/stereoscope/stereoscope/test/integration/fixture_image_simple_test.go:163
        	Error:      	Received unexpected error:
        	            	exit status 1
        	Test:       	BenchmarkSimpleImage_GetImage
        	Messages:   	could not import docker image to containerd (shell out)
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   59490	     20373 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   59274	     20286 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   58906	     20240 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   58724	     20243 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   59316	     20476 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   59218	     20255 ns/op	    2712 B/op	      21 allocs/op
BenchmarkSimpleImage_FetchSquashedContents/docker-archive-4         	   59422	     20329 ns/op	    2712 B/op	      21 allocs/op
--- FAIL: BenchmarkSimpleImage_FetchSquashedContents
    image_fixtures.go:193: using existing image tar: 'test-fixtures/cache/stereoscope-fixture-image-simple-04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7.tar' (size: 22528, modified: 2025-04-10 14:57:28.060663315 +0000 UTC, mode: -rw-r--r--)
    image_fixtures.go:75: error getting fixture image: 'podman' 'image-simple' with request 'podman:stereoscope-fixture-image-simple:04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7': unable to detect input for 'stereoscope-fixture-image-simple:04e16e44161c8888a1a963720fd0443cbf7eef8101434c431de8725cd98cc9f7', errs: podman not available: no host address
FAIL
exit status 1
FAIL	github.com/anchore/stereoscope/test/integration	19.969s
?   	github.com/anchore/stereoscope/test/integration/test-fixtures/registry	[no test files]
FAIL
goos: linux
goarch: amd64
pkg: github.com/anchore/stereoscope/pkg/file
cpu: AMD EPYC 7763 64-Core Processor                
ctr: 
           │ .tmp/benchmark-4f35d4e.txt │
           │           sec/op           │
TarIndex-4                  34.39µ ± 2%

           │ .tmp/benchmark-4f35d4e.txt │
           │            B/op            │
TarIndex-4                 5.566Ki ± 0%

           │ .tmp/benchmark-4f35d4e.txt │
           │         allocs/op          │
TarIndex-4                   93.00 ± 0%

pkg: github.com/anchore/stereoscope/test/integration
                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │           sec/op           │
SimpleImage_GetImage/docker-archive-4                  1.197m ± 7%

                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │            B/op            │
SimpleImage_GetImage/docker-archive-4                 272.6Ki ± 0%

                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │         allocs/op          │
SimpleImage_GetImage/docker-archive-4                  2.432k ± 0%

ctr: failed to dial "/run/containerd/containerd.sock": connection error: desc = "transport: error while dialing: dial unix /run/containerd/containerd.sock: connect: permission denied"
                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │           sec/op           │
SimpleImage_FetchSquashedContents/docker-archive-4                  20.29µ ± 1%

                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │            B/op            │
SimpleImage_FetchSquashedContents/docker-archive-4                 2.648Ki ± 0%

                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │         allocs/op          │
SimpleImage_FetchSquashedContents/docker-archive-4                   21.00 ± 0%
goos: linux
goarch: amd64
pkg: github.com/anchore/stereoscope/pkg/file
cpu: AMD EPYC 7763 64-Core Processor                
ctr: 
           │ .tmp/benchmark-4f35d4e.txt │
           │           sec/op           │
TarIndex-4                  34.39µ ± 2%

           │ .tmp/benchmark-4f35d4e.txt │
           │            B/op            │
TarIndex-4                 5.566Ki ± 0%

           │ .tmp/benchmark-4f35d4e.txt │
           │         allocs/op          │
TarIndex-4                   93.00 ± 0%

pkg: github.com/anchore/stereoscope/test/integration
                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │           sec/op           │
SimpleImage_GetImage/docker-archive-4                  1.197m ± 7%

                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │            B/op            │
SimpleImage_GetImage/docker-archive-4                 272.6Ki ± 0%

                                      │ .tmp/benchmark-4f35d4e.txt │
                                      │         allocs/op          │
SimpleImage_GetImage/docker-archive-4                  2.432k ± 0%

ctr: failed to dial "/run/containerd/containerd.sock": connection error: desc = "transport: error while dialing: dial unix /run/containerd/containerd.sock: connect: permission denied"
                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │           sec/op           │
SimpleImage_FetchSquashedContents/docker-archive-4                  20.29µ ± 1%

                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │            B/op            │
SimpleImage_FetchSquashedContents/docker-archive-4                 2.648Ki ± 0%

                                                   │ .tmp/benchmark-4f35d4e.txt │
                                                   │         allocs/op          │
SimpleImage_FetchSquashedContents/docker-archive-4                   21.00 ± 0%

@kzantow kzantow merged commit 4941a51 into main Apr 10, 2025
7 checks passed
@kzantow kzantow deleted the chore/timing-log-info branch April 10, 2025 16:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@wagoodman wagoodman wagoodman approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@kzantow @wagoodman