Kubernetes 源码解读 - 由一次 debug 学到的

在最近公司办的第一次 Open L 活动中，我们分享了为什么我们要用 Kubernetes，其中吸引我们的一方面就是 autoscaling，它能够根据 CPU 等指标动态调整 pod 的个数，以此提高机器的利用率。

但最近却发现它并不能按预期正常地工作，deployment 的 Horizontal Pod Autoscaler(HPA) 显示的 CPU 并不能反应实际情况，所以也就不能正常地对 pod 的数量进行调整。查了 log 又 Google 一番后，我们并没有发现根本原因和解决办法，试了一些可能的方案，比如升级 docker，也没有解决，于是我们决定借助 k8s 的相关源码来弄清问题的根由，也方便之后再出现其他问题时能够更快地解决。

（本文基于 Kubernetes v1.4.6 e569a27d02 和 heapster v1.2.0 eea8c965）

先看一下 HPA 的工作原理：

HPA 会被 controller manager 启动，不断从 heapster 抓取所有 pod 的 metrics，计算出平均值，再控制 deployment 伸缩。我们的问题很明显出在计算平均值的那前半段。

HPA 启动和运行 #

Kubernetes 那么多代码，从哪看起呢？ 我们先查看了 controller manager 的 log，发现了关键的几行

W0429 12:42:11.182073       5 horizontal.go:105] Failed to reconcile neo-staging-web: failed to compute desired number of replicas based on CPU utilization for Deployment/backend/neo-staging-web: failed to get CPU utilization: failed to get CPU consumption and request: metrics obtained for 0/2 of pods (sample missing pod: backend/neo-staging-web-v201-dqxj5)

这个 log 是在 k8s/controller/podautoscaler/horizontal.go:105 被打印的，逆着调用链，我们发现程序入口在 kube-controller-manager/controller-manager.go:53，接着在 cmd/kube-controller-manager/app/controllermanager.go:121 这个 Run 函数中启动了多个 controller，其中就包括 podautoscaler pkg 的 HorizontalController（cmd/kube-controller-manager/app/controllermanager.go:337）。当它被调用 .Run(wait.NeverStop) 的时候，就会创建一个 loop 每隔一段时间从 apiserver 获取 autoscaler 列表，再对每个 autoscaler 做处理。这个处理的过程(pkg/controller/podautoscaler/horizontal.go:258)包括获取相关监控数据、计算需要的 pod 数量和调用 apiserver 的 API 来更新 autoscaler 的 desired pod 数量。

获取监控数据的逻辑入口在这里 pkg/controller/podautoscaler/metrics/metrics_client.go:104。其中两个关键函数 GetCpuConsumptionAndRequestInMillis 和 getCpuUtilizationForPods 函数简化后是

func (h *HeapsterMetricsClient) GetCpuConsumptionAndRequestInMillis(...) (...) {
    podList, err := h.client.Core().Pods(namespace).
        List(api.ListOptions{LabelSelector: selector})

    // ... pods 必须是 running 并且有设置 requested CPU
    requestAvg := requestSum / int64(len(podNames))
    consumption, timestamp, err := h.getCpuUtilizationForPods(namespace, selector, podNames)
    return consumption, requestAvg, len(podNames), timestamp, nil
}

func (h *HeapsterMetricsClient) getCpuUtilizationForPods(namespace, selector, podNames) (int64, time.Time, error) {
    metricPath := fmt.Sprintf("/apis/metrics/v1alpha1/namespaces/%s/pods", namespace)
    params := map[string]string{"labelSelector": selector.String()}

    resultRaw, err := h.client.Core().Services(h.heapsterNamespace).
        ProxyGet(h.heapsterScheme, h.heapsterService, h.heapsterPort, metricPath, params).
        DoRaw()

    metrics := metrics_api.PodMetricsList{}
    err = json.Unmarshal(resultRaw, &metrics)

    if len(metrics.Items) != len(podNames) {
        missing := // 找出没有 metrics 的 pod
        hint := ""
        if len(missing) > 0 {
            hint = fmt.Sprintf(" (sample missing pod: %s/%s)", namespace, missing[0])
        }
        return 0, time.Time{}, fmt.Errorf("metrics obtained for %d/%d of pods%s", len(metrics.Items), len(podNames), hint)
    }
}

先通过 apiserver 得到 pod list，经过简单的判断和过滤，再调用 heapster 的 API 得到 metrics，只有返回的 metrics 和 pod 一致才会继续进行。从错误日志可以判断，问题就出在 heapster 返回的 metrics 少了。

heapster API 返回 pod metrics #

heapster 是一个单独的项目，在 k8s 中，heapster 通常以 pod 的形式被部署在 k8s 集群中，它从 k8s 的每个节点那里收集数据，经过处理之后再写到一些存储里。它也提供 API 来得到数据，比如刚刚看到的 /apis/metrics/v1alpha1/namespaces/:namespace/pods。

由 build 的脚本或者直接搜索代码，很容易知道 heapster 是在 metrics/heapster.go:63 启动的，这里先初始化了 source（用来得到监控数据，比如 k8s）和 sink（用来保存数据，比如 influxdb），启动了用来收集和处理数据的 manager，最后启动了 HTTP server。先从上边的 API 调用入口看起 metrics/apis/metrics/handlers.go:188，这里获取了 pods 列表，然后从 MetricsSink 中取到相应的 metrics。MetricsSink 就是其中一种 sink，它比较简单，只是把长期（15m）和短期（140s）的数据放在 struct 里，metrics 的实际获取是异步进行的，这里先按下不表，先来看是哪里出的问题。从 log 中我们看到了如下的错误：

