Skip to content

Instantly share code, notes, and snippets.

@PatrickLang

PatrickLang/README.md

Last active February 8, 2019 00:51
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save PatrickLang/b49f85e91dcf990f92e90f30e245b330 to your computer and use it in GitHub Desktop.
Save PatrickLang/b49f85e91dcf990f92e90f30e245b330 to your computer and use it in GitHub Desktop.
Download ZIP
Investigating pod startup time
Raw
README.md

Investigations for kubernetes/kubernetes#72722

$ kubectl scale deploy iis-2019 --replicas=10
deployment.extensions/iis-2019 scaled
patrick@planglx1:~/aznet17+ssh$ kubectl get pod -o wide -w
NAME                        READY   STATUS              RESTARTS   AGE     IP             NODE         NOMINATED NODE
iis-2019-5d465d7bb9-4zkjm   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-7vlrm   2/2     Running             0          89s     10.240.0.109   2709k8s010   <none>
iis-2019-5d465d7bb9-cnw4f   2/2     Running             0          89s     10.240.0.116   2709k8s010   <none>
iis-2019-5d465d7bb9-hxjgp   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-njzb6   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-vt42r   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-wgp7s   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-wmq5w   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-x2mb4   2/2     Running             0          4m25s   10.240.0.119   2709k8s010   <none>
iis-2019-5d465d7bb9-xhq5h   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-njzb6   2/2   Running   0     102s   10.240.0.102   2709k8s010   <none>
iis-2019-5d465d7bb9-vt42r   2/2   Running   0     117s   10.240.0.107   2709k8s010   <none>
iis-2019-5d465d7bb9-hxjgp   2/2   Running   0     2m13s   10.240.0.100   2709k8s010   <none>
iis-2019-5d465d7bb9-wgp7s   2/2   Running   0     2m24s   10.240.0.105   2709k8s010   <none>
iis-2019-5d465d7bb9-4zkjm   2/2   Running   0     2m34s   10.240.0.98   2709k8s010   <none>
iis-2019-5d465d7bb9-wmq5w   2/2   Running   0     2m45s   10.240.0.111   2709k8s010   <none>
iis-2019-5d465d7bb9-xhq5h   2/2   Running   0     3m10s   10.240.0.126   2709k8s010   <none>

At this point, I'm asking why there's 100 seconds between these statuses:

iis-2019-5d465d7bb9-njzb6   0/2     ContainerCreating   0          2s      <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-njzb6   2/2   Running   0     102s   10.240.0.102   2709k8s010   <none>

$ kubectl describe pod iis-2019-5d465d7bb9-njzb6
Name:               iis-2019-5d465d7bb9-njzb6
Namespace:          default
Priority:           0
PriorityClassName:  <none>
Node:               2709k8s010/10.240.0.96
Start Time:         Thu, 07 Feb 2019 04:03:04 +0000
Labels:             app=iis-2019
                    pod-template-hash=5d465d7bb9
Annotations:        <none>
Status:             Running
IP:                 10.240.0.102
Controlled By:      ReplicaSet/iis-2019-5d465d7bb9
Containers:
  iis:
    Container ID:   docker://0478ebd98726e857d4e38ecc69ec5d7508a91aeacc596d200cebdae3af1686c3
    Image:          mcr.microsoft.com/windows/servercore/iis:windowsservercore-ltsc2019
    Image ID:       docker-pullable://mcr.microsoft.com/windows/servercore/iis@sha256:f1840a40dfeff9bca1f059a2f673e1d446cc0550f32701bcc3fbaeabd124a866
    Port:           80/TCP
    Host Port:      0/TCP
    State:          Running
      Started:      Thu, 07 Feb 2019 04:04:09 +0000
    Ready:          True
    Restart Count:  0
    Limits:
      cpu:     1
      memory:  800m
    Requests:
      cpu:        100m
      memory:     300m
    Environment:  <none>
    Mounts:
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-hhkqb (ro)
  windowswebserver:
    Container ID:  docker://01e8f79ab617fb81746ac8e8e8b9510e79eb9470dee3c0c44e1029745980851d
    Image:         mcr.microsoft.com/windows/servercore:1809
    Image ID:      docker-pullable://mcr.microsoft.com/windows/servercore@sha256:312e52776493d2789992f2231e6b9d17ac4303ceed2598d6ee2739061fb5cf1f
    Port:          <none>
    Host Port:     <none>
    Command:
      powershell.exe
      -command
      <#code used from https://gist.github.com/wagnerandrade/5424431#> ; $$listener = New-Object System.Net.HttpListener ; $$listener.Prefixes.Add('http://*:81/') ; $$listener.Start() ; $$callerCounts = @{} ; Write-Host('Listening at http://*:81/') ; while ($$listener.IsListening) { ;$$context = $$listener.GetContext() ;$$requestUrl = $$context.Request.Url ;$$clientIP = $$context.Request.RemoteEndPoint.Address ;$$response = $$context.Response ;Write-Host '' ;Write-Host('> {0}' -f $$requestUrl) ;  ;$$count = 1 ;$$k=$$callerCounts.Get_Item($$clientIP) ;if ($$k -ne $$null) { $$count += $$k } ;$$callerCounts.Set_Item($$clientIP, $$count) ;$$ip=(Get-NetAdapter | Get-NetIpAddress); $$header='<html><body><H1>Windows Container Web Server</H1>' ;$$callerCountsString='' ;$$callerCounts.Keys | % { $$callerCountsString+='<p>IP {0} callerCount {1} ' -f $$ip[1].IPAddress,$$callerCounts.Item($$_) } ;$$footer='</body></html>' ;$$content='{0}{1}{2}' -f $$header,$$callerCountsString,$$footer ;Write-Output $$content ;$$buffer = [System.Text.Encoding]::UTF8.GetBytes($$content) ;$$response.ContentLength64 = $$buffer.Length ;$$response.OutputStream.Write($$buffer, 0, $$buffer.Length) ;$$response.Close() ;$$responseStatus = $$response.StatusCode ;Write-Host('< {0}' -f $$responseStatus)  } ;
    State:          Running
      Started:      Thu, 07 Feb 2019 04:04:24 +0000
    Ready:          True
    Restart Count:  0
    Environment:    <none>
    Mounts:
      /var/run/secrets/kubernetes.io/serviceaccount from default-token-hhkqb (ro)
