Jupyter notebooks spawning time

[zonca]

Prompted by #46, let's debug what takes so long in starting up a session:

here is the kubernetes log

Events:
  Type    Reason                  Age    From                     Message
  ----    ------                  ----   ----                     -------
  Normal  Scheduled               2m41s  jhub-user-scheduler      Successfully assigned jhub/jupyter-zonca to zonca
-k8s-node-nf-1
  Normal  SuccessfulAttachVolume  2m8s   attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-a4d
0d8fb-46b4-4dbc-b5cb-3bad7ced6280"
  Normal  Pulled                  79s    kubelet                  Container image "jupyterhub/k8s-network-tools:0.9
.0" already present on machine
  Normal  Created                 78s    kubelet                  Created container block-cloud-metadata
  Normal  Started                 78s    kubelet                  Started container block-cloud-metadata
  Normal  Pulled                  75s    kubelet                  Container image "zonca/docker-jupyter-cdms-light:
2020.07.07" already present on machine
  Normal  Created                 75s    kubelet                  Created container notebook
  Normal  Started                 74s    kubelet                  Started container notebook

• startup took about 1 min and 30 sec @pibion do you often see startup times way longer?
• it takes ~30 sec to mount the user volume
• however there is another minute after that, but don't know what is driving that

[zonca]

I thought it was the mounting of the NFS volume, if I temporarily disable the NFS/CVMFS volume I get:

Events:
  Type    Reason                  Age   From                     Message
  ----    ------                  ----  ----                     -------
  Normal  Scheduled               84s   jhub-user-scheduler      Successfully assigned jhub/jupyter-zonca to zonca-k8s-node-nf-1
  Normal  SuccessfulAttachVolume  49s   attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-a4d0d8fb-46b4-4dbc-b5cb-3bad7ced6280"
  Normal  Pulled                  11s   kubelet                  Container image "jupyterhub/k8s-network-tools:0.9.0" already present on machine
  Normal  Created                 10s   kubelet                  Created container block-cloud-metadata
  Normal  Started                 10s   kubelet                  Started container block-cloud-metadata
  Normal  Pulled                  9s    kubelet                  Container image "zonca/docker-jupyter-cdms-light:2020.07.07" already present on machine
  Normal  Created                 9s    kubelet                  Created container notebook
  Normal  Started                 9s    kubelet                  Started container notebook

so it is still 40 seconds after mounting the volume

[zonca]

Starting a container outside of JupyterHub with the same image and also mounting the NFS volume, it starts very quickly:

Standalone container with NFS volume

Events:
  Type    Reason     Age   From               Message
  ----    ------     ----  ----               -------
  Normal  Scheduled  13s   default-scheduler  Successfully assigned default/test-nfs-mount to zonca-k8s-node-nf-1
  Normal  Pulled     12s   kubelet            Container image "zonca/docker-jupyter-cdms-light:2020.07.07" already 
present on machine
  Normal  Created    11s   kubelet            Created container app
  Normal  Started    11s   kubelet            Started container app

definitely is not the image and not the NFS volume

[zonca]

Standalone container with NFS volume and Openstack volume

Events:
  Type    Reason     Age   From               Message
  ----    ------     ----  ----               -------
  Normal  Scheduled  84s   default-scheduler  Successfully assigned jhub/test-nfs-mount to zonca-k8s-node-nf-1
  Normal  Pulled     23s   kubelet            Container image "zonca/docker-jupyter-cdms-light:2020.07.07" already 
present on machine
  Normal  Created    23s   kubelet            Created container app
  Normal  Started    23s   kubelet            Started container app

this takes about a minute

If I do the attach operation directly in openstack, it only takes 3 seconds, so it is something in Kubernetes

[zonca]

it looks like with the current version of Kubernetes, startup improved significantly:

  Normal  Scheduled               2m46s  jhub-user-scheduler      Successfully assigned jhub/jupyter-zonca to kubejetstream-k8s-node-nf-1
  Normal  SuccessfulAttachVolume  2m42s  attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-a4d0d8fb-46b4-4dbc-b5cb-3bad7ced6280"
  Normal  Pulled                  2m23s  kubelet                  Container image "jupyterhub/k8s-network-tools:0.11.1" already present on machine
  Normal  Created                 2m23s  kubelet                  Created container block-cloud-metadata
  Normal  Started                 2m22s  kubelet                  Started container block-cloud-metadata
  Normal  Pulled                  2m21s  kubelet                  Container image "zonca/docker-jupyter-cdms-light:2020.11.25" already present on machine
  Normal  Created                 2m20s  kubelet                  Created container notebook
  Normal  Started                 2m20s  kubelet                  Started container notebook

I see just it took me only 26s instead of 90s it was taking before. @pibion please reopen if instead you see different timings.