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 的工作原理:
Horizontal_Pod_Autoscaling___Kubernetes.jpg

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 返回的数据有问题。

 
12
Kudos
 
12
Kudos

Now read this

125 days contributing on GitHub

如果本文有个中文标题,大概会是这样:在 GitHub 上连续 125 天有 contribution 记录是怎样一种体验? 先来简单说说这 125 天里一些自己认为值得一提的事,可能这样大家才可能比较感兴趣地往下看。 在 elixir-lang/ecto(类似于 ActiveRecord) 有 22 次提交,排名第8。 完成了 Qiniu SDK for Elixir 的主要开发工作。 其他零碎的,比如 elixir-lang/elixir、... Continue →