Conditions:
  Type              Status
  Initialized       True
  Ready             True
  ContainersReady   True
  PodScheduled      True
Volumes:
  default-token-hhkqb:
    Type:        Secret (a volume populated by a Secret)
    SecretName:  default-token-hhkqb
    Optional:    false
QoS Class:       Burstable
Node-Selectors:  beta.kubernetes.io/os=windows
Tolerations:     node.kubernetes.io/not-ready:NoExecute for 300s
                 node.kubernetes.io/unreachable:NoExecute for 300s
Events:
  Type    Reason     Age    From                 Message
  ----    ------     ----   ----                 -------
  Normal  Scheduled  4m8s   default-scheduler    Successfully assigned default/iis-2019-5d465d7bb9-njzb6 to 2709k8s010
  Normal  Pulled     3m11s  kubelet, 2709k8s010  Container image "mcr.microsoft.com/windows/servercore/iis:windowsservercore-ltsc2019" already present on machine
  Normal  Created    3m11s  kubelet, 2709k8s010  Created container
  Normal  Started    3m2s   kubelet, 2709k8s010  Started container
  Normal  Pulled     3m2s   kubelet, 2709k8s010  Container image "mcr.microsoft.com/windows/servercore:1809" already present on machine
  Normal  Created    3m2s   kubelet, 2709k8s010  Created container
  Normal  Started    2m48s  kubelet, 2709k8s010  Started container

I don't see any errors in kubelet.err.log

Another attempt - just scale up by 1. This completes in ~30 seconds

I0208 00:43:40.865411    1256 reconciler.go:207] operationExecutor.VerifyControllerAttachedVolume started for volume "default-token-hhkqb" (UniqueName: "kubernetes.io/secret/944e7b59-2b3a-11e9-831a-000d3a0689a8-default-token-hhkqb") pod "iis-2019-5d
465d7bb9-cmx4x" (UID: "944e7b59-2b3a-11e9-831a-000d3a0689a8")
E0208 00:43:43.188587    1256 docker_sandbox.go:697] ResolvConfPath is empty.
W0208 00:43:43.190575    1256 pod_container_deletor.go:75] Container "0351d2e383ff03f696ef4c77943a3c653d6fec88279e804000da75b54080ec11" not found in pod's containers
W0208 00:43:52.993913    1256 helpers.go:808] eviction manager: no observation found for eviction signal nodefs.inodesFree
I0208 00:43:54.382864    1256 fake_cpu_manager.go:40] [fake cpumanager] AddContainer (pod: iis-2019-5d465d7bb9-cmx4x, container: iis, container id: 0b033f30f55f77068958d735fddfb8be11e569fd3e473eefada47a7d35f27ab2)
I0208 00:43:57.102705    1256 fake_cpu_manager.go:40] [fake cpumanager] AddContainer (pod: iis-2019-5d465d7bb9-cmx4x, container: windowswebserver, container id: 4159677770bf4df2ff072801a0893cdc6ac605c09a9f97298d00367e1fd04d94)
W0208 00:44:47.894150    1256 helpers.go:808] eviction manager: no observation found for eviction signal nodefs.inodesFree

$ kubectl scale deploy iis-2019 --replicas=11^C
patrick@planglx1:~/aznet17+ssh$ kubectl get pod -o wide -w
NAME                        READY   STATUS              RESTARTS   AGE   IP             NODE         NOMINATED NODE
iis-2019-5d465d7bb9-4zkjm   2/2     Running             0          20h   10.240.0.98    2709k8s010   <none>
iis-2019-5d465d7bb9-7vlrm   2/2     Running             0          20h   10.240.0.109   2709k8s010   <none>
iis-2019-5d465d7bb9-cmx4x   0/2     ContainerCreating   0          10s   <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-cnw4f   2/2     Running             0          20h   10.240.0.116   2709k8s010   <none>
iis-2019-5d465d7bb9-hxjgp   2/2     Running             0          20h   10.240.0.100   2709k8s010   <none>
iis-2019-5d465d7bb9-njzb6   2/2     Running             0          20h   10.240.0.102   2709k8s010   <none>
iis-2019-5d465d7bb9-vt42r   2/2     Running             0          20h   10.240.0.107   2709k8s010   <none>
iis-2019-5d465d7bb9-wgp7s   2/2     Running             0          20h   10.240.0.105   2709k8s010   <none>
iis-2019-5d465d7bb9-wmq5w   2/2     Running             0          20h   10.240.0.111   2709k8s010   <none>
iis-2019-5d465d7bb9-x2mb4   2/2     Running             0          20h   10.240.0.119   2709k8s010   <none>
iis-2019-5d465d7bb9-xhq5h   2/2     Running             0          20h   10.240.0.126   2709k8s010   <none>
iis-2019-5d465d7bb9-cmx4x   2/2   Running   0     37s   10.240.0.121   2709k8s010   <none>

starting 2 simultaneous

$ kubectl scale deploy iis-2019 --replicas=3
deployment.extensions/iis-2019 scaled
patrick@planglx1:~/aznet17+ssh/b49f85e91dcf990f92e90f30e245b330$ kubectl get pod -o wide -w
NAME                        READY   STATUS              RESTARTS   AGE   IP             NODE         NOMINATED NODE
iis-2019-5d465d7bb9-tm2nb   0/2     ContainerCreating   0          2s    <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-vbqtd   0/2     ContainerCreating   0          2s    <none>         2709k8s010   <none>
iis-2019-5d465d7bb9-x2mb4   2/2     Running             0          20h   10.240.0.119   2709k8s010   <none>
iis-2019-5d465d7bb9-tm2nb   2/2   Running   0     38s   10.240.0.122   2709k8s010   <none>
iis-2019-5d465d7bb9-vbqtd   2/2   Running   0     48s   10.240.0.102   2709k8s010   <none>
Raw
iis-multi.yml
apiVersion: apps/v1
kind: Deployment
metadata:
name: iis-2019
labels:
app: iis-2019
spec:
replicas: 1
template:
metadata:
name: iis-2019
labels:
app: iis-2019
spec:
containers:
- name: iis
image: mcr.microsoft.com/windows/servercore/iis:windowsservercore-ltsc2019
resources:
limits:
cpu: 1
memory: 800m
requests:
cpu: .1
memory: 300m
ports:
- containerPort: 80
- name: windowswebserver
image: mcr.microsoft.com/windows/servercore:1809
command:
- powershell.exe
- -command
- "<#code used from https://gist.github.com/wagnerandrade/5424431#> ; $$listener = New-Object System.Net.HttpListener ; $$listener.Prefixes.Add('http://*:81/') ; $$listener.Start() ; $$callerCounts = @{} ; Write-Host('Listening at http://*:81/') ; while ($$listener.IsListening) { ;$$context = $$listener.GetContext() ;$$requestUrl = $$context.Request.Url ;$$clientIP = $$context.Request.RemoteEndPoint.Address ;$$response = $$context.Response ;Write-Host '' ;Write-Host('> {0}' -f $$requestUrl) ; ;$$count = 1 ;$$k=$$callerCounts.Get_Item($$clientIP) ;if ($$k -ne $$null) { $$count += $$k } ;$$callerCounts.Set_Item($$clientIP, $$count) ;$$ip=(Get-NetAdapter | Get-NetIpAddress); $$header='<html><body><H1>Windows Container Web Server</H1>' ;$$callerCountsString='' ;$$callerCounts.Keys | % { $$callerCountsString+='<p>IP {0} callerCount {1} ' -f $$ip[1].IPAddress,$$callerCounts.Item($$_) } ;$$footer='</body></html>' ;$$content='{0}{1}{2}' -f $$header,$$callerCountsString,$$footer ;Write-Output $$content ;$$buffer = [System.Text.Encoding]::UTF8.GetBytes($$content) ;$$response.ContentLength64 = $$buffer.Length ;$$response.OutputStream.Write($$buffer, 0, $$buffer.Length) ;$$response.Close() ;$$responseStatus = $$response.StatusCode ;Write-Host('< {0}' -f $$responseStatus) } ; "
nodeSelector:
"beta.kubernetes.io/os": windows
selector:
matchLabels:
app: iis-2019
---
apiVersion: v1
kind: Service
metadata:
name: iis
spec:
type: LoadBalancer
ports:
- protocol: TCP
port: 80
selector:
app: iis-2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment