{"id":"IL-0401","org":"Kubernetes project","date":"2019-05-30","docs":["https://github.com/kubernetes/test-infra/issues/12829"],"title":{"en":"Prow jobs on the k8s-prow-build GKE cluster failed and merges stalled as nodes hit IOPS throttling and kernel panics","ko":"Kubernetes 프로젝트의 Prow 빌드 클러스터 노드가 GCP 디스크 IOPS 스로틀링에 걸려 테스트가 이상하게 실패하고 PR 머지가 몇 시간 멈췄다"},"domain":["kubernetes","gcp"],"impact":{"scope":"Prow CI jobs failed, were aborted or did not upload artifacts; at peak 60 PRs were stuck in the merge queue and no PRs merged for many hours; the Kubernetes 1.15 code freeze slipped a day","users":"Kubernetes contributors whose PRs depended on Prow","region":"us-central1-f"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"Prow metrics were not recorded before the incident, which made it hard to understand, and alerting for these failures did not exist or did not work. After the cause was found and a fix devised, nothing happened for another two hours. The team counts it as luck that someone who recognised IOPS as the problem happened to be around to look.","ko":"사고 전에 Prow 지표가 기록되지 않아 무슨 일인지 파악하기 어려웠다. 이런 장애를 잡는 알림은 없거나 동작하지 않았다. 원인을 찾고 해결책을 정한 뒤에도 두 시간 동안 아무것도 하지 않았다. 사고로 1.15 code freeze 가 밀렸다. IOPS 가 문제라는 것을 알아본 사람이 마침 자리에 있었던 것은 운이었다."},"related":[],"sources":[{"url":"https://github.com/kubernetes/test-infra/blob/master/docs/post-mortems/2019-05-30.md","kind":"github","archived":null}],"summary":{"en":"Prow runs Kubernetes project test jobs in a 100-node GKE cluster, k8s-prow-build, whose nodes had eight CPUs, 52 GB of RAM and 250 GB disks. On GCP, IOPS are limited in proportion to disk size, which gave 187.5 IOPS per instance. Most nodes barely touched the disk, but nodes running some workloads spiked to large multiples of that, and test load had grown over time. Ahead of the 1.15 code freeze a spike in usage hit hard throttling, and I/O became so slow that pods failed, kubelets crashed and nodes had kernel panics. Only a minority of nodes were affected at any time, but a job needs many pods to complete before a PR can merge, so merging nearly stopped for at least seven hours and the code freeze slipped a day.\n\nThe problem was reported on Slack at 13:26. At 14:11 the team found many problems with the nodes and test pods, and at 14:43 an engineer brought in from the node team identified severe I/O throttling as the root cause. The oncaller was told how to add capacity and got additional disk quota by 15:14, but capacity was not increased until 17:10, when 55 nodes with 500 GB disks were brought up, within the quota headroom. From 17:41 the remaining capacity was migrated gradually from the 250 GB node pool to the 500 GB pool by draining old nodes; the migration finished at 23:55 and Prow was merging at its usual rate again by 07:00. A global `max_concurrency` for plank was suggested as another way to throttle job load but was held back while the new nodes took effect. Because of an unrelated failure, most prow/tide monitoring for the week before the incident is lost, so when the cluster first became faulty is not known.","ko":"Prow 잡은 노드 100개짜리 k8s-prow-build 클러스터에서 돈다. 노드마다 CPU 8개, RAM 52 GB, 디스크 250 GB 다. GCP 는 디스크 크기에 비례해 IOPS 를 제한하므로 250 GB 디스크는 인스턴스당 187.5 IOPS 였다. 대부분의 노드는 디스크를 거의 쓰지 않았지만, 어떤 작업을 받은 노드는 디스크 사용량이 그 몇 배까지 치솟았다. 테스트 부하는 시간이 지나며 늘었고, Kubernetes 1.15 code freeze 를 앞두고 사용량이 뛰었다. 그러자 I/O 작업이 너무 오래 걸려 노드에서 파드 실패, kubelet 크래시, 커널 패닉이 났고, 테스트 코드도 이상하게 동작했다. 한 번에 영향을 받은 노드는 소수였다. 그러나 잡 하나가 머지되려면 많은 파드가 성공해야 해서 머지가 사실상 멈췄다.\n\n13:26 의 신고 뒤 14:11 에 노드와 테스트 파드에 문제가 많다는 것을 확인했고, 14:43 에 원인이 심한 I/O 스로틀링이라는 것을 찾았다. 15:02 에 온콜 담당자가 용량을 늘리는 방법을 안내받고 디스크 quota 를 요청해 15:14 에 받았다. 그러나 그 뒤 두 시간 동안 아무것도 하지 않았다. 17:10 에 용량이 늘지 않은 것을 알고 500 GB 디스크 노드 55개를 띄웠고, 17:41 부터 노드를 500GB 노드 풀로 차례로 옮겨 23:55 에 모든 노드가 500 GB 디스크를 쓰게 됐다. 다음 날 07:00 에 Prow 는 평소 속도로 머지했다. 문제는 적어도 7시간 이어졌고, 정점에 PR 60개가 머지 큐에 걸렸으며, 1.15 code freeze 는 하루 밀렸다. 관련 없는 모니터링 장애로 사고 전 한 주의 prow/tide 모니터링 데이터 대부분이 영구히 사라졌다. 그래서 클러스터가 언제부터 망가졌는지 알기 어려웠다."},"trigger":{"en":"A spike in test load before the Kubernetes 1.15 code freeze pushed disk I/O on the build nodes far beyond the IOPS that GCP allows for 250 GB disks.","ko":"Kubernetes 1.15 code freeze 를 앞두고 테스트 사용량이 치솟아, k8s-prow-build 클러스터 노드의 디스크 I/O 가 GCP 의 스로틀링 한도에 걸렸다."},"severity":"unknown","symptoms":["node-not-ready","node-kernel-panic","pod-stuck-terminating","throughput-degraded"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"incident","detection":{"en":"Several users reported jobs that GitHub showed as failed but Deck showed as still running, and the first report came on Slack at 13:26. Alerting for these failures did not exist or did not work.","ko":"여러 사용자가 GitHub 에는 실패로 올라왔지만 잡 상태로는 아직 실행 중인 잡이 있다고 신고했다. 첫 신고는 13:26 에 Slack 으로 들어왔다. 이런 장애를 잡는 알림은 없거나 동작하지 않았다."},"components":["block-storage","node-disk","kubelet","ci-system"],"root_cause":"capacity","remediation":[{"text":{"en":"Requested and received additional disk quota","ko":"디스크 quota 를 더 요청해 15:14 에 받았다."}},{"text":{"en":"Brought up 55 nodes with 500 GB disks in a new node pool","ko":"17:10 에 500 GB 디스크 노드 55개를 띄웠다."}},{"text":{"en":"Migrated all nodes from the 250 GB disk pool to the 500 GB disk pool by draining old nodes, finishing at 23:55","ko":"23:55 에 새 노드 풀로 옮기는 일을 마쳐 모든 노드가 500 GB 디스크를 쓰게 됐다."}}],"action_items":[{"text":{"en":"Create or fix monitoring so the oncall is paged when tide stops doing things","ko":"tide 가 일을 멈추면 온콜 담당자가 호출을 받도록 모니터링을 만들거나 고친다. 이 일은 이슈 #12829 에서 다룬다."}},{"text":{"en":"Set a process and guidelines for adding new members to the oncall rotation, with preparation and extra support","ko":"온콜 순번에 새 사람을 넣는 절차와 지침을 만들어, 새 사람이 준비나 추가 지원 없이 혼자 맡겨지지 않게 한다."}}],"contributing":["monitoring-blind-spot","early-signal-ignored"],"recurrence_of":null,"symptoms_text":{"en":"On 30 May 2019, in the run-up to the Kubernetes 1.15 code freeze, Prow test jobs in the k8s-prow-build cluster failed in surprising ways or were aborted partway through. Jobs were reported to GitHub as failed while Deck still showed them as running, because pods exited without uploading `finished.json`, the file most Prow tooling uses to tell a job's state.\n\nOne terminated job pod showed `State: Terminated`, `Exit Code: 0`, and `Started` and `Finished` both as `Mon, 01 Jan 0001 00:00:00 +0000`. Artifacts were often not uploaded, so Spyglass and Testgrid could not see that jobs had finished, and spurious Testgrid flake alerts fired. Pods and nodes were in odd states: pods were being evicted by something the team did not control, pods were not being killed, something had tried to kill one job pod 2,420 times over four days, pods sat in `PodInitializing` for half an hour, and kubelets were in reboot loops.\n\nNodes in the containerd pool went `NotReady` (for example `gke-prow-containerd-pool-99179761-02q6   NotReady   <none>   14d     v1.13.5-gke.10`), and the set of NotReady nodes kept changing. The team first suspected kubelet to CRI RPC problems and a deadlock when deleting pods, and then found kernel panics. The disks' estimated limits were 187.50 read and 375.00 write sustained random IOPS and 30 MB/s throughput, while throttled nodes were reaching 80MB/s and more than 450 IOPS; the throttled disk operations graph showed the problem had grown much worse over the previous day or two.\n\nMerging slowed to a stop. At peak 60 PRs were stuck in the merge queue, the last merge into kubernetes/kubernetes was 5 hours old by 16:05, and no PRs merged for many hours. Tide itself was working, but CI was so red that the queue drained slowly. In the GKE chat the problem was described as long-running and previously written off as COS / containerd issues.","ko":"2019년 5월 30일 13:26 PDT 에 Slack 으로 Prow 가 이상하다는 신고가 들어왔다. GitHub 에는 잡이 실패했다고 올라왔는데 Deck 에서는 같은 잡이 아직 실행 중으로 보였다. 많은 테스트가 뜻밖의 방식으로 실패하거나 실행 도중 뚜렷한 이유 없이 중단됐다.\n\n파드가 finished.json 을 올리지 못하고 끝나 아티팩트가 자주 올라가지 않았다. 도구 대부분이 이 파일로 잡 상태를 판단하므로 Spyglass 와 Testgrid 는 잡이 끝난 것을 알지 못했다. 업로드가 안 된 잡 때문에 Testgrid 가 잘못된 flake 알림을 보냈다. 한 파드는 State: Terminated, Exit Code: 0 이면서 Started 와 Finished 가 모두 Mon, 01 Jan 0001 00:00:00 +0000 으로 찍혀 있었다.\n\ncontainerd 노드 풀의 노드가 NotReady 였고, NotReady 인 노드는 계속 바뀌었다. gke-prow-containerd-pool-99179761-02q6, gke-prow-containerd-pool-99179761-313j, gke-prow-containerd-pool-99179761-4377, gke-prow-containerd-pool-99179761-t05g, gke-prow-containerd-pool-99179761-s4k7 이 NotReady 목록에 올랐고, 버전은 모두 v1.13.5-gke.10 이었다.\n\n노드에서는 커널 패닉이 났고 kubelet 은 재부팅을 되풀이했다. 파드는 제대로 죽지 않았고, 팀이 하지 않은 무언가가 파드를 evict 하고 있었다. 30분째 PodInitializing 에 머문 파드도 있었고, 나흘 동안 2,420번이나 kill 시도를 받은 잡 파드도 있었다.\n\n13:50 에 온콜 담당자는 큰 이상 신호를 찾지 못했다. 신고된 잡은 너무 오래돼 쓸 만한 정보를 얻을 수 없었다. 온콜 담당자는 완료 상태를 Prow 에 올리는 잡의 일시적인 문제로 봤다. 14:17 무렵에는 kubelet 과 CRI 사이 RPC 문제와 파드 삭제 중의 교착을 의심했다. 전에는 이 증상을 COS 나 containerd 문제로 보고 넘겼다.\n\n14:43 에 원인이 심한 I/O 스로틀링으로 밝혀졌다. 250 GB 디스크의 Sustained random IOPS limit 은 읽기 187.50, 쓰기 375.00 이고, Sustained throughput limit 은 30.00 MB/s 였다. 스로틀링될 때 실제 사용량은 80MB/s 와 450 IOPS 이상이었다. 스로틀링된 디스크 작업 그래프는 최근 하루 이틀 사이 크게 나빠져 있었다.\n\n16:05 기준으로 마지막 머지는 5시간 전이었다. 정점에는 PR 60개가 머지 큐에 걸려 있었고, 몇 시간 동안 PR 이 하나도 머지되지 않았다. CI 가 계속 실패해 큐는 천천히 빠졌다."},"updated_at":"2026-11-14T12:34:05.247976Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0401","org_slug":"kubernetes-project"}