[Bug]: High CPU utilization

[patrick-esentire]

zot version

v2.0.0

Describe the bug

zot is consuming one CPU core minimum. You can see this behavior with the example/config-minimal.json

The problem appears to be in the scheduler, there is a spin loop at line 261 in pkg/scheduler.go that appears to never hit the throttle condition, and instead loops infinitely against scheduler.getTask looking for tasks that don't (and won't) exist.

To test this theory, I added a 1ms sleep in the loop I mentioned above, and it reduced the CPU utilization down to approx 20 millicpu

diff --git a/pkg/scheduler/scheduler.go b/pkg/scheduler/scheduler.go
index 174559d..e21528b 100644
--- a/pkg/scheduler/scheduler.go
+++ b/pkg/scheduler/scheduler.go
@@ -282,6 +282,7 @@ func (scheduler *Scheduler) RunScheduler() {
 					// push tasks into worker pool until workerChan is full.
 					scheduler.workerChan <- task
 				}
+				time.Sleep(1 * time.Millisecond)
 			}
 		}
 	}()

To reproduce

1. make OS=darwin ARCH=arm64 binary
2. ./bin/zot-darwin-arm64 serve examples/config-minimal.json

Expected behavior

The expected behavior would be near-zero CPU utilization when there are no images and no work being done.

Screenshots

This is from a 30s cpu profile, showing the main utilization coming from the scheduler and scheduler.getTask

Additional context

Here is the log output, when running using the minimal config.

{"level":"info","params":{"distSpecVersion":"1.1.0-dev","GoVersion":"go1.20.9","Commit":"v2.0.0-1-g59f41ac-dirty","ReleaseTag":"v2.0.0","BinaryType":"-imagetrust-lint-metrics-mgmt-profile-scrub-search-sync-ui-userprefs","Storage":{"RootDirectory":"/tmp/zot","Dedupe":true,"RemoteCache":false,"GC":true,"Commit":false,"GCDelay":3600000000000,"GCInterval":3600000000000,"Retention":{"DryRun":false,"Delay":0,"Policies":null},"StorageDriver":null,"CacheDriver":null,"SubPaths":null},"HTTP":{"Address":"127.0.0.1","ExternalURL":"","Port":"8080","AllowOrigin":"","TLS":null,"Auth":{"FailDelay":0,"HTPasswd":{"Path":""},"LDAP":null,"Bearer":null,"OpenID":null,"APIKey":false},"AccessControl":null,"Realm":"","Ratelimit":null},"Log":{"Level":"debug","Output":"","Audit":""},"Extensions":null,"scheduler":null},"goroutine":1,"caller":"zotregistry.io/zot/pkg/api/controller.go:221","time":"2023-12-27T16:49:40.024082-06:00","message":"configuration settings"}
{"level":"info","cpus":8,"max. open files":61440,"goroutine":1,"caller":"zotregistry.io/zot/pkg/api/controller.go:90","time":"2023-12-27T16:49:40.024119-06:00","message":"runtime params"}
{"level":"warn","goroutine":1,"caller":"zotregistry.io/zot/pkg/debug/swagger/swagger_disabled.go:20","time":"2023-12-27T16:49:40.043161-06:00","message":"skipping enabling swagger because given zot binary doesn't include this feature, please build a binary that does so"}
{"level":"warn","goroutine":1,"caller":"zotregistry.io/zot/pkg/debug/gqlplayground/gqlplayground_disabled.go:17","time":"2023-12-27T16:49:40.043198-06:00","message":"skipping enabling graphql playground extension because given zot binary doesn't include this feature, please build a binary that does so"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_metrics.go:31","time":"2023-12-27T16:49:40.043265-06:00","message":"setting up metrics routes"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_search.go:79","time":"2023-12-27T16:49:40.043292-06:00","message":"skip enabling the search route as the config prerequisites are not met"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_image_trust.go:30","time":"2023-12-27T16:49:40.04333-06:00","message":"skip enabling the image trust routes as the config prerequisites are not met"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_mgmt.go:89","time":"2023-12-27T16:49:40.043344-06:00","message":"skip enabling the mgmt route as the config prerequisites are not met"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_userprefs.go:33","time":"2023-12-27T16:49:40.043369-06:00","message":"skip enabling the user preferences route as the config prerequisites are not met"}
{"level":"info","goroutine":1,"caller":"zotregistry.io/zot/pkg/extensions/extension_ui.go:64","time":"2023-12-27T16:49:40.043405-06:00","message":"skip enabling the ui route as the config prerequisites are not met"}
{"level":"info","component":"dedupe","goroutine":23,"caller":"zotregistry.io/zot/pkg/storage/common/common.go:991","time":"2023-12-27T16:49:40.043706-06:00","message":"no repositories found in storage, finished."}

[patrick-esentire]

It looks like the bug was introduced in #2085, when the <-throttle was moved out of the for loop, and placed into a conditional which we don't appear to hit.

https://github.com/project-zot/zot/pull/2085/files#diff-fb3d6b36d3cd727e1dd2353fb86c0aee0bfaae1c900e0f005ab913620021d551L272

[danielsand]

can confirm this also for amd64

[rchincha]

@patrick-esentire @danielsand yes, we are aware of this issue. Thanks for reporting it. We will get to this as soon as folks are back from holidays.

[rchincha]

Note that depending on configuration, zot has many background tasks - CVE scanning, scrub, sync, stats, etc which can keep it quite busy.