No metrics for pod backend/neo-staging-web-v201-dqxj5

但这块代码错误处理写得并不是很好，没有把更进一步的原因打到 log 里，所以我们很难知道是因为 MetricsSink 里没有数据，还是数据不正确。这里我们为了更快地定位问题，自己改了一下代码，在这个函数 metrics/apis/metrics/handlers.go:260 GetLatestDataBatch() 判空以及 parseResourceList error 判断的地方加了 log，把自己修改后的代码重新 build image 并运行。结论是因为 metrics 里没有 “cpu/usage_rate”(CPU usage on all cores in millicores)。因为是数据的问题，所以只看这段代码是不够的，我们需要知道 MetricsSink 的数据是如何被写入的。

heapster 从 Kubernetes 获取 metrics #

heapster 的 main 函数里先创建了 sourceManager、dataProcessors 和 sinkManager，再用它们创建了一个总的 manager（metrics/manager/manager.go:64），并运行它。这个运行的过程，其实就是创建了一个 goroutine，异步地不断进行数据从抓取到保存的整个过程。

简化后的代码如下：

// metrics/manager/manager.go:110
func (rm *realManager) housekeep(start, end time.Time) {
    select {
    go func(rm *realManager) {
        data := rm.source.ScrapeMetrics(start, end)

        for _, p := range rm.processors {
            newData, err := process(p, data)
            data = newData
        }
        rm.sink.ExportData(data)
    }(rm)
}

// metrics/sources/manager.go:78
func (this *sourceManager) ScrapeMetrics(start, end time.Time) *DataBatch {
    sources := this.metricsSourceProvider.GetMetricsSources()

    response := DataBatch{
        MetricSets: map[string]*MetricSet{},
    }
    for _, source := range sources {
        metrics := s.ScrapeMetrics(start, end)
        for key, value := range metrics.MetricSets {
            response.MetricSets[key] = value
        }
    }
    return &response
}

// metrics/processors/rate_calculator.go:32
func (this *RateCalculator) Process(batch *core.DataBatch) (*core.DataBatch, error) {
    if this.previousBatch == nil {
        this.previousBatch = batch
        return batch, nil
    }

    for key, newMs := range batch.MetricSets {
        if oldMs, found := this.previousBatch.MetricSets[key]; found {
            if !newMs.CreateTime.Equal(oldMs.CreateTime) {
                glog.V(4).Infof("Skipping rates for %s - different create time new:%v  old:%v", key, newMs.CreateTime, oldMs.CreateTime)
                // Create time for container must be the same.
                continue
            }

            for metricName, targetMetric := range this.rateMetricsMapping {
                // 通过新旧 metrics 来计算 rate，并修改 newMs
            }
        }
    }
    this.previousBatch = batch
    return batch, nil
}

这里会先得到所有的 sources，也就是每个 k8s cluster node 的 kubelet，然后调用 kubelet 的 “/stats/container/” 接口来得到 []cadvisor.ContainerInfo，它包含所有 container 的信息以及对应的 metrics。再用得到的数据来计算一些 rate metrics，比如前边提到过的 CpuUsageRate，也就是一段时间内的 CPU usage。但在计算之前做了一些判断，比如会比较前后两个 DataBatch 的 container 的创建时间。通过把 log 级别调到 4，我们发现这里会输出很多这样错误日志：

rate_calculator.go:51] Skipping rates for namespace:backend/pod:neo-staging-web-v201-ee4c3 - different create time new:2017-05-04 14:26:19.639205791 +0000 UTC  old:2017-05-04 14:25:19.591801877 +0000 UTC

所以基本可以确定，前边发现没有 CpuUsageRate 的原因是在这里跳过了计算。那为什么要比较 container 的创建时间呢？通过 git blame，我们在这个 issue https://github.com/kubernetes/heapster/issues/988 找到了答案，原来是为了处理 container 重启的情况。而实际上，container 并没有重启，但为什么 container 的创建时间会一直不一致呢？是从 kubelet 中获取的数据本身就有问题还是经过 heapster 的处理后造成的问题？

我们可以直接在 node 上边调用 kubelet 的 API 来看结果有什么问题，其中不太重要的信息被我略去了

$ curl -X "POST" -d '{"containerName":"/","subcontainers":true,"num_stats":1}' http://localhost:10255/stats/container
{
  "/system.slice/docker.service/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f": {
    "id": "cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "name": "/system.slice/docker.service/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "spec": {
      "creation_time": "2017-05-04T15:30:22.688799748Z",
      "labels": {
        "io.kubernetes.container.name": "neo-web",
        "io.kubernetes.pod.name": "neo-staging-web-v201-dqxj5",
        "io.kubernetes.pod.namespace": "backend"
      }
    }
  },
  "/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f": {
    "id": "cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "name": "/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "spec": {
      "creation_time": "2017-05-04T15:30:43.173457599Z",
      "labels": {
        "io.kubernetes.container.name": "neo-web",
        "io.kubernetes.pod.name": "neo-staging-web-v201-dqxj5",
        "io.kubernetes.pod.namespace": "backend"
      }
    }
  }
}

MetricSet 的 key 是这三个 labels 拼起来的，container 的创建时间是 spec.creation_time。可以发现，我们有两份 container、pod 完全一样但 id 和创建时间却又细微差别的数据。所以我们基本可以确定 kubelet 返回的数据有问题。