Create builder cost too much time

[zhoufenqin]

In our K8s cluster, we notice that create a builder and wait for it to be ready will cost around 12 mins on average. Not sure which step cost most of the time.

Env

• Kpack version: 0.7.2

Kpack-controller configuration

apiVersion: v1
kind: Pod
metadata:
  name: kpack-controller-6bf7bf576-mrd7z
  namespace: kpack
spec:
  containers:
  - env:
    - name: ENABLE_PRIORITY_CLASSES
      value: "false"
    - name: AZURE_CONTAINER_REGISTRY_CONFIG
      value: /etc/kubernetes/azure.json
    - name: CONFIG_LOGGING_NAME
      value: config-logging
    - name: CONFIG_OBSERVABILITY_NAME
      value: config-observability
    - name: METRICS_DOMAIN
      value: kpack.io
    - name: SYSTEM_NAMESPACE
      valueFrom:
        fieldRef:
          apiVersion: v1
          fieldPath: metadata.namespace
    - name: BUILD_INIT_IMAGE
      valueFrom:
        configMapKeyRef:
          key: image
          name: build-init-image
    - name: REBASE_IMAGE
      valueFrom:
        configMapKeyRef:
          key: image
          name: rebase-image
    - name: COMPLETION_IMAGE
      valueFrom:
        configMapKeyRef:
          key: image
          name: completion-image
    image: xx
    imagePullPolicy: IfNotPresent
    name: controller
    resources:
      limits:
        cpu: 100m
        memory: 500Mi
      requests:
        cpu: 20m
        memory: 100Mi
.....

Builder configuration

apiVersion: kpack.io/v1alpha2
kind: Builder
metadata:
  name: default.default.1
  namespace: build-service
spec:
  order:
  - group:
    - id: tanzu-buildpacks/java-azure
      optional: true
    - id: tanzu-buildpacks/dotnet-core
      optional: true
    - id: tanzu-buildpacks/go
      optional: true
    - id: tanzu-buildpacks/web-servers
      optional: true
    - id: tanzu-buildpacks/nodejs
      optional: true
    - id: tanzu-buildpacks/python
      optional: true
  serviceAccountName: sa-build-service
  stack:
    kind: ClusterStack
    name: base
  store:
    kind: ClusterStore
    name: default
  tag: xxx

The create timestamp shows creationTimestamp: "2023-02-22T02:56:57Z"

The lastTransitionTime shows lastTransitionTime: "2023-02-22T03:08:20Z"

The kpack log shows:

> k logs -f kpack-controller-6bf7bf576-mrd7z
W0222 02:56:50.921388       1 client_config.go:617] Neither --kubeconfig nor --master was specified.  Using the inClusterConfig.  This might not work.
{"level":"info","ts":"2023-02-22T02:56:51.051805898Z","logger":"controller","caller":"profiling/server.go:64","msg":"Profiling enabled: false","commit":"9343a26-dirty"}
{"level":"info","ts":"2023-02-22T02:56:51.866468594Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.866646097Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867314911Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"images.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867351612Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"images.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867373312Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"builds.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867400813Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"builds.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867423713Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867448113Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867469514Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"clusterbuilders.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867492414Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"clusterbuilders.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867511515Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"clusterstores.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867538615Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"clusterstores.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867636917Z","logger":"controller","caller":"controller/controller.go:486","msg":"Starting controller and workers","commit":"9343a26-dirty","knative.dev/kind":"sourceresolvers.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:51.867659118Z","logger":"controller","caller":"controller/controller.go:496","msg":"Started workers","commit":"9343a26-dirty","knative.dev/kind":"sourceresolvers.kpack.io"}
{"level":"info","ts":"2023-02-22T02:56:53.723701012Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"715c799f-e962-4e9f-a6ef-051d7693e837","knative.dev/key":"base-jammy","duration":1.85531358}
{"level":"info","ts":"2023-02-22T02:56:54.214623241Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"a1bdeeb1-4091-401d-a3fe-3702092272e3","knative.dev/key":"base","duration":2.347911542}
{"level":"info","ts":"2023-02-22T02:56:54.471309607Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstores.kpack.io","knative.dev/traceid":"c3b412a2-33f5-4295-9bab-a1b4e4dccc24","knative.dev/key":"default","duration":2.603732191}
{"level":"info","ts":"2023-02-22T02:56:55.114282849Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"af996754-4d30-47f1-bf38-1c74a225f408","knative.dev/key":"full-jammy","duration":1.390527036}
{"level":"info","ts":"2023-02-22T02:56:55.82432355Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"de241dd7-e4cc-45b8-93d9-7981ae561b55","knative.dev/key":"full","duration":1.609620907}
{"level":"info","ts":"2023-02-22T02:56:56.143376464Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"a7d4767c-761f-4cf9-9e24-236a32b1fbcd","knative.dev/key":"base-jammy","duration":1.029021713}
{"level":"info","ts":"2023-02-22T02:56:56.221778186Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"240de8c6-ed08-457a-b0c7-784c9747bfcb","knative.dev/key":"base","duration":0.397390935}
{"level":"info","ts":"2023-02-22T02:56:56.320247174Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"4476b4d5-b361-4602-94e0-53627aa0cc95","knative.dev/key":"full-jammy","duration":0.176805008}
{"level":"info","ts":"2023-02-22T02:56:56.519558106Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstacks.kpack.io","knative.dev/traceid":"72975a6d-8209-4360-a7c1-d0faed42e418","knative.dev/key":"full","duration":0.297705518}
{"level":"info","ts":"2023-02-22T02:56:56.72539479Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstores.kpack.io","knative.dev/traceid":"aef7fed9-83c9-4be7-b3e8-5ece7ed0d0ce","knative.dev/key":"default","duration":2.210942879}
{"level":"info","ts":"2023-02-22T03:08:20.233470823Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io","knative.dev/traceid":"6080c19b-f298-4fd9-91e8-75938fbd6229","knative.dev/key":"build-service/default.default.1","duration":683.0590809}
{"level":"info","ts":"2023-02-22T03:08:20.649788961Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io","knative.dev/traceid":"38c978cb-1afa-4ada-94bb-49f3b85488d0","knative.dev/key":"build-service/default.default.1","duration":0.415309616}

see these two lines {"level":"info","ts":"2023-02-22T02:56:56.72539479Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"clusterstores.kpack.io","knative.dev/traceid":"aef7fed9-83c9-4be7-b3e8-5ece7ed0d0ce","knative.dev/key":"default","duration":2.210942879}

{"level":"info","ts":"2023-02-22T03:08:20.233470823Z","logger":"controller","caller":"controller/controller.go:550","msg":"Reconcile succeeded","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io","knative.dev/traceid":"6080c19b-f298-4fd9-91e8-75938fbd6229","knative.dev/key":"build-service/default.default.1","duration":683.0590809}

I know if the builder image size is large, then it may cost longer time to upload the image, but it won't cost 10 mins.

Which part cost the longest time to reconcile the builder?

[smile37773]

The builder message shows 'could not find buildpack with id 'tanzu-buildpacks/java-azure''.

And the kpack-controller error logs:

{"level":"error","ts":"2023-02-27T02:03:21.507046469Z","logger":"controller","caller":"controller/controller.go:566","msg":"Reconcile error","commit":"9343a26-dirty","knative.dev/kind":"builders.kpack.io","knative.dev/traceid":"6bf87daa-0ae4-46d6-a7a5-611947c07f1a","knative.dev/key":"build-service/default.default.1","duration":2.632799627,"error":"could not find buildpack with id 'tanzu-buildpacks/java-azure'","errorVerbose":"could not find buildpack with id 'tanzu-buildpacks/java-azure'\ngithub.com/pivotal/kpack/pkg/cnb.(*StoreBuildpackRepository).findBuildpack\n\tgithub.com/pivotal/kpack/pkg/cnb/store_buildpack_repository.go:71\ngithub.com/pivotal/kpack/pkg/cnb.(*StoreBuildpackRepository).FindByIdAndVersion\n\tgithub.com/pivotal/kpack/pkg/cnb/store_buildpack_repository.go:23\ngithub.com/pivotal/kpack/pkg/cnb.(*RemoteBuilderCreator).CreateBuilder\n\tgithub.com/pivotal/kpack/pkg/cnb/create_builder.go:59\ngithub.com/pivotal/kpack/pkg/reconciler/builder.(*Reconciler).reconcileBuilder\n\tgithub.com/pivotal/kpack/pkg/reconciler/builder/builder.go:145\ngithub.com/pivotal/kpack/pkg/reconciler/builder.(*Reconciler).Reconcile\n\tgithub.com/pivotal/kpack/pkg/reconciler/builder/builder.go:97\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20220816153547-f78a00694307/controller/controller.go:542\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20220816153547-f78a00694307/controller/controller.go:491\nruntime.goexit\n\truntime/asm_amd64.s:1571","stacktrace":"knative.dev/pkg/controller.(*Impl).handleErr\n\tknative.dev/pkg@v0.0.0-20220816153547-f78a00694307/controller/controller.go:566\nknative.dev/pkg/controller.(*Impl).processNextWorkItem\n\tknative.dev/pkg@v0.0.0-20220816153547-f78a00694307/controller/controller.go:543\nknative.dev/pkg/controller.(*Impl).RunContext.func3\n\tknative.dev/pkg@v0.0.0-20220816153547-f78a00694307/controller/controller.go:491"}

[smile37773]

I have a founding that Tanzu Java Azure Buildpack takes much longer than other buildpacks, such as .NET Core Buildpack.

Java Azure Builder takes 6min49

.Net Core Builder takes 2min20

[tomkennedy513]

It looks like the long time to reconcile builders might be due to the buildpacks in the clusterstore being in a different registry than where the builder is being written to. This results in the kpack controller having to stream all those images to the registry during builder reconciliation. A mitigation for this is to relocate the buildpack images to the builder registry.

[smile37773]

@tomkennedy513 For our used case, it's difficult to relocate the buildpack images to the builder registry. And we used two registries all the time but it didn't take so much time to wait for the builder ready. Is that possible to shorten the time?

[metron2]

Why not delete your limit?

limits/cpu: 100m will make you wait a